Skip to content

Commit e0a1ef1

Browse files
jbachorikjbachorik
committed
Use single-entry for measuring unwinding costs
1 parent 3dde0b5 commit e0a1ef1

File tree

8 files changed

+18
-245
lines changed

8 files changed

+18
-245
lines changed

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -60,7 +60,8 @@
6060
X(AGCT_NATIVE_NO_JAVA_CONTEXT, "agct_native_no_java_context") \
6161
X(AGCT_BLOCKED_IN_VM, "agct_blocked_in_vm") \
6262
X(SKIPPED_WALLCLOCK_UNWINDS, "skipped_wallclock_unwinds") \
63-
X(UNWINDING_TIME, "unwinding_time")
63+
X(UNWINDING_TIME_ASYNC, "unwinding_ticks_async") \
64+
X(UNWINDING_TIME_JVMTI, "unwinding_ticks_jvmti")
6465
#define X_ENUM(a, b) a,
6566
typedef enum CounterId : int {
6667
DD_COUNTER_TABLE(X_ENUM) DD_NUM_COUNTERS

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

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@
2323
#include "stackWalker.h"
2424
#include "symbols.h"
2525
#include "thread.h"
26+
#include "tsc.h"
2627
#include "vmStructs.h"
2728
#include "wallClock.h"
2829
#include <algorithm>
@@ -600,6 +601,7 @@ u32 Profiler::recordJVMTISample(u64 counter, int tid, jthread thread, jint event
600601
}
601602
u32 call_trace_id = 0;
602603
if (!_omit_stacktraces) {
604+
u64 startTime = TSC::ticks();
603605
ASGCT_CallFrame *frames = _calltrace_buffer[lock_index]->_asgct_frames;
604606
jvmtiFrameInfo *jvmti_frames = _calltrace_buffer[lock_index]->_jvmti_frames;
605607

@@ -619,6 +621,10 @@ u32 Profiler::recordJVMTISample(u64 counter, int tid, jthread thread, jint event
619621
}
620622

621623
call_trace_id = _call_trace_storage.put(num_frames, frames, false, counter);
624+
u64 duration = TSC::ticks() - startTime;
625+
if (duration > 0) {
626+
Counters::increment(UNWINDING_TIME_JVMTI, duration); // increment the JVMTI specific counter
627+
}
622628
}
623629
if (!deferred) {
624630
_jfr.recordEvent(lock_index, tid, call_trace_id, event_type, event);
@@ -670,6 +676,7 @@ void Profiler::recordSample(void *ucontext, u64 counter, int tid,
670676
// record a null stacktrace we can skip the unwind if we've got a
671677
// call_trace_id determined to be reusable at a higher level
672678
if (!_omit_stacktraces && call_trace_id == 0) {
679+
u64 startTime = TSC::ticks();
673680
ASGCT_CallFrame *frames = _calltrace_buffer[lock_index]->_asgct_frames;
674681

675682
int num_frames = 0;
@@ -716,6 +723,10 @@ void Profiler::recordSample(void *ucontext, u64 counter, int tid,
716723
if (thread != nullptr) {
717724
thread->recordCallTraceId(call_trace_id);
718725
}
726+
u64 duration = TSC::ticks() - startTime;
727+
if (duration > 0) {
728+
Counters::increment(UNWINDING_TIME_ASYNC, duration); // increment the async specific counter
729+
}
719730
}
720731
_jfr.recordEvent(lock_index, tid, call_trace_id, event_type, event);
721732

@@ -1360,6 +1371,11 @@ Error Profiler::dump(const char *path, const int length) {
13601371

13611372
_thread_info.clearAll(thread_ids);
13621373
_thread_info.reportCounters();
1374+
1375+
// reset unwinding counters
1376+
Counters::set(UNWINDING_TIME_ASYNC, 0);
1377+
Counters::set(UNWINDING_TIME_JVMTI, 0);
1378+
13631379
return err;
13641380
}
13651381

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

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

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

6158
bool StackFrame::unwindStub(instruction_t *entry, const char *name,
6259
uintptr_t &pc, uintptr_t &sp, uintptr_t &fp) {
63-
const u64 startTime = TSC::ticks();
6460
instruction_t *ip = (instruction_t *)pc;
6561
if (ip == entry || *ip == 0xd65f03c0 || strncmp(name, "itable", 6) == 0 ||
6662
strncmp(name, "vtable", 6) == 0 ||
@@ -71,12 +67,6 @@ bool StackFrame::unwindStub(instruction_t *entry, const char *name,
7167
strcmp(name, "atomic entry points") == 0 ||
7268
strcmp(name, "InlineCacheBuffer") == 0) {
7369
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_TIME, duration);
79-
}
8070
return true;
8171
} else if (strcmp(name, "forward_copy_longs") == 0 ||
8272
strcmp(name, "backward_copy_longs") == 0
@@ -93,12 +83,6 @@ bool StackFrame::unwindStub(instruction_t *entry, const char *name,
9383
// When cstack=vm, unwind stub frames one by one
9484
pc = link();
9585
}
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_TIME, duration);
101-
}
10286
return true;
10387
} else if (entry != NULL && entry[0] == 0xa9bf7bfd) {
10488
// The stub begins with
@@ -107,23 +91,11 @@ bool StackFrame::unwindStub(instruction_t *entry, const char *name,
10791
if (ip == entry + 1) {
10892
sp += 16;
10993
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_TIME, duration);
115-
}
11694
return true;
11795
} else if (entry[1] == 0x910003fd && withinCurrentStack(fp)) {
11896
sp = fp + 16;
11997
fp = ((uintptr_t *)sp)[-2];
12098
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_TIME, duration);
126-
}
12799
return true;
128100
}
129101
} else if (strncmp(name, "indexof_linear_", 15) == 0 &&
@@ -145,7 +117,6 @@ static inline bool isEntryBarrier(instruction_t *ip) {
145117

146118
bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
147119
uintptr_t &fp) {
148-
const u64 startTime = TSC::ticks();
149120
instruction_t *ip = (instruction_t *)pc;
150121
instruction_t *entry = (instruction_t *)nm->entry();
151122
if ((*ip & 0xffe07fff) == 0xa9007bfd) {
@@ -154,71 +125,34 @@ bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
154125
unsigned int offset = (*ip >> 12) & 0x1f8;
155126
sp += offset + 16;
156127
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_TIME, duration);
162-
}
163128
} else if (ip > entry && ip[0] == 0x910003fd && ip[-1] == 0xa9bf7bfd) {
164129
// stp x29, x30, [sp, #-16]!
165130
// mov x29, sp
166131
sp += 16;
167132
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_TIME, duration);
173-
}
174133
} else if (ip > entry + 3 && !nm->isFrameCompleteAt(ip) &&
175134
(isEntryBarrier(ip) || isEntryBarrier(ip + 1))) {
176135
// Frame should be complete at this point
177136
sp += nm->frameSize() * sizeof(void *);
178137
fp = ((uintptr_t *)sp)[-2];
179138
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_TIME, duration);
185-
}
186139
} else {
187140
// Just try
188141
pc = link();
189142
}
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_TIME, duration);
195-
}
196143
return true;
197144
}
198145

199146
bool StackFrame::unwindAtomicStub(const void*& pc) {
200147
// VM threads may call generated atomic stubs, which are not normally walkable
201-
const u64 startTime = TSC::ticks();
202148
const void* lr = (const void*)link();
203149
if (VMStructs::libjvm()->contains(lr)) {
204150
NMethod* nm = CodeHeap::findNMethod(pc);
205151
if (nm != NULL && strncmp(nm->name(), "Stub", 4) == 0) {
206152
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_TIME, duration);
212-
}
213153
return true;
214154
}
215155
}
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_TIME, duration);
221-
}
222156
return false;
223157
}
224158

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

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

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

7875
bool StackFrame::unwindStub(instruction_t *entry, const char *name,
7976
uintptr_t &pc, uintptr_t &sp, uintptr_t &fp) {
80-
const u64 startTime = TSC::ticks();
8177
instruction_t *ip = (instruction_t *)pc;
8278
if (ip == entry || *ip == 0xe12fff1e || strncmp(name, "itable", 6) == 0 ||
8379
strncmp(name, "vtable", 6) == 0 ||
8480
strcmp(name, "InlineCacheBuffer") == 0) {
8581
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_TIME, duration);
91-
}
9282
return true;
9383
}
94-
95-
const u64 endTime = TSC::ticks();
96-
u64 duration = TSC::ticks_to_millis(endTime - startTime);
97-
if (duration > 1) {
98-
Counters::increment(UNWINDING_TIME, duration);
99-
}
10084
return false;
10185
}
10286

10387
bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
10488
uintptr_t &fp) {
105-
const u64 startTime = TSC::ticks();
10689
instruction_t *ip = (instruction_t *)pc;
10790
instruction_t *entry = (instruction_t *)nm->entry();
10891
if (ip > entry && ip <= entry + 4 && (*ip & 0xffffff00) == 0xe24dd000) {
@@ -112,34 +95,16 @@ bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
11295
fp = ((uintptr_t *)sp)[0];
11396
pc = ((uintptr_t *)sp)[1];
11497
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_TIME, duration);
120-
}
12198
return true;
12299
} else if (*ip == 0xe8bd4800) {
123100
// add sp, sp, #offs
124101
// -> pop {r11, lr}
125102
fp = ((uintptr_t *)sp)[0];
126103
pc = ((uintptr_t *)sp)[1];
127104
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_TIME, duration);
133-
}
134105
return true;
135106
}
136107
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_TIME, duration);
142-
}
143108
return true;
144109
}
145110

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

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

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

7269
bool StackFrame::unwindStub(instruction_t *entry, const char *name,
7370
uintptr_t &pc, uintptr_t &sp, uintptr_t &fp) {
74-
const u64 startTime = TSC::ticks();
7571
instruction_t *ip = (instruction_t *)pc;
7672
if (ip == entry || *ip == 0xc3 || strncmp(name, "itable", 6) == 0 ||
7773
strncmp(name, "vtable", 6) == 0 ||
7874
strcmp(name, "InlineCacheBuffer") == 0) {
7975
pc = *(uintptr_t *)sp;
8076
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_TIME, duration);
86-
}
8777
return true;
8878
} else if (entry != NULL && entry[0] == 0x55 && entry[1] == 0x8b &&
8979
entry[2] == 0xec) {
@@ -93,38 +83,19 @@ bool StackFrame::unwindStub(instruction_t *entry, const char *name,
9383
if (ip == entry + 1) {
9484
pc = ((uintptr_t *)sp)[1];
9585
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_TIME, duration);
101-
}
10286
return true;
10387
} else if (withinCurrentStack(fp)) {
10488
sp = fp + 8;
10589
fp = ((uintptr_t *)sp)[-2];
10690
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_TIME, duration);
112-
}
11391
return true;
11492
}
11593
}
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_TIME, duration);
121-
}
12294
return false;
12395
}
12496

12597
bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
12698
uintptr_t &fp) {
127-
const u64 startTime = TSC::ticks();
12899
instruction_t *ip = (instruction_t *)pc;
129100
instruction_t *entry = (instruction_t *)nm->entry();
130101
if (ip <= entry || *ip == 0xc3 // ret
@@ -133,32 +104,14 @@ bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
133104
{
134105
pc = *(uintptr_t *)sp;
135106
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_TIME, duration);
141-
}
142107
return true;
143108
} else if (*ip == 0x5d) {
144109
// pop ebp
145110
fp = ((uintptr_t *)sp)[0];
146111
pc = ((uintptr_t *)sp)[1];
147112
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_TIME, duration);
153-
}
154113
return true;
155114
}
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_TIME, duration);
161-
}
162115
return false;
163116
}
164117

0 commit comments

Comments
 (0)