[Profiling] Improve debug logging

danielmitterdorfer · Sep 29, 2023 · 1b8e2c1 · 1b8e2c1
1 parent 05189ef
commit 1b8e2c1
Show file tree

Hide file tree

Showing 2 changed files with 28 additions and 0 deletions.
diff --git a/x-pack/plugin/profiling/src/main/java/org/elasticsearch/xpack/profiling/EventsIndex.java b/x-pack/plugin/profiling/src/main/java/org/elasticsearch/xpack/profiling/EventsIndex.java
@@ -57,6 +57,11 @@ public EventsIndex getResampledIndex(long targetSampleSize, long currentSampleSi
         return EventsIndex.getSampledIndex(targetSampleSize, currentSampleSize, this.getExponent());
     }
 
+    @Override
+    public String toString() {
+        return name;
+    }
+
     // Return the index that has between targetSampleSize..targetSampleSize*samplingFactor entries.
     // The starting point is the number of entries from the profiling-events-5pow<initialExp> index.
     private static EventsIndex getSampledIndex(long targetSampleSize, long sampleCountFromInitialExp, int initialExp) {

diff --git a/...filing/src/main/java/org/elasticsearch/xpack/profiling/TransportGetStackTracesAction.java b/...filing/src/main/java/org/elasticsearch/xpack/profiling/TransportGetStackTracesAction.java
@@ -129,6 +129,13 @@ protected void doExecute(Task submitTask, GetStackTracesRequest request, ActionL
             .execute(ActionListener.wrap(searchResponse -> {
                 long sampleCount = searchResponse.getHits().getTotalHits().value;
                 EventsIndex resampledIndex = mediumDownsampled.getResampledIndex(request.getSampleSize(), sampleCount);
+                log.debug(
+                    "User requested [{}] samples, [{}] samples matched in [{}]. Picking [{}]",
+                    request.getSampleSize(),
+                    sampleCount,
+                    mediumDownsampled,
+                    resampledIndex
+                );
                 log.debug("getResampledIndex took [" + (System.nanoTime() - start) / 1_000_000.0d + " ms].");
                 searchEventGroupByStackTrace(client, request, resampledIndex, submitListener);
             }, e -> {
@@ -184,14 +191,23 @@ private void searchEventGroupByStackTrace(
                 // sort items lexicographically to access Lucene's term dictionary more efficiently when issuing an mget request.
                 // The term dictionary is lexicographically sorted and using the same order reduces the number of page faults
                 // needed to load it.
+                long totalFinalCount = 0;
                 Map<String, Integer> stackTraceEvents = new TreeMap<>();
                 for (StringTerms.Bucket bucket : stacktraces.getBuckets()) {
                     Sum count = bucket.getAggregations().get("count");
                     int finalCount = resampler.adjustSampleCount((int) count.value());
+                    totalFinalCount += finalCount;
                     if (finalCount > 0) {
                         stackTraceEvents.put(bucket.getKeyAsString(), finalCount);
                     }
                 }
+                log.debug(
+                    "Found [{}] stacktrace events, resampled with sample rate [{}] to [{}] events ([{}] unique stack traces).",
+                    totalCount,
+                    eventsIndex.getSampleRate(),
+                    totalFinalCount,
+                    stackTraceEvents.size()
+                );
                 log.debug("searchEventGroupByStackTrace took [" + (System.nanoTime() - start) / 1_000_000.0d + " ms].");
                 if (stackTraceEvents.isEmpty() == false) {
                     responseBuilder.setStart(Instant.ofEpochMilli(minTime));
@@ -304,6 +320,12 @@ public void onResponse(MultiGetResponse multiGetItemResponses) {
             if (this.remainingSlices.decrementAndGet() == 0) {
                 responseBuilder.setStackTraces(stackTracePerId);
                 responseBuilder.setTotalFrames(totalFrames.get());
+                log.debug(
+                    "retrieveStackTraces found [{}] stack traces, [{}] frames, [{}] executables.",
+                    stackTracePerId.size(),
+                    stackFrameIds.size(),
+                    executableIds.size()
+                );
                 log.debug("retrieveStackTraces took [" + (System.nanoTime() - start) / 1_000_000.0d + " ms].");
                 retrieveStackTraceDetails(
                     clusterState,
@@ -448,6 +470,7 @@ public void mayFinish() {
             if (expectedSlices.decrementAndGet() == 0) {
                 builder.setExecutables(executables);
                 builder.setStackFrames(stackFrames);
+                log.debug("retrieveStackTraceDetails found [{}] stack frames, [{}] executables.", stackFrames.size(), executables.size());
                 log.debug("retrieveStackTraceDetails took [" + (System.nanoTime() - start) / 1_000_000.0d + " ms].");
                 submitListener.onResponse(builder.build());
             }