Skip to content

Commit 50ba0aa

Browse files
Add debug-level logging for cloud fetch performance diagnostics (#1218)
## Summary - Adds structured `debug`-level logs across the cloud fetch pipeline (chunk download, link wait, decompression, task completion) with `statementId` correlation for end-to-end tracing - Enriches the `executeStatement` completion log with manifest details (format, totalBytes, totalChunks, totalRows, compression) replacing the previous sparse log - Breaks down `ArrowResultChunk.downloadData` timing into HTTP response, stream read, and decompress+parse phases NO_CHANGELOG=true ## Test plan - [ ] Verify logs appear when debug logging is enabled (e.g. `log4j.logger.com.databricks.jdbc=DEBUG`) - [ ] Verify no logs appear at default (INFO) level — no noise for customers - [ ] Run existing unit tests to confirm no regressions 🤖 Generated with [Claude Code](https://claude.com/claude-code) Signed-off-by: Vikrant Puppala <vikrant.puppala@databricks.com> Co-authored-by: Claude Opus 4.6 <noreply@anthropic.com>
1 parent 3710687 commit 50ba0aa

5 files changed

Lines changed: 70 additions & 10 deletions

File tree

src/main/java/com/databricks/jdbc/api/impl/arrow/AbstractRemoteChunkProvider.java

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -156,6 +156,7 @@ public T getChunk() throws DatabricksSQLException {
156156

157157
T chunk = chunkIndexToChunksMap.get(currentChunkIndex);
158158

159+
long waitStart = System.nanoTime();
159160
try {
160161
chunk.waitForChunkReady();
161162
} catch (InterruptedException e) {
@@ -174,6 +175,12 @@ public T getChunk() throws DatabricksSQLException {
174175
throw new DatabricksSQLException(
175176
"Failed to ready chunk", e.getCause(), DatabricksDriverErrorCode.CHUNK_READY_ERROR);
176177
}
178+
long waitMs = (System.nanoTime() - waitStart) / 1_000_000;
179+
LOGGER.debug(
180+
"Chunk ready: statementId={}, chunkIndex={}, waitMs={}",
181+
statementId,
182+
chunk.getChunkIndex(),
183+
waitMs);
177184

178185
return chunk;
179186
}

src/main/java/com/databricks/jdbc/api/impl/arrow/ArrowResultChunk.java

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -89,6 +89,7 @@ protected void downloadData(
8989

9090
// Read compressed stream fully (download latency excludes decompression)
9191
byte[] compressed = IOUtils.toByteArray(response.getEntity().getContent());
92+
long readTimeMs = (System.nanoTime() - startTime) / 1_000_000;
9293

9394
// Set status to DOWNLOAD_SUCCEEDED after reading the compressed stream fully
9495
setStatus(ChunkStatus.DOWNLOAD_SUCCEEDED);
@@ -101,6 +102,7 @@ protected void downloadData(
101102
speedThreshold);
102103

103104
// Decompress (if needed) and parse
105+
long decompressStart = System.nanoTime();
104106
try {
105107
String ctx =
106108
String.format(
@@ -111,6 +113,19 @@ protected void downloadData(
111113
} catch (Exception e) {
112114
handleFailure(e, ChunkStatus.PROCESSING_FAILED);
113115
}
116+
long decompressTimeMs = (System.nanoTime() - decompressStart) / 1_000_000;
117+
long totalTimeMs = (System.nanoTime() - startTime) / 1_000_000;
118+
LOGGER.debug(
119+
"Chunk download complete: statementId={}, chunkIndex={}, "
120+
+ "compressedBytes={}, httpResponseMs={}, streamReadMs={}, decompressAndParseMs={}, "
121+
+ "totalMs={}",
122+
statementId,
123+
chunkIndex,
124+
compressed.length,
125+
downloadTimeMs,
126+
readTimeMs - downloadTimeMs,
127+
decompressTimeMs,
128+
totalTimeMs);
114129
} catch (Exception e) {
115130
handleFailure(e, ChunkStatus.DOWNLOAD_FAILED);
116131
} finally {

src/main/java/com/databricks/jdbc/api/impl/arrow/ChunkDownloadTask.java

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,15 +48,23 @@ public Void call() throws DatabricksSQLException, ExecutionException, Interrupte
4848
DatabricksThreadContextHolder.setConnectionContext(this.connectionContext);
4949
DatabricksThreadContextHolder.setStatementId(this.statementId);
5050

51+
long taskStartTime = System.nanoTime();
5152
try {
5253
DatabricksThreadContextHolder.setRetryCount(retries);
5354
while (!downloadSuccessful) {
5455
try {
5556
if (chunk.isChunkLinkInvalid()) {
57+
long linkWaitStart = System.nanoTime();
5658
ExternalLink link =
5759
linkDownloadService
5860
.getLinkForChunk(chunk.getChunkIndex())
5961
.get(); // Block until link is available
62+
long linkWaitMs = (System.nanoTime() - linkWaitStart) / 1_000_000;
63+
LOGGER.debug(
64+
"Link wait: statementId={}, chunkIndex={}, linkWaitMs={}",
65+
statementId,
66+
chunk.getChunkIndex(),
67+
linkWaitMs);
6068
chunk.setChunkLink(link);
6169
}
6270

@@ -65,6 +73,13 @@ public Void call() throws DatabricksSQLException, ExecutionException, Interrupte
6573
chunkDownloader.getCompressionCodec(),
6674
connectionContext != null ? connectionContext.getCloudFetchSpeedThreshold() : 0.1);
6775
downloadSuccessful = true;
76+
long taskTotalMs = (System.nanoTime() - taskStartTime) / 1_000_000;
77+
LOGGER.debug(
78+
"ChunkDownloadTask complete: statementId={}, chunkIndex={}, totalTaskMs={}, retries={}",
79+
statementId,
80+
chunk.getChunkIndex(),
81+
taskTotalMs,
82+
retries);
6883
} catch (IOException | DatabricksSQLException e) {
6984
retries++;
7085
if (retries >= MAX_RETRIES) {

src/main/java/com/databricks/jdbc/api/impl/arrow/ChunkLinkDownloadService.java

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -242,15 +242,19 @@ private void triggerNextBatchDownload() {
242242
CompletableFuture.runAsync(
243243
() -> {
244244
try {
245+
long fetchStart = System.nanoTime();
245246
ChunkLinkFetchResult result =
246247
session
247248
.getDatabricksClient()
248249
.getResultChunks(statementId, batchStartIndex, batchStartRowOffset);
249-
LOGGER.info(
250-
"Retrieved {} links for batch starting at {} for statement id {}",
251-
result.getChunkLinks().size(),
250+
long fetchMs = (System.nanoTime() - fetchStart) / 1_000_000;
251+
LOGGER.debug(
252+
"Link batch fetch: statementId={}, batchStartIndex={}, "
253+
+ "linksRetrieved={}, fetchApiMs={}",
254+
statementId,
252255
batchStartIndex,
253-
statementId);
256+
result.getChunkLinks().size(),
257+
fetchMs);
254258

255259
// Complete futures for all chunks in this batch
256260
for (ExternalLink link : result.getChunkLinks()) {

src/main/java/com/databricks/jdbc/dbclient/impl/sqlexec/DatabricksSdkClient.java

Lines changed: 25 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@
3434
import com.databricks.jdbc.model.core.Disposition;
3535
import com.databricks.jdbc.model.core.ExternalLink;
3636
import com.databricks.jdbc.model.core.ResultData;
37+
import com.databricks.jdbc.model.core.ResultManifest;
3738
import com.databricks.jdbc.model.telemetry.enums.DatabricksDriverErrorCode;
3839
import com.databricks.sdk.WorkspaceClient;
3940
import com.databricks.sdk.core.ApiClient;
@@ -279,12 +280,30 @@ public DatabricksResultSet executeStatement(
279280
pollCount++;
280281
}
281282
long executionEndTime = Instant.now().toEpochMilli();
282-
LOGGER.debug(
283-
"Executed sql {} with status {}, total time taken {} and pollCount {}",
284-
sql,
285-
responseState,
286-
(executionEndTime - executionStartTime),
287-
pollCount);
283+
{
284+
ResultManifest manifest = response.getManifest();
285+
ResultData resultData = response.getResult();
286+
int numExternalLinks =
287+
(resultData != null && resultData.getExternalLinks() != null)
288+
? resultData.getExternalLinks().size()
289+
: 0;
290+
LOGGER.debug(
291+
"executeStatement complete: statementId={}, state={}, format={}, "
292+
+ "totalBytes={}, totalChunks={}, totalRows={}, "
293+
+ "hasInlineAttachment={}, numExternalLinks={}, compression={}, "
294+
+ "executionTimeMs={}, pollCount={}",
295+
statementId,
296+
responseState,
297+
manifest != null ? manifest.getFormat() : "null",
298+
manifest != null ? manifest.getTotalByteCount() : "null",
299+
manifest != null ? manifest.getTotalChunkCount() : "null",
300+
manifest != null ? manifest.getTotalRowCount() : "null",
301+
resultData != null && resultData.getAttachment() != null,
302+
numExternalLinks,
303+
manifest != null ? manifest.getResultCompression() : "null",
304+
(executionEndTime - executionStartTime),
305+
pollCount);
306+
}
288307
if (responseState != StatementState.SUCCEEDED && responseState != StatementState.CLOSED) {
289308
handleFailedExecution(response, statementId, sql);
290309
}

0 commit comments

Comments
 (0)