Skip to content

Commit 92cc141

Browse files
bric3bric3
committed
Add profiler counters for time spent in stack unwinding
Note still debating on how to add/declare these counters. PROF-11368
1 parent 0e5b5f9 commit 92cc141

6 files changed

Lines changed: 260 additions & 3 deletions

File tree

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

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -59,7 +59,10 @@
5959
X(AGCT_NOT_JAVA, "agct_not_java") \
6060
X(AGCT_NATIVE_NO_JAVA_CONTEXT, "agct_native_no_java_context") \
6161
X(AGCT_BLOCKED_IN_VM, "agct_blocked_in_vm") \
62-
X(SKIPPED_WALLCLOCK_UNWINDS, "skipped_wallclock_unwinds")
62+
X(SKIPPED_WALLCLOCK_UNWINDS, "skipped_wallclock_unwinds") \
63+
X(UNWINDING_STUB_TIME, "unwinding_stub_time") \
64+
X(UNWINDING_COMPILED_TIME, "unwinding_compiled_time") \
65+
X(UNWINDING_ATOMIC_STUB_TIME, "unwinding_atomic_stub_time")
6366
#define X_ENUM(a, b) a,
6467
typedef enum CounterId : int {
6568
DD_COUNTER_TABLE(X_ENUM) DD_NUM_COUNTERS

‎ddprof-lib/src/main/cpp/stackFrame_aarch64.cpp‎

Lines changed: 79 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,9 @@
2323
#include <string.h>
2424
#include <sys/syscall.h>
2525

26+
#include "counters.h"
27+
#include "tsc.h"
28+
2629
#ifdef __APPLE__
2730
#define REG(l, m) _ucontext->uc_mcontext->__ss.__##m
2831
#else
@@ -57,6 +60,7 @@ void StackFrame::ret() { pc() = link(); }
5760

5861
bool StackFrame::unwindStub(instruction_t *entry, const char *name,
5962
uintptr_t &pc, uintptr_t &sp, uintptr_t &fp) {
63+
const u64 startTime = TSC::ticks();
6064
instruction_t *ip = (instruction_t *)pc;
6165
if (ip == entry || *ip == 0xd65f03c0 || strncmp(name, "itable", 6) == 0 ||
6266
strncmp(name, "vtable", 6) == 0 ||
@@ -67,6 +71,12 @@ bool StackFrame::unwindStub(instruction_t *entry, const char *name,
6771
strcmp(name, "atomic entry points") == 0 ||
6872
strcmp(name, "InlineCacheBuffer") == 0) {
6973
pc = link();
74+
75+
const u64 endTime = TSC::ticks();
76+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
77+
if (duration > 1) {
78+
Counters::increment(UNWINDING_STUB_TIME, duration);
79+
}
7080
return true;
7181
} else if (strcmp(name, "forward_copy_longs") == 0 ||
7282
strcmp(name, "backward_copy_longs") == 0
@@ -83,6 +93,12 @@ bool StackFrame::unwindStub(instruction_t *entry, const char *name,
8393
// When cstack=vm, unwind stub frames one by one
8494
pc = link();
8595
}
96+
97+
const u64 endTime = TSC::ticks();
98+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
99+
if (duration > 1) {
100+
Counters::increment(UNWINDING_STUB_TIME, duration);
101+
}
86102
return true;
87103
} else if (entry != NULL && entry[0] == 0xa9bf7bfd) {
88104
// The stub begins with
@@ -91,11 +107,23 @@ bool StackFrame::unwindStub(instruction_t *entry, const char *name,
91107
if (ip == entry + 1) {
92108
sp += 16;
93109
pc = ((uintptr_t *)sp)[-1];
110+
111+
const u64 endTime = TSC::ticks();
112+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
113+
if (duration > 1) {
114+
Counters::increment(UNWINDING_STUB_TIME, duration);
115+
}
94116
return true;
95117
} else if (entry[1] == 0x910003fd && withinCurrentStack(fp)) {
96118
sp = fp + 16;
97119
fp = ((uintptr_t *)sp)[-2];
98120
pc = ((uintptr_t *)sp)[-1];
121+
122+
const u64 endTime = TSC::ticks();
123+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
124+
if (duration > 1) {
125+
Counters::increment(UNWINDING_STUB_TIME, duration);
126+
}
99127
return true;
100128
}
101129
} else if (strncmp(name, "indexof_linear_", 15) == 0 &&
@@ -104,8 +132,20 @@ bool StackFrame::unwindStub(instruction_t *entry, const char *name,
104132
// Entry and exit are covered by the very first 'if', in all other cases SP is 4 words off.
105133
sp += 32;
106134
pc = link();
107-
return true;
135+
136+
const u64 endTime = TSC::ticks();
137+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
138+
if (duration > 1) {
139+
Counters::increment(UNWINDING_STUB_TIME, duration);
140+
}
141+
return true;
108142
}
143+
144+
const u64 endTime = TSC::ticks();
145+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
146+
if (duration > 1) {
147+
Counters::increment(UNWINDING_STUB_TIME, duration);
148+
}
109149
return false;
110150
}
111151

@@ -117,6 +157,7 @@ static inline bool isEntryBarrier(instruction_t *ip) {
117157

118158
bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
119159
uintptr_t &fp) {
160+
const u64 startTime = TSC::ticks();
120161
instruction_t *ip = (instruction_t *)pc;
121162
instruction_t *entry = (instruction_t *)nm->entry();
122163
if ((*ip & 0xffe07fff) == 0xa9007bfd) {
@@ -125,34 +166,71 @@ bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
125166
unsigned int offset = (*ip >> 12) & 0x1f8;
126167
sp += offset + 16;
127168
pc = link();
169+
170+
const u64 endTime = TSC::ticks();
171+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
172+
if (duration > 1) {
173+
Counters::increment(UNWINDING_STUB_TIME, duration);
174+
}
128175
} else if (ip > entry && ip[0] == 0x910003fd && ip[-1] == 0xa9bf7bfd) {
129176
// stp x29, x30, [sp, #-16]!
130177
// mov x29, sp
131178
sp += 16;
132179
pc = ((uintptr_t *)sp)[-1];
180+
181+
const u64 endTime = TSC::ticks();
182+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
183+
if (duration > 1) {
184+
Counters::increment(UNWINDING_STUB_TIME, duration);
185+
}
133186
} else if (ip > entry + 3 && !nm->isFrameCompleteAt(ip) &&
134187
(isEntryBarrier(ip) || isEntryBarrier(ip + 1))) {
135188
// Frame should be complete at this point
136189
sp += nm->frameSize() * sizeof(void *);
137190
fp = ((uintptr_t *)sp)[-2];
138191
pc = ((uintptr_t *)sp)[-1];
192+
193+
const u64 endTime = TSC::ticks();
194+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
195+
if (duration > 1) {
196+
Counters::increment(UNWINDING_STUB_TIME, duration);
197+
}
139198
} else {
140199
// Just try
141200
pc = link();
142201
}
202+
203+
const u64 endTime = TSC::ticks();
204+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
205+
if (duration > 1) {
206+
Counters::increment(UNWINDING_STUB_TIME, duration);
207+
}
143208
return true;
144209
}
145210

146211
bool StackFrame::unwindAtomicStub(const void*& pc) {
147212
// VM threads may call generated atomic stubs, which are not normally walkable
213+
const u64 startTime = TSC::ticks();
148214
const void* lr = (const void*)link();
149215
if (VMStructs::libjvm()->contains(lr)) {
150216
NMethod* nm = CodeHeap::findNMethod(pc);
151217
if (nm != NULL && strncmp(nm->name(), "Stub", 4) == 0) {
152218
pc = lr;
219+
220+
const u64 endTime = TSC::ticks();
221+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
222+
if (duration > 1) {
223+
Counters::increment(UNWINDING_STUB_TIME, duration);
224+
}
153225
return true;
154226
}
155227
}
228+
229+
const u64 endTime = TSC::ticks();
230+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
231+
if (duration > 1) {
232+
Counters::increment(UNWINDING_STUB_TIME, duration);
233+
}
156234
return false;
157235
}
158236

‎ddprof-lib/src/main/cpp/stackFrame_arm.cpp‎

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,9 @@
2121
#include <errno.h>
2222
#include <string.h>
2323

24+
#include "counters.h"
25+
#include "tsc.h"
26+
2427
uintptr_t &StackFrame::pc() {
2528
return (uintptr_t &)_ucontext->uc_mcontext.arm_pc;
2629
}
@@ -74,18 +77,32 @@ void StackFrame::ret() { pc() = link(); }
7477

7578
bool StackFrame::unwindStub(instruction_t *entry, const char *name,
7679
uintptr_t &pc, uintptr_t &sp, uintptr_t &fp) {
80+
const u64 startTime = TSC::ticks();
7781
instruction_t *ip = (instruction_t *)pc;
7882
if (ip == entry || *ip == 0xe12fff1e || strncmp(name, "itable", 6) == 0 ||
7983
strncmp(name, "vtable", 6) == 0 ||
8084
strcmp(name, "InlineCacheBuffer") == 0) {
8185
pc = link();
86+
87+
const u64 endTime = TSC::ticks();
88+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
89+
if (duration > 1) {
90+
Counters::increment(UNWINDING_STUB_TIME, duration);
91+
}
8292
return true;
8393
}
94+
95+
const u64 endTime = TSC::ticks();
96+
u64 duration = TSC::ticks_to_millis(endTime - startTime);
97+
if (duration > 1) {
98+
Counters::increment(UNWINDING_STUB_TIME, duration);
99+
}
84100
return false;
85101
}
86102

87103
bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
88104
uintptr_t &fp) {
105+
const u64 startTime = TSC::ticks();
89106
instruction_t *ip = (instruction_t *)pc;
90107
instruction_t *entry = (instruction_t *)nm->entry();
91108
if (ip > entry && ip <= entry + 4 && (*ip & 0xffffff00) == 0xe24dd000) {
@@ -95,16 +112,34 @@ bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
95112
fp = ((uintptr_t *)sp)[0];
96113
pc = ((uintptr_t *)sp)[1];
97114
sp += 8;
115+
116+
const u64 endTime = TSC::ticks();
117+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
118+
if (duration > 1) {
119+
Counters::increment(UNWINDING_STUB_TIME, duration);
120+
}
98121
return true;
99122
} else if (*ip == 0xe8bd4800) {
100123
// add sp, sp, #offs
101124
// -> pop {r11, lr}
102125
fp = ((uintptr_t *)sp)[0];
103126
pc = ((uintptr_t *)sp)[1];
104127
sp += 8;
128+
129+
const u64 endTime = TSC::ticks();
130+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
131+
if (duration > 1) {
132+
Counters::increment(UNWINDING_STUB_TIME, duration);
133+
}
105134
return true;
106135
}
107136
pc = link();
137+
138+
const u64 endTime = TSC::ticks();
139+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
140+
if (duration > 1) {
141+
Counters::increment(UNWINDING_STUB_TIME, duration);
142+
}
108143
return true;
109144
}
110145

‎ddprof-lib/src/main/cpp/stackFrame_i386.cpp‎

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,9 @@
2121
#include <errno.h>
2222
#include <string.h>
2323

24+
#include "counters.h"
25+
#include "tsc.h"
26+
2427
uintptr_t &StackFrame::pc() {
2528
return (uintptr_t &)_ucontext->uc_mcontext.gregs[REG_EIP];
2629
}
@@ -68,12 +71,19 @@ void StackFrame::ret() {
6871

6972
bool StackFrame::unwindStub(instruction_t *entry, const char *name,
7073
uintptr_t &pc, uintptr_t &sp, uintptr_t &fp) {
74+
const u64 startTime = TSC::ticks();
7175
instruction_t *ip = (instruction_t *)pc;
7276
if (ip == entry || *ip == 0xc3 || strncmp(name, "itable", 6) == 0 ||
7377
strncmp(name, "vtable", 6) == 0 ||
7478
strcmp(name, "InlineCacheBuffer") == 0) {
7579
pc = *(uintptr_t *)sp;
7680
sp += 4;
81+
82+
const u64 endTime = TSC::ticks();
83+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
84+
if (duration > 1) {
85+
Counters::increment(UNWINDING_STUB_TIME, duration);
86+
}
7787
return true;
7888
} else if (entry != NULL && entry[0] == 0x55 && entry[1] == 0x8b &&
7989
entry[2] == 0xec) {
@@ -83,19 +93,38 @@ bool StackFrame::unwindStub(instruction_t *entry, const char *name,
8393
if (ip == entry + 1) {
8494
pc = ((uintptr_t *)sp)[1];
8595
sp += 8;
96+
97+
const u64 endTime = TSC::ticks();
98+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
99+
if (duration > 1) {
100+
Counters::increment(UNWINDING_STUB_TIME, duration);
101+
}
86102
return true;
87103
} else if (withinCurrentStack(fp)) {
88104
sp = fp + 8;
89105
fp = ((uintptr_t *)sp)[-2];
90106
pc = ((uintptr_t *)sp)[-1];
107+
108+
const u64 endTime = TSC::ticks();
109+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
110+
if (duration > 1) {
111+
Counters::increment(UNWINDING_STUB_TIME, duration);
112+
}
91113
return true;
92114
}
93115
}
116+
117+
const u64 endTime = TSC::ticks();
118+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
119+
if (duration > 1) {
120+
Counters::increment(UNWINDING_STUB_TIME, duration);
121+
}
94122
return false;
95123
}
96124

97125
bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
98126
uintptr_t &fp) {
127+
const u64 startTime = TSC::ticks();
99128
instruction_t *ip = (instruction_t *)pc;
100129
instruction_t *entry = (instruction_t *)nm->entry();
101130
if (ip <= entry || *ip == 0xc3 // ret
@@ -104,14 +133,32 @@ bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
104133
{
105134
pc = *(uintptr_t *)sp;
106135
sp += 4;
136+
137+
const u64 endTime = TSC::ticks();
138+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
139+
if (duration > 1) {
140+
Counters::increment(UNWINDING_STUB_TIME, duration);
141+
}
107142
return true;
108143
} else if (*ip == 0x5d) {
109144
// pop ebp
110145
fp = ((uintptr_t *)sp)[0];
111146
pc = ((uintptr_t *)sp)[1];
112147
sp += 8;
148+
149+
const u64 endTime = TSC::ticks();
150+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
151+
if (duration > 1) {
152+
Counters::increment(UNWINDING_STUB_TIME, duration);
153+
}
113154
return true;
114155
}
156+
157+
const u64 endTime = TSC::ticks();
158+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
159+
if (duration > 1) {
160+
Counters::increment(UNWINDING_STUB_TIME, duration);
161+
}
115162
return false;
116163
}
117164

0 commit comments

Comments
 (0)