[#9200] Backport: Fix agent callstack overflow log

Author: jaehong-kim

agent/src/main/resources/profiles/local/pinpoint.config

@@ -165,6 +165,7 @@ profiler.monitor.deadlock.interval=60000
 ## Call Stack
 # Set max depth, if -1 is unlimited and min is 2.
 profiler.callstack.max.depth=64
+profiler.callstack.overflow.log.ration=100
 
 # weather or not to propagate exceptions occurred at interceptor
 profiler.interceptor.exception.propagate=false

agent/src/main/resources/profiles/release/pinpoint.config

@@ -165,6 +165,7 @@ profiler.monitor.deadlock.interval=60000
 ## Call Stack
 # Set max depth, if -1 is unlimited and min is 2.
 profiler.callstack.max.depth=64
+profiler.callstack.overflow.log.ration=100
 
 # weather or not to propagate exceptions occurred at interceptor
 profiler.interceptor.exception.propagate=false

bootstraps/bootstrap-core/src/main/java/com/navercorp/pinpoint/bootstrap/interceptor/AsyncContextSpanEventEndPointInterceptor.java

@@ -143,8 +143,8 @@ protected AsyncContext getAsyncContext(Object target, Object[] args) {
     private Trace getAsyncTrace(AsyncContext asyncContext) {
         final Trace trace = asyncContext.continueAsyncTraceObject();
         if (trace == null) {
-            if (logger.isWarnEnabled()) {
-                logger.warn("Failed to continue async trace. 'result is null'");
+            if (isDebug) {
+                logger.debug("Failed to continue async trace. 'result is null'");
             }
             return null;
         }

bootstraps/bootstrap-core/src/main/java/com/navercorp/pinpoint/bootstrap/interceptor/AsyncContextSpanEventSimpleAroundInterceptor.java

@@ -127,8 +127,8 @@ protected AsyncContext getAsyncContext(Object target, Object[] args, Object resu
     private Trace getAsyncTrace(AsyncContext asyncContext) {
         final Trace trace = asyncContext.continueAsyncTraceObject();
         if (trace == null) {
-            if (logger.isWarnEnabled()) {
-                logger.warn("Failed to continue async trace. 'result is null'");
+            if (isDebug) {
+                logger.debug("Failed to continue async trace. 'result is null'");
             }
             return null;
         }

plugins/akka-http/src/main/java/com/navercorp/pinpoint/plugin/akka/http/interceptor/AsyncContextSpanEventEndPointInterceptor.java

@@ -145,8 +145,8 @@ protected AsyncContext getAsyncContext(Object target) {
     private Trace getAsyncTrace(AsyncContext asyncContext) {
         final Trace trace = asyncContext.continueAsyncTraceObject();
         if (trace == null) {
-            if (logger.isWarnEnabled()) {
-                logger.warn("Failed to continue async trace. 'result is null'");
+            if (isDebug) {
+                logger.debug("Failed to continue async trace. 'result is null'");
             }
             return null;
         }

plugins/netty/src/main/java/com/navercorp/pinpoint/plugin/netty/interceptor/http/HttpEncoderInterceptor.java

@@ -232,8 +232,8 @@ protected void doInAfterTrace(SpanEventRecorder recorder, Object target, Object[
     private Trace getAsyncTrace(AsyncContext asyncContext) {
         final Trace trace = asyncContext.continueAsyncTraceObject();
         if (trace == null) {
-            if (logger.isWarnEnabled()) {
-                logger.warn("Failed to continue async trace. 'result is null'");
+            if (isDebug) {
+                logger.debug("Failed to continue async trace. 'result is null'");
             }
             return null;
         }

plugins/rabbitmq/src/main/java/com/navercorp/pinpoint/plugin/rabbitmq/client/interceptor/ConsumerHandleDeliveryInterceptor.java

@@ -134,8 +134,8 @@ private boolean validate(Object target, Object[] args) {
     private Trace getAsyncTrace(AsyncContext asyncContext) {
         final Trace trace = asyncContext.continueAsyncTraceObject();
         if (trace == null) {
-            if (logger.isWarnEnabled()) {
-                logger.warn("Failed to continue async trace. 'result is null'");
+            if (isDebug) {
+                logger.debug("Failed to continue async trace. 'result is null'");
             }
             return null;
         }

plugins/user/src/main/java/com/navercorp/pinpoint/plugin/user/interceptor/MQExternalClientHandlerInterceptor.java

@@ -136,8 +136,8 @@ private AsyncContext getAsyncContext(Object[] args) {
     private Trace getAsyncTrace(AsyncContext asyncContext) {
         final Trace trace = asyncContext.continueAsyncTraceObject();
         if (trace == null) {
-            if (logger.isWarnEnabled()) {
-                logger.warn("Failed to continue async trace. 'result is null'");
+            if (isDebug) {
+                logger.debug("Failed to continue async trace. 'result is null'");
             }
             return null;
         }

plugins/vertx/src/main/java/com/navercorp/pinpoint/plugin/vertx/interceptor/AsyncContextSpanEventEndPointInterceptor.java

@@ -145,8 +145,8 @@ protected AsyncContext getAsyncContext(Object target) {
     private Trace getAsyncTrace(AsyncContext asyncContext) {
         final Trace trace = asyncContext.continueAsyncTraceObject();
         if (trace == null) {
-            if (logger.isWarnEnabled()) {
-                logger.warn("Failed to continue async trace. 'result is null'");
+            if (isDebug) {
+                logger.debug("Failed to continue async trace. 'result is null'");
             }
             return null;
         }

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/AsyncChildTrace.java

@@ -39,7 +39,6 @@ public class AsyncChildTrace implements Trace {
 
     private static final Logger logger = LogManager.getLogger(AsyncChildTrace.class.getName());
     private static final boolean isDebug = logger.isDebugEnabled();
-
     private final CallStack<SpanEvent> callStack;
 
     private final Storage storage;

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/CallStack.java

@@ -40,6 +40,8 @@ public interface CallStack<T> {
 
     Factory<T> getFactory();
 
+    void setOverflowListener(CallStackOverflowListener overflowListener);
+
     interface Factory<T> {
         Class<T> getType();
 

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/CallStackFactoryV1.java

@@ -24,14 +24,22 @@ public class CallStackFactoryV1 implements CallStackFactory<SpanEvent> {
     private final CallStack.Factory<SpanEvent> factory = new SpanEventFactory();
     private final int maxDepth;
     private final int maxSequence;
+    private final CallStackOverflowListener overflowListener;
 
-    public CallStackFactoryV1(int maxDepth, int maxSequence) {
+    public CallStackFactoryV1(int maxDepth, int maxSequence, int overflowLogRation) {
         this.maxDepth = maxDepth;
         this.maxSequence = maxSequence;
+        if (overflowLogRation > 1) {
+            this.overflowListener = new ThrottledLogCallStackOverflowListener(maxDepth, maxSequence, overflowLogRation);
+        } else {
+            this.overflowListener = new DefaultCallStackOverflowListener(maxDepth, maxSequence);
+        }
     }
 
     @Override
     public CallStack<SpanEvent> newCallStack() {
-        return new DepthCompressCallStack<>(factory, maxDepth, maxSequence);
+        final CallStack<SpanEvent> callStack = new DepthCompressCallStack<>(factory, maxDepth, maxSequence);
+        callStack.setOverflowListener(overflowListener);
+        return callStack;
     }
-}
+}

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/CallStackFactoryV2.java

@@ -24,14 +24,22 @@ public class CallStackFactoryV2 implements CallStackFactory<SpanEvent> {
     private final CallStack.Factory<SpanEvent> factory = new SpanEventFactory();
     private final int maxDepth;
     private final int maxSequence;
+    private final CallStackOverflowListener overflowListener;
 
-    public CallStackFactoryV2(int maxDepth, int maxSequence) {
+    public CallStackFactoryV2(int maxDepth, int maxSequence, int overflowLogRation) {
         this.maxDepth = maxDepth;
         this.maxSequence = maxSequence;
+        if (overflowLogRation > 1) {
+            this.overflowListener = new ThrottledLogCallStackOverflowListener(maxDepth, maxSequence, overflowLogRation);
+        } else {
+            this.overflowListener = new DefaultCallStackOverflowListener(maxDepth, maxSequence);
+        }
     }
 
     @Override
     public CallStack<SpanEvent> newCallStack() {
-        return new DefaultCallStack<>(factory, maxDepth, maxSequence);
+        final CallStack<SpanEvent> callStack = new DefaultCallStack<>(factory, maxDepth, maxSequence);
+        callStack.setOverflowListener(overflowListener);
+        return callStack;
     }
 }

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/CallStackOverflowListener.java

@@ -0,0 +1,22 @@
+/*
+ * Copyright 2022 NAVER Corp.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.navercorp.pinpoint.profiler.context;
+
+public interface CallStackOverflowListener {
+
+    void fireOverflow(int callStackIndex);
+}

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/DefaultCallStack.java

@@ -39,6 +39,8 @@ public class DefaultCallStack<T> implements CallStack<T> {
     protected int overflowIndex = 0;
     protected final int maxSequence;
     protected int sequence;
+    protected CallStackOverflowListener overflowListener;
+    protected boolean overflowed = false;
 
     public DefaultCallStack(Factory<T> factory) {
         this(factory, -1, -1);
@@ -53,16 +55,28 @@ public DefaultCallStack(Factory<T> factory, int maxDepth, int maxSequence) {
         this.factory = factory;
         this.maxDepth = maxDepth;
         this.maxSequence = maxSequence;
-
         this.stack = newStack(factory.getType(), STACK_SIZE);
     }
 
+    public void setOverflowListener(CallStackOverflowListener overflowListener) {
+        this.overflowListener = overflowListener;
+    }
+
+    void onOverflow(final int point) {
+        if (Boolean.FALSE == overflowed) {
+            if (overflowListener != null) {
+                overflowListener.fireOverflow(point);
+            }
+            // Make sure it runs only once per CallStack.
+            overflowed = true;
+        }
+    }
+
     @SuppressWarnings("unchecked")
     private T[] newStack(Class<T> type, int size) {
         return (T[]) Array.newInstance(type, size);
     }
 
-
     @Override
     public int getIndex() {
         if (isOverflow()) {
@@ -76,7 +90,9 @@ public int getIndex() {
     public int push(final T element) {
         if (isOverflow()) {
             overflowIndex++;
-            return index + overflowIndex;
+            final int point = index + overflowIndex;
+            onOverflow(point);
+            return point;
         }
 
         checkExtend(index + 1);
@@ -90,7 +106,6 @@ protected void markDepth(T element, int index) {
         factory.markDepth(element, index);
     }
 
-
     private void checkExtend(final int size) {
         final T[] originalStack = this.stack;
         if (size >= originalStack.length) {

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/DefaultCallStackOverflowListener.java

@@ -0,0 +1,40 @@
+/*
+ * Copyright 2022 NAVER Corp.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.navercorp.pinpoint.profiler.context;
+
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+public class DefaultCallStackOverflowListener implements CallStackOverflowListener {
+    private final Logger logger = LogManager.getLogger(this.getClass());
+    private final boolean isInfo = logger.isInfoEnabled();
+
+    private final int maxDepth;
+    private final int maxSequence;
+
+    public DefaultCallStackOverflowListener(final int maxDepth, final int maxSequence) {
+        this.maxDepth = maxDepth;
+        this.maxSequence = maxSequence;
+    }
+
+    @Override
+    public void fireOverflow(final int callStackIndex) {
+        if (isInfo) {
+            logger.info("CallStack maximum depth/sequence exceeded. Check the profiler.callstack.max.depth. current.index={}, max.depth={}, max.sequence={}", callStackIndex, maxDepth, maxSequence);
+        }
+    }
+}

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/DepthCompressCallStack.java

@@ -43,7 +43,4 @@ protected void markDepth(T element, int depth) {
             this.factory.markDepth(element, latestStackIndex);
         }
     }
-
-
-
 }

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/ThrottledLogCallStackOverflowListener.java

@@ -0,0 +1,43 @@
+/*
+ * Copyright 2022 NAVER Corp.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.navercorp.pinpoint.profiler.context;
+
+import com.navercorp.pinpoint.common.profiler.logging.ThrottledLogger;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+
+public class ThrottledLogCallStackOverflowListener implements CallStackOverflowListener {
+    private final Logger logger = LogManager.getLogger(this.getClass());
+    private final boolean isInfo = logger.isInfoEnabled();
+
+    private final int maxDepth;
+    private final int maxSequence;
+    private ThrottledLogger throttledLogger;
+
+    public ThrottledLogCallStackOverflowListener(final int maxDepth, final int maxSequence, final int overflowLogRation) {
+        this.maxDepth = maxDepth;
+        this.maxSequence = maxSequence;
+        this.throttledLogger = ThrottledLogger.getLogger(logger, overflowLogRation);
+    }
+
+    @Override
+    public void fireOverflow(final int callStackIndex) {
+        if (isInfo) {
+            throttledLogger.info("CallStack maximum depth/sequence exceeded. Check the profiler.callstack.max.depth. current.index={}, max.depth={}, max.sequence={}", callStackIndex, maxDepth, maxSequence);
+        }
+    }
+}

profiler/src/main/java/com/navercorp/pinpoint/profiler/context/provider/CallStackFactoryProvider.java

@@ -35,25 +35,25 @@ public class CallStackFactoryProvider implements Provider<CallStackFactory<SpanE
     private final TraceDataFormatVersion version;
     private final int callStackMaxDepth;
     private final int callStackMaxSequence;
-
+    private final int callStackOverflowLogRation;
 
     @Inject
     public CallStackFactoryProvider(InstrumentConfig instrumentConfig,
                                     TraceDataFormatVersion version) {
         this.version = Objects.requireNonNull(version, "version");
         this.callStackMaxDepth = instrumentConfig.getCallStackMaxDepth();
         this.callStackMaxSequence = instrumentConfig.getCallStackMaxSequence();
+        this.callStackOverflowLogRation = instrumentConfig.getCallStackOverflowLogRation();
     }
 
     @Override
     public CallStackFactory<SpanEvent> get() {
         if (version == TraceDataFormatVersion.V2) {
-            return new CallStackFactoryV2(callStackMaxDepth, callStackMaxSequence);
+            return new CallStackFactoryV2(callStackMaxDepth, callStackMaxSequence, callStackOverflowLogRation);
         }
         if (version == TraceDataFormatVersion.V1) {
-            return new CallStackFactoryV1(callStackMaxDepth, callStackMaxSequence);
+            return new CallStackFactoryV1(callStackMaxDepth, callStackMaxSequence, callStackOverflowLogRation);
         }
         throw new UnsupportedOperationException("unknown version :" + version);
     }
-
 }