Add pre-check for heavy debug logs (apache#15706)

Co-authored-by: Kashif Faraz <[email protected]> Co-authored-by: Benedict Jin <[email protected]>
monetate · Feb 29, 2024 · e0bce0e · e0bce0e
1 parent 7c42e87
commit e0bce0e
Show file tree

Hide file tree

Showing 10 changed files with 41 additions and 43 deletions.
diff --git a/...ava/org/apache/druid/indexing/common/task/batch/parallel/ParallelIndexSupervisorTask.java b/...ava/org/apache/druid/indexing/common/task/batch/parallel/ParallelIndexSupervisorTask.java
@@ -752,7 +752,7 @@ TaskStatus runHashPartitionMultiPhaseParallel(TaskToolbox toolbox) throws Except
         );
 
         // This is for potential debugging in case we suspect bad estimation of cardinalities etc,
-        LOG.debug("intervalToNumShards: %s", intervalToNumShards.toString());
+        LOG.debug("intervalToNumShards: %s", intervalToNumShards);
 
       } else {
         intervalToNumShards = CollectionUtils.mapValues(

diff --git a/...in/java/org/apache/druid/indexing/seekablestream/supervisor/SeekableStreamSupervisor.java b/...in/java/org/apache/druid/indexing/seekablestream/supervisor/SeekableStreamSupervisor.java
@@ -1155,14 +1155,13 @@ public void tryInit()
                     Instant handleNoticeEndTime = Instant.now();
                     Duration timeElapsed = Duration.between(handleNoticeStartTime, handleNoticeEndTime);
                     String noticeType = notice.getType();
-                    log.debug(
-                        "Handled notice [%s] from notices queue in [%d] ms, "
-                        + "current notices queue size [%d] for datasource [%s]",
-                        noticeType,
-                        timeElapsed.toMillis(),
-                        getNoticesQueueSize(),
-                        dataSource
-                    );
+                    if (log.isDebugEnabled()) {
+                      log.debug(
+                          "Handled notice [%s] from notices queue in [%d] ms, "
+                              + "current notices queue size [%d] for datasource [%s]",
+                          noticeType, timeElapsed.toMillis(), getNoticesQueueSize(), dataSource
+                      );
+                    }
                     emitNoticeProcessTime(noticeType, timeElapsed.toMillis());
                   }
                   catch (Throwable e) {

diff --git a/...va/org/apache/druid/indexing/seekablestream/supervisor/autoscaler/LagBasedAutoScaler.java b/...va/org/apache/druid/indexing/seekablestream/supervisor/autoscaler/LagBasedAutoScaler.java
@@ -149,7 +149,7 @@ private Runnable computeAndCollectLag()
             long totalLags = lagStats.getTotalLag();
             lagMetricsQueue.offer(totalLags > 0 ? totalLags : 0L);
           }
-          log.debug("Current lags [%s] for dataSource [%s].", new ArrayList<>(lagMetricsQueue), dataSource);
+          log.debug("Current lags for dataSource[%s] are [%s].", dataSource, lagMetricsQueue);
         } else {
           log.warn("[%s] supervisor is suspended, skipping lag collection", dataSource);
         }

diff --git a/...tion-tests/src/main/java/org/apache/druid/testing/clients/OverlordResourceTestClient.java b/...tion-tests/src/main/java/org/apache/druid/testing/clients/OverlordResourceTestClient.java
@@ -185,7 +185,9 @@ private List<TaskResponseObject> getTasks(String identifier)
           HttpMethod.GET,
           StringUtils.format("%s%s", getIndexerURL(), identifier)
       );
-      LOG.debug("Tasks %s response %s", identifier, response.getContent());
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("Tasks %s response %s", identifier, response.getContent());
+      }
       return jsonMapper.readValue(
           response.getContent(), new TypeReference<List<TaskResponseObject>>()
           {
@@ -204,7 +206,9 @@ public TaskPayloadResponse getTaskPayload(String taskId)
           HttpMethod.GET,
           StringUtils.format("%stask/%s", getIndexerURL(), StringUtils.urlEncode(taskId))
       );
-      LOG.debug("Task %s response %s", taskId, response.getContent());
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("Task %s response %s", taskId, response.getContent());
+      }
       return jsonMapper.readValue(
           response.getContent(), new TypeReference<TaskPayloadResponse>()
           {

diff --git a/processing/src/main/java/org/apache/druid/frame/processor/FrameProcessorExecutor.java b/processing/src/main/java/org/apache/druid/frame/processor/FrameProcessorExecutor.java
@@ -595,7 +595,6 @@ private static <T> void logProcessorStatusString(
 
       sb.append("; cancel=").append(finishedFuture.isCancelled() ? "y" : "n");
       sb.append("; done=").append(finishedFuture.isDone() ? "y" : "n");
-
       log.debug(StringUtils.encodeForFormat(sb.toString()));
     }
   }

diff --git a/...src/main/java/org/apache/druid/java/util/common/guava/ParallelMergeCombiningSequence.java b/...src/main/java/org/apache/druid/java/util/common/guava/ParallelMergeCombiningSequence.java
@@ -475,20 +475,17 @@ private int computeNumTasks()
 
       final int computedNumParallelTasks = Math.max(computedOptimalParallelism, 1);
 
-      LOG.debug(
-          "Computed parallel tasks: [%s]; ForkJoinPool details - sequence parallelism: [%s] "
-          + "active threads: [%s] running threads: [%s] queued submissions: [%s] queued tasks: [%s] "
-          + "pool parallelism: [%s] pool size: [%s] steal count: [%s]",
-          computedNumParallelTasks,
-          parallelism,
-          getPool().getActiveThreadCount(),
-          runningThreadCount,
-          submissionCount,
-          getPool().getQueuedTaskCount(),
-          getPool().getParallelism(),
-          getPool().getPoolSize(),
-          getPool().getStealCount()
-      );
+      if (LOG.isDebugEnabled()) {
+        ForkJoinPool pool = getPool();
+        LOG.debug(
+            "Computed parallel tasks: [%s]; ForkJoinPool details - sequence parallelism: [%s] "
+                + "active threads: [%s] running threads: [%s] queued submissions: [%s] queued tasks: [%s] "
+                + "pool parallelism: [%s] pool size: [%s] steal count: [%s]",
+            computedNumParallelTasks, parallelism,
+            pool.getActiveThreadCount(), runningThreadCount, submissionCount, pool.getQueuedTaskCount(),
+            pool.getParallelism(), pool.getPoolSize(), pool.getStealCount()
+        );
+      }
 
       return computedNumParallelTasks;
     }

diff --git a/processing/src/main/java/org/apache/druid/java/util/common/io/smoosh/FileSmoosher.java b/processing/src/main/java/org/apache/druid/java/util/common/io/smoosh/FileSmoosher.java
@@ -490,11 +490,9 @@ public boolean isOpen()
     public void close() throws IOException
     {
       closer.close();
-      FileSmoosher.LOG.debug(
-          "Created smoosh file [%s] of size [%s] bytes.",
-          outFile.getAbsolutePath(),
-          outFile.length()
-      );
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("Created smoosh file [%s] of size [%s] bytes.", outFile.getAbsolutePath(), outFile.length());
+      }
     }
   }
 }
diff --git a/server/src/main/java/org/apache/druid/discovery/DataServerClient.java b/server/src/main/java/org/apache/druid/discovery/DataServerClient.java
@@ -91,7 +91,9 @@ public <T> Sequence<T> run(Query<T> query, ResponseContext responseContext, Java
       requestBuilder = requestBuilder.jsonContent(objectMapper, query);
     }
 
-    log.debug("Sending request to servers for query[%s], request[%s]", query.getId(), requestBuilder.toString());
+    if (log.isDebugEnabled()) {
+      log.debug("Sending request to servers for query[%s], request[%s]", query.getId(), requestBuilder);
+    }
     ListenableFuture<InputStream> resultStreamFuture = serviceClient.asyncRequest(
         requestBuilder,
         new DataServerResponseHandler(query, responseContext, objectMapper)

diff --git a/server/src/main/java/org/apache/druid/server/coordinator/DruidCoordinator.java b/server/src/main/java/org/apache/druid/server/coordinator/DruidCoordinator.java
@@ -538,10 +538,9 @@ List<CoordinatorDuty> makeIndexingServiceDuties()
     if (getCompactSegmentsDutyFromCustomGroups().isEmpty()) {
       duties.add(compactSegments);
     }
-    log.debug(
-        "Initialized indexing service duties [%s].",
-        duties.stream().map(duty -> duty.getClass().getName()).collect(Collectors.toList())
-    );
+    if (log.isDebugEnabled()) {
+      log.debug("Initialized indexing service duties [%s].", duties.stream().map(duty -> duty.getClass().getName()).collect(Collectors.toList()));
+    }
     return ImmutableList.copyOf(duties);
   }
 

diff --git a/server/src/main/java/org/apache/druid/server/coordinator/loading/CuratorLoadQueuePeon.java b/server/src/main/java/org/apache/druid/server/coordinator/loading/CuratorLoadQueuePeon.java
@@ -230,12 +230,12 @@ public void run()
         final String path = ZKPaths.makePath(basePath, segmentHolder.getSegmentIdentifier());
         final byte[] payload = jsonMapper.writeValueAsBytes(segmentHolder.getChangeRequest());
         curator.create().withMode(CreateMode.EPHEMERAL).forPath(path, payload);
-        log.debug(
-            "ZKNode created for server to [%s] %s [%s]",
-            basePath,
-            segmentHolder.getAction(),
-            segmentHolder.getSegmentIdentifier()
-        );
+        if (log.isDebugEnabled()) {
+          log.debug(
+              "ZKNode created for server to [%s] %s [%s]",
+              basePath, segmentHolder.getAction(), segmentHolder.getSegmentIdentifier()
+          );
+        }
         final ScheduledFuture<?> nodeDeletedCheck = scheduleNodeDeletedCheck(path);
         final Stat stat = curator.checkExists().usingWatcher(
             (CuratorWatcher) watchedEvent -> {
-Original file line number
+Diff line change
@@ Expand Up / @@ -595,7 +595,6 @@ private static <T> void logProcessorStatusString( @@
           sb.append("; cancel=").append(finishedFuture.isCancelled() ? "y" : "n");
           sb.append("; done=").append(finishedFuture.isDone() ? "y" : "n");
           log.debug(StringUtils.encodeForFormat(sb.toString()));
         }
       }
@@ Expand Down @@