Skip to content

Commit e094330

Browse files
bric3jbachorik
bric3
authored and
jbachorik
committed
Add profiler counters for time spent in stack unwinding
1 parent c74ac25 commit e094330

File tree

6 files changed

+247
-2
lines changed

6 files changed

+247
-2
lines changed

‎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: 66 additions & 0 deletions
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 &&
@@ -117,6 +145,7 @@ static inline bool isEntryBarrier(instruction_t *ip) {
117145

118146
bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
119147
uintptr_t &fp) {
148+
const u64 startTime = TSC::ticks();
120149
instruction_t *ip = (instruction_t *)pc;
121150
instruction_t *entry = (instruction_t *)nm->entry();
122151
if ((*ip & 0xffe07fff) == 0xa9007bfd) {
@@ -125,34 +154,71 @@ bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
125154
unsigned int offset = (*ip >> 12) & 0x1f8;
126155
sp += offset + 16;
127156
pc = link();
157+
158+
const u64 endTime = TSC::ticks();
159+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
160+
if (duration > 1) {
161+
Counters::increment(UNWINDING_COMPILED_TIME, duration);
162+
}
128163
} else if (ip > entry && ip[0] == 0x910003fd && ip[-1] == 0xa9bf7bfd) {
129164
// stp x29, x30, [sp, #-16]!
130165
// mov x29, sp
131166
sp += 16;
132167
pc = ((uintptr_t *)sp)[-1];
168+
169+
const u64 endTime = TSC::ticks();
170+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
171+
if (duration > 1) {
172+
Counters::increment(UNWINDING_COMPILED_TIME, duration);
173+
}
133174
} else if (ip > entry + 3 && !nm->isFrameCompleteAt(ip) &&
134175
(isEntryBarrier(ip) || isEntryBarrier(ip + 1))) {
135176
// Frame should be complete at this point
136177
sp += nm->frameSize() * sizeof(void *);
137178
fp = ((uintptr_t *)sp)[-2];
138179
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_COMPILED_TIME, duration);
185+
}
139186
} else {
140187
// Just try
141188
pc = link();
142189
}
190+
191+
const u64 endTime = TSC::ticks();
192+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
193+
if (duration > 1) {
194+
Counters::increment(UNWINDING_COMPILED_TIME, duration);
195+
}
143196
return true;
144197
}
145198

146199
bool StackFrame::unwindAtomicStub(const void*& pc) {
147200
// VM threads may call generated atomic stubs, which are not normally walkable
201+
const u64 startTime = TSC::ticks();
148202
const void* lr = (const void*)link();
149203
if (VMStructs::libjvm()->contains(lr)) {
150204
NMethod* nm = CodeHeap::findNMethod(pc);
151205
if (nm != NULL && strncmp(nm->name(), "Stub", 4) == 0) {
152206
pc = lr;
207+
208+
const u64 endTime = TSC::ticks();
209+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
210+
if (duration > 1) {
211+
Counters::increment(UNWINDING_ATOMIC_STUB_TIME, duration);
212+
}
153213
return true;
154214
}
155215
}
216+
217+
const u64 endTime = TSC::ticks();
218+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
219+
if (duration > 1) {
220+
Counters::increment(UNWINDING_ATOMIC_STUB_TIME, duration);
221+
}
156222
return false;
157223
}
158224

‎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_COMPILED_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_COMPILED_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_COMPILED_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_COMPILED_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_COMPILED_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_COMPILED_TIME, duration);
161+
}
115162
return false;
116163
}
117164

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

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,9 @@
2222
#include <errno.h>
2323
#include <signal.h>
2424

25+
#include "counters.h"
26+
#include "tsc.h"
27+
2528
uintptr_t &StackFrame::pc() {
2629
return (uintptr_t &)_ucontext->uc_mcontext.regs->nip;
2730
}
@@ -112,12 +115,21 @@ static inline bool inC2PrologueCrit(uintptr_t pc) {
112115

113116
bool StackFrame::unwindStub(instruction_t *entry, const char *name,
114117
uintptr_t &pc, uintptr_t &sp, uintptr_t &fp) {
118+
const u64 startTime = TSC::ticks();
115119
pc = link();
120+
121+
const u64 endTime = TSC::ticks();
122+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
123+
if (duration > 1) {
124+
Counters::increment(UNWINDING_STUB_TIME, duration);
125+
}
116126
return true;
117127
}
118128

119129
bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
120130
uintptr_t &fp) {
131+
const u64 startTime = TSC::ticks();
132+
121133
// On PPC there is a valid back link to the previous frame at all times. The
122134
// callee stores the return address in the caller's frame before it constructs
123135
// its own frame. After it has destroyed its frame it restores the link
@@ -140,6 +152,12 @@ bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
140152
pc = link();
141153
}
142154

155+
156+
const u64 endTime = TSC::ticks();
157+
const u64 duration = TSC::ticks_to_millis(endTime - startTime);
158+
if (duration > 1) {
159+
Counters::increment(UNWINDING_COMPILED_TIME, duration);
160+
}
143161
return true;
144162
}
145163

0 commit comments

Comments
 (0)