Add profiler counters for time spent in stack unwinding

ddprof-lib/src/main/cpp/counters.h

@@ -59,7 +59,9 @@
   X(AGCT_NOT_JAVA, "agct_not_java")                                            \
   X(AGCT_NATIVE_NO_JAVA_CONTEXT, "agct_native_no_java_context")                \
   X(AGCT_BLOCKED_IN_VM, "agct_blocked_in_vm")                                  \
-  X(SKIPPED_WALLCLOCK_UNWINDS, "skipped_wallclock_unwinds")
+  X(SKIPPED_WALLCLOCK_UNWINDS, "skipped_wallclock_unwinds")                    \
+  X(UNWINDING_TIME_ASYNC, "unwinding_ticks_async")                             \
+  X(UNWINDING_TIME_JVMTI, "unwinding_ticks_jvmti")
 #define X_ENUM(a, b) a,
 typedef enum CounterId : int {
   DD_COUNTER_TABLE(X_ENUM) DD_NUM_COUNTERS

ddprof-lib/src/main/cpp/profiler.cpp

@@ -23,6 +23,7 @@
 #include "stackWalker.h"
 #include "symbols.h"
 #include "thread.h"
+#include "tsc.h"
 #include "vmStructs.h"
 #include "wallClock.h"
 #include <algorithm>
@@ -600,6 +601,7 @@ u32 Profiler::recordJVMTISample(u64 counter, int tid, jthread thread, jint event
   }
   u32 call_trace_id = 0;
   if (!_omit_stacktraces) {
+    u64 startTime = TSC::ticks();
     ASGCT_CallFrame *frames = _calltrace_buffer[lock_index]->_asgct_frames;
     jvmtiFrameInfo *jvmti_frames = _calltrace_buffer[lock_index]->_jvmti_frames;
 
@@ -619,6 +621,10 @@ u32 Profiler::recordJVMTISample(u64 counter, int tid, jthread thread, jint event
     }
 
     call_trace_id = _call_trace_storage.put(num_frames, frames, false, counter);
+    u64 duration = TSC::ticks() - startTime;
+    if (duration > 0) {
+      Counters::increment(UNWINDING_TIME_JVMTI, duration); // increment the JVMTI specific counter
+    }
   }
   if (!deferred) {
     _jfr.recordEvent(lock_index, tid, call_trace_id, event_type, event);
@@ -670,6 +676,7 @@ void Profiler::recordSample(void *ucontext, u64 counter, int tid,
   // record a null stacktrace we can skip the unwind if we've got a
   // call_trace_id determined to be reusable at a higher level
   if (!_omit_stacktraces && call_trace_id == 0) {
+    u64 startTime = TSC::ticks();
     ASGCT_CallFrame *frames = _calltrace_buffer[lock_index]->_asgct_frames;
 
     int num_frames = 0;
@@ -716,6 +723,10 @@ void Profiler::recordSample(void *ucontext, u64 counter, int tid,
     if (thread != nullptr) {
       thread->recordCallTraceId(call_trace_id);
     }
+    u64 duration = TSC::ticks() - startTime;
+    if (duration > 0) {
+      Counters::increment(UNWINDING_TIME_ASYNC, duration); // increment the async specific counter
+    }
   }
   _jfr.recordEvent(lock_index, tid, call_trace_id, event_type, event);
 
@@ -1360,6 +1371,11 @@ Error Profiler::dump(const char *path, const int length) {
 
     _thread_info.clearAll(thread_ids);
     _thread_info.reportCounters();
+
+    // reset unwinding counters
+    Counters::set(UNWINDING_TIME_ASYNC, 0);
+    Counters::set(UNWINDING_TIME_JVMTI, 0);
+
     return err;
   }
 

ddprof-lib/src/main/cpp/stackFrame_x64.cpp

@@ -62,7 +62,6 @@ void StackFrame::ret() {
 
 bool StackFrame::unwindStub(instruction_t *entry, const char *name,
                             uintptr_t &pc, uintptr_t &sp, uintptr_t &fp) {
-
   instruction_t *ip = (instruction_t *)pc;
   if (ip == entry || *ip == 0xc3 || strncmp(name, "itable", 6) == 0 ||
       strncmp(name, "vtable", 6) == 0 ||

ddprof-lib/src/main/cpp/stackWalker.cpp

@@ -146,7 +146,6 @@ int StackWalker::walkFP(void *ucontext, const void **callchain, int max_depth,
     sp = fp + (FRAME_PC_SLOT + 1) * sizeof(void *);
     fp = *(uintptr_t *)fp;
   }
-
   return depth;
 }