From 486c6f3cf9ca15ceb4da8be9351693fa128135c3 Mon Sep 17 00:00:00 2001 From: Clint Wylie Date: Sun, 16 Dec 2018 22:20:28 -0800 Subject: [PATCH] emit logs that are only useful for debugging at debug level (#6741) * make logs that are only useful for debugging be at debug level so log volume is much more chill * info level messages for total merge buffer allocated/free * more chill compaction logs --- .../indexing/common/actions/SegmentInsertAction.java | 3 ++- .../common/actions/SegmentMetadataUpdateAction.java | 2 +- .../indexing/common/actions/SegmentNukeAction.java | 2 +- .../actions/SegmentTransactionalInsertAction.java | 2 +- .../java/org/apache/druid/segment/IndexMerger.java | 12 ++++++++++-- .../server/coordinator/CuratorLoadQueuePeon.java | 6 +++--- .../druid/server/coordinator/DruidCoordinator.java | 2 +- .../druid/server/coordinator/HttpLoadQueuePeon.java | 4 ++-- .../coordinator/helper/DruidCoordinatorBalancer.java | 6 +++--- .../helper/DruidCoordinatorSegmentCompactor.java | 6 +++++- .../druid/server/router/CoordinatorRuleManager.java | 2 +- 11 files changed, 30 insertions(+), 17 deletions(-) diff --git a/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentInsertAction.java b/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentInsertAction.java index c78aefe58df..42f74e59737 100644 --- a/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentInsertAction.java +++ b/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentInsertAction.java @@ -27,6 +27,7 @@ import org.apache.druid.indexing.common.task.Task; import org.apache.druid.timeline.DataSegment; import java.util.Set; +import java.util.stream.Collectors; /** * Insert segments into metadata storage. The segment versions must all be less than or equal to a lock held by @@ -83,7 +84,7 @@ public class SegmentInsertAction implements TaskAction> public String toString() { return "SegmentInsertAction{" + - "segments=" + segments + + "segments=" + segments.stream().map(DataSegment::getIdentifier).collect(Collectors.joining(",")) + '}'; } } diff --git a/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentMetadataUpdateAction.java b/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentMetadataUpdateAction.java index fd6f88aab8f..4bb70a533d8 100644 --- a/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentMetadataUpdateAction.java +++ b/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentMetadataUpdateAction.java @@ -114,7 +114,7 @@ public class SegmentMetadataUpdateAction implements TaskAction public String toString() { return "SegmentMetadataUpdateAction{" + - "segments=" + segments + + "segments=" + segments.stream().map(DataSegment::getIdentifier).collect(Collectors.joining(",")) + '}'; } } diff --git a/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentNukeAction.java b/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentNukeAction.java index ac5c286c7fc..db632a78507 100644 --- a/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentNukeAction.java +++ b/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentNukeAction.java @@ -116,7 +116,7 @@ public class SegmentNukeAction implements TaskAction public String toString() { return "SegmentNukeAction{" + - "segments=" + segments + + "segments=" + segments.stream().map(DataSegment::getIdentifier).collect(Collectors.joining(",")) + '}'; } } diff --git a/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentTransactionalInsertAction.java b/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentTransactionalInsertAction.java index ffc799befd9..3d733f90eff 100644 --- a/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentTransactionalInsertAction.java +++ b/indexing-service/src/main/java/org/apache/druid/indexing/common/actions/SegmentTransactionalInsertAction.java @@ -154,7 +154,7 @@ public class SegmentTransactionalInsertAction implements TaskAction(conversionDirectBuffer, allocationSize)); } else { conversions[i] = IntBuffer.allocate(indexed.size()); + mergeBufferTotalSize += indexed.size(); } final PeekingIterator iter = Iterators.peekingIterator( @@ -422,6 +426,7 @@ public interface IndexMerger pQueue.add(Pair.of(i, iter)); } } + log.info("Allocated [%,d] bytes of dictionary merging direct buffers", mergeBufferTotalSize); } @Override @@ -482,10 +487,13 @@ public interface IndexMerger @Override public void close() { + long mergeBufferTotalSize = 0; for (Pair bufferAllocation : directBufferAllocations) { - log.info("Freeing dictionary merging direct buffer with size[%,d]", bufferAllocation.rhs); + log.debug("Freeing dictionary merging direct buffer with size[%,d]", bufferAllocation.rhs); + mergeBufferTotalSize += bufferAllocation.rhs; ByteBufferUtils.free(bufferAllocation.lhs); } + log.info("Freed [,%d] bytes of dictionary merging direct buffers", mergeBufferTotalSize); } } } diff --git a/server/src/main/java/org/apache/druid/server/coordinator/CuratorLoadQueuePeon.java b/server/src/main/java/org/apache/druid/server/coordinator/CuratorLoadQueuePeon.java index c790382c2ee..e0972260ac9 100644 --- a/server/src/main/java/org/apache/druid/server/coordinator/CuratorLoadQueuePeon.java +++ b/server/src/main/java/org/apache/druid/server/coordinator/CuratorLoadQueuePeon.java @@ -235,10 +235,10 @@ public class CuratorLoadQueuePeon extends LoadQueuePeon if (!segmentsToDrop.isEmpty()) { currentlyProcessing = segmentsToDrop.firstEntry().getValue(); - log.info("Server[%s] dropping [%s]", basePath, currentlyProcessing.getSegmentIdentifier()); + log.debug("Server[%s] dropping [%s]", basePath, currentlyProcessing.getSegmentIdentifier()); } else if (!segmentsToLoad.isEmpty()) { currentlyProcessing = segmentsToLoad.firstEntry().getValue(); - log.info("Server[%s] loading [%s]", basePath, currentlyProcessing.getSegmentIdentifier()); + log.debug("Server[%s] loading [%s]", basePath, currentlyProcessing.getSegmentIdentifier()); } else { return; } @@ -386,7 +386,7 @@ public class CuratorLoadQueuePeon extends LoadQueuePeon ); return; } - log.info( + log.debug( "Server[%s] done processing %s of segment [%s]", basePath, currentlyProcessing.getType() == LOAD ? "load" : "drop", 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 index 852068342c0..be4f106ca1a 100644 --- a/server/src/main/java/org/apache/druid/server/coordinator/DruidCoordinator.java +++ b/server/src/main/java/org/apache/druid/server/coordinator/DruidCoordinator.java @@ -334,7 +334,7 @@ public class DruidCoordinator public void removeSegment(DataSegment segment) { - log.info("Removing Segment[%s]", segment); + log.info("Removing Segment[%s]", segment.getIdentifier()); metadataSegmentManager.removeSegment(segment.getDataSource(), segment.getIdentifier()); } diff --git a/server/src/main/java/org/apache/druid/server/coordinator/HttpLoadQueuePeon.java b/server/src/main/java/org/apache/druid/server/coordinator/HttpLoadQueuePeon.java index ef86d1efc24..a0641a21082 100644 --- a/server/src/main/java/org/apache/druid/server/coordinator/HttpLoadQueuePeon.java +++ b/server/src/main/java/org/apache/druid/server/coordinator/HttpLoadQueuePeon.java @@ -223,7 +223,7 @@ public class HttpLoadQueuePeon extends LoadQueuePeon handleResponseStatus(e.getRequest(), e.getStatus()); break; case PENDING: - log.info("Request[%s] is still pending on server[%s].", e.getRequest(), serverId); + log.debug("Request[%s] is still pending on server[%s].", e.getRequest(), serverId); break; default: scheduleNextRunImmediately = false; @@ -521,7 +521,7 @@ public class HttpLoadQueuePeon extends LoadQueuePeon public void requestSucceeded() { - log.info( + log.debug( "Server[%s] Successfully processed segment[%s] request[%s].", serverId, segment.getIdentifier(), diff --git a/server/src/main/java/org/apache/druid/server/coordinator/helper/DruidCoordinatorBalancer.java b/server/src/main/java/org/apache/druid/server/coordinator/helper/DruidCoordinatorBalancer.java index 97589c9bec0..129b4535085 100644 --- a/server/src/main/java/org/apache/druid/server/coordinator/helper/DruidCoordinatorBalancer.java +++ b/server/src/main/java/org/apache/druid/server/coordinator/helper/DruidCoordinatorBalancer.java @@ -155,11 +155,11 @@ public class DruidCoordinatorBalancer implements DruidCoordinatorHelper moveSegment(segmentToMoveHolder, destinationHolder.getServer(), params); moved++; } else { - log.info("Segment [%s] is 'optimally' placed.", segmentToMove.getIdentifier()); + log.debug("Segment [%s] is 'optimally' placed.", segmentToMove.getIdentifier()); unmoved++; } } else { - log.info( + log.debug( "No valid movement destinations for segment [%s].", segmentToMove.getIdentifier() ); @@ -207,7 +207,7 @@ public class DruidCoordinatorBalancer implements DruidCoordinatorHelper if (!toPeon.getSegmentsToLoad().contains(segmentToMove) && (toServer.getSegment(segmentName) == null) && new ServerHolder(toServer, toPeon).getAvailableSize() > segmentToMove.getSize()) { - log.info("Moving [%s] from [%s] to [%s]", segmentName, fromServer.getName(), toServer.getName()); + log.debug("Moving [%s] from [%s] to [%s]", segmentName, fromServer.getName(), toServer.getName()); LoadPeonCallback callback = null; try { diff --git a/server/src/main/java/org/apache/druid/server/coordinator/helper/DruidCoordinatorSegmentCompactor.java b/server/src/main/java/org/apache/druid/server/coordinator/helper/DruidCoordinatorSegmentCompactor.java index b02969737f1..4067b3a7a5d 100644 --- a/server/src/main/java/org/apache/druid/server/coordinator/helper/DruidCoordinatorSegmentCompactor.java +++ b/server/src/main/java/org/apache/druid/server/coordinator/helper/DruidCoordinatorSegmentCompactor.java @@ -160,7 +160,11 @@ public class DruidCoordinatorSegmentCompactor implements DruidCoordinatorHelper config.getTuningConfig(), config.getTaskContext() ); - LOG.info("Submitted a compactTask[%s] for segments[%s]", taskId, segmentsToCompact); + LOG.info( + "Submitted a compactTask[%s] for segments[%s]", + taskId, + segmentsToCompact.stream().map(DataSegment::getIdentifier).collect(Collectors.joining(",")) + ); } else if (segmentsToCompact.size() == 1) { throw new ISE("Found one segments[%s] to compact", segmentsToCompact); } else { diff --git a/server/src/main/java/org/apache/druid/server/router/CoordinatorRuleManager.java b/server/src/main/java/org/apache/druid/server/router/CoordinatorRuleManager.java index 1e9ea81639c..c8c3b56a104 100644 --- a/server/src/main/java/org/apache/druid/server/router/CoordinatorRuleManager.java +++ b/server/src/main/java/org/apache/druid/server/router/CoordinatorRuleManager.java @@ -156,7 +156,7 @@ public class CoordinatorRuleManager ) ); - log.info("Got [%,d] rules", newRules.size()); + log.debug("Got [%,d] rules", newRules.size()); rules.set(newRules); }