From dd3acc83198468ee03be4507c556556657a8d8bd Mon Sep 17 00:00:00 2001 From: Clint Wylie Date: Sat, 15 Dec 2018 19:26:02 -0800 Subject: [PATCH 1/3] make logs that are only useful for debugging be at debug level so log volume is much more chill --- .../druid/indexing/common/actions/SegmentInsertAction.java | 3 ++- .../common/actions/SegmentMetadataUpdateAction.java | 2 +- .../druid/indexing/common/actions/SegmentNukeAction.java | 2 +- .../common/actions/SegmentTransactionalInsertAction.java | 2 +- .../src/main/java/org/apache/druid/segment/IndexMerger.java | 4 ++-- .../druid/server/coordinator/CuratorLoadQueuePeon.java | 6 +++--- .../apache/druid/server/coordinator/DruidCoordinator.java | 2 +- .../apache/druid/server/coordinator/HttpLoadQueuePeon.java | 4 ++-- .../server/coordinator/helper/DruidCoordinatorBalancer.java | 6 +++--- .../apache/druid/server/router/CoordinatorRuleManager.java | 2 +- 10 files changed, 17 insertions(+), 16 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 c78aefe58df3..42f74e59737a 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.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 boolean isAudited() 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 fd6f88aab8f9..4bb70a533d88 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 boolean isAudited() 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 ac5c286c7fc8..db632a78507a 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 boolean isAudited() 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 ffc799befd94..3d733f90eff2 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 boolean isAudited() public String toString() { return "SegmentInsertAction{" + - "segments=" + segments + + "segments=" + segments.stream().map(DataSegment::getIdentifier).collect(Collectors.joining(",")) + ", startMetadata=" + startMetadata + ", endMetadata=" + endMetadata + '}'; diff --git a/processing/src/main/java/org/apache/druid/segment/IndexMerger.java b/processing/src/main/java/org/apache/druid/segment/IndexMerger.java index 4661b652eeda..4f4f26f7565f 100644 --- a/processing/src/main/java/org/apache/druid/segment/IndexMerger.java +++ b/processing/src/main/java/org/apache/druid/segment/IndexMerger.java @@ -404,7 +404,7 @@ class DictionaryMergeIterator implements CloseableIterator Indexed indexed = dimValueLookups[i]; if (useDirect) { int allocationSize = indexed.size() * Integer.BYTES; - log.info("Allocating dictionary merging direct buffer with size[%,d]", allocationSize); + log.debug("Allocating dictionary merging direct buffer with size[%,d]", allocationSize); final ByteBuffer conversionDirectBuffer = ByteBuffer.allocateDirect(allocationSize); conversions[i] = conversionDirectBuffer.asIntBuffer(); directBufferAllocations.add(new Pair<>(conversionDirectBuffer, allocationSize)); @@ -483,7 +483,7 @@ public void remove() public void close() { 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); ByteBufferUtils.free(bufferAllocation.lhs); } } 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 c790382c2ee6..e0972260ac93 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 @@ private void processSegmentChangeRequest() 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 @@ private void entryRemoved(String path) ); 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 852068342c00..be4f106ca1af 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 CoordinatorCompactionConfig getCompactionConfig() 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 ef86d1efc24b..a0641a210824 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 void onSuccess(InputStream result) 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 boolean hasTimedOut() 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 97589c9bec0d..129b45350856 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 @@ private void balanceTier( 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 @@ protected void moveSegment( 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/router/CoordinatorRuleManager.java b/server/src/main/java/org/apache/druid/server/router/CoordinatorRuleManager.java index afc1a6416d22..27661bc78dfb 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 @@ -154,7 +154,7 @@ public void poll() ) ); - log.info("Got [%,d] rules", newRules.size()); + log.debug("Got [%,d] rules", newRules.size()); rules.set(newRules); } From 65e710275735ccd6df8a877ff2fa46dafa7c0ed7 Mon Sep 17 00:00:00 2001 From: Clint Wylie Date: Sat, 15 Dec 2018 19:31:19 -0800 Subject: [PATCH 2/3] info level messages for total merge buffer allocated/free --- .../main/java/org/apache/druid/segment/IndexMerger.java | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/processing/src/main/java/org/apache/druid/segment/IndexMerger.java b/processing/src/main/java/org/apache/druid/segment/IndexMerger.java index 4f4f26f7565f..87466d255e3e 100644 --- a/processing/src/main/java/org/apache/druid/segment/IndexMerger.java +++ b/processing/src/main/java/org/apache/druid/segment/IndexMerger.java @@ -397,6 +397,8 @@ class DictionaryMergeIterator implements CloseableIterator { pQueue = new PriorityQueue<>(dimValueLookups.length, NULLS_FIRST_PEEKING_COMPARATOR); conversions = new IntBuffer[dimValueLookups.length]; + + long mergeBufferTotalSize = 0; for (int i = 0; i < conversions.length; i++) { if (dimValueLookups[i] == null) { continue; @@ -405,11 +407,13 @@ class DictionaryMergeIterator implements CloseableIterator if (useDirect) { int allocationSize = indexed.size() * Integer.BYTES; log.debug("Allocating dictionary merging direct buffer with size[%,d]", allocationSize); + mergeBufferTotalSize += allocationSize; final ByteBuffer conversionDirectBuffer = ByteBuffer.allocateDirect(allocationSize); conversions[i] = conversionDirectBuffer.asIntBuffer(); directBufferAllocations.add(new Pair<>(conversionDirectBuffer, allocationSize)); } else { conversions[i] = IntBuffer.allocate(indexed.size()); + mergeBufferTotalSize += indexed.size(); } final PeekingIterator iter = Iterators.peekingIterator( @@ -422,6 +426,7 @@ class DictionaryMergeIterator implements CloseableIterator pQueue.add(Pair.of(i, iter)); } } + log.info("Allocated [%,d] bytes of dictionary merging direct buffers", mergeBufferTotalSize); } @Override @@ -482,10 +487,13 @@ public void remove() @Override public void close() { + long mergeBufferTotalSize = 0; for (Pair bufferAllocation : directBufferAllocations) { 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); } } } From 3a31c7453f12838ecb7b734adb3cc2e7a24dd8bd Mon Sep 17 00:00:00 2001 From: Clint Wylie Date: Sat, 15 Dec 2018 19:37:54 -0800 Subject: [PATCH 3/3] more chill compaction logs --- .../helper/DruidCoordinatorSegmentCompactor.java | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) 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 b02969737f1a..4067b3a7a5d2 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 @@ private CoordinatorStats doRun( 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 {