Skip to content

Commit 7c13881

Browse files
jbachorikjbachorik
committed
Use single-entry for measuring unwinding costs
1 parent dbee7ff commit 7c13881

File tree

8 files changed

+26
-261
lines changed

8 files changed

+26
-261
lines changed

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

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -60,7 +60,9 @@
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, "unwinding_ticks") \
64+
X(UNWINDING_TIME_ASYNC, "unwinding_ticks_async") \
65+
X(UNWINDING_TIME_JVMTI, "unwinding_ticks_jvmti")
6466
#define X_ENUM(a, b) a,
6567
typedef enum CounterId : int {
6668
DD_COUNTER_TABLE(X_ENUM) DD_NUM_COUNTERS

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

Lines changed: 19 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>
@@ -596,6 +597,7 @@ u32 Profiler::recordJVMTISample(u64 counter, int tid, jthread thread, jint event
596597
}
597598
u32 call_trace_id = 0;
598599
if (!_omit_stacktraces) {
600+
u64 startTime = TSC::ticks();
599601
ASGCT_CallFrame *frames = _calltrace_buffer[lock_index]->_asgct_frames;
600602
jvmtiFrameInfo *jvmti_frames = _calltrace_buffer[lock_index]->_jvmti_frames;
601603

@@ -615,6 +617,11 @@ u32 Profiler::recordJVMTISample(u64 counter, int tid, jthread thread, jint event
615617
}
616618

617619
call_trace_id = _call_trace_storage.put(num_frames, frames, false, counter);
620+
u64 duration = TSC::ticks() - startTime;
621+
if (duration > 0) {
622+
Counters::increment(UNWINDING_TIME, duration);
623+
Counters::increment(UNWINDING_TIME, duration, 2); // increment the JVMTI specific counter
624+
}
618625
}
619626
if (!deferred) {
620627
_jfr.recordEvent(lock_index, tid, call_trace_id, event_type, event);
@@ -666,6 +673,7 @@ void Profiler::recordSample(void *ucontext, u64 counter, int tid,
666673
// record a null stacktrace we can skip the unwind if we've got a
667674
// call_trace_id determined to be reusable at a higher level
668675
if (!_omit_stacktraces && call_trace_id == 0) {
676+
u64 startTime = TSC::ticks();
669677
ASGCT_CallFrame *frames = _calltrace_buffer[lock_index]->_asgct_frames;
670678

671679
int num_frames = 0;
@@ -712,6 +720,11 @@ void Profiler::recordSample(void *ucontext, u64 counter, int tid,
712720
if (thread != nullptr) {
713721
thread->recordCallTraceId(call_trace_id);
714722
}
723+
u64 duration = TSC::ticks() - startTime;
724+
if (duration > 0) {
725+
Counters::increment(UNWINDING_TIME, duration);
726+
Counters::increment(UNWINDING_TIME, duration, 1); // increment the async specific counter
727+
}
715728
}
716729
_jfr.recordEvent(lock_index, tid, call_trace_id, event_type, event);
717730

@@ -1356,6 +1369,12 @@ Error Profiler::dump(const char *path, const int length) {
13561369

13571370
_thread_info.clearAll(thread_ids);
13581371
_thread_info.reportCounters();
1372+
1373+
// reset unwinding counters
1374+
Counters::set(UNWINDING_TIME, 0);
1375+
Counters::set(UNWINDING_TIME, 0, 1);
1376+
Counters::set(UNWINDING_TIME, 0, 2);
1377+
13591378
return err;
13601379
}
13611380

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

Lines changed: 4 additions & 82 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,44 +91,20 @@ 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 &&
130102
entry != NULL && entry[0] == 0xa9be57f4 && entry[1] == 0xa9015ff6) {
131-
// JDK-8189103: String.indexOf intrinsic.
132-
// Entry and exit are covered by the very first 'if', in all other cases SP is 4 words off.
133-
sp += 32;
134-
pc = link();
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_TIME, duration);
140-
}
103+
// JDK-8189103: String.indexOf intrinsic.
104+
// Entry and exit are covered by the very first 'if', in all other cases SP is 4 words off.
105+
sp += 32;
106+
pc = link();
141107
return true;
142-
}
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_TIME, duration);
148108
}
149109
return false;
150110
}
@@ -157,7 +117,6 @@ static inline bool isEntryBarrier(instruction_t *ip) {
157117

158118
bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
159119
uintptr_t &fp) {
160-
const u64 startTime = TSC::ticks();
161120
instruction_t *ip = (instruction_t *)pc;
162121
instruction_t *entry = (instruction_t *)nm->entry();
163122
if ((*ip & 0xffe07fff) == 0xa9007bfd) {
@@ -166,71 +125,34 @@ bool StackFrame::unwindCompiled(NMethod *nm, uintptr_t &pc, uintptr_t &sp,
166125
unsigned int offset = (*ip >> 12) & 0x1f8;
167126
sp += offset + 16;
168127
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_TIME, duration);
174-
}
175128
} else if (ip > entry && ip[0] == 0x910003fd && ip[-1] == 0xa9bf7bfd) {
176129
// stp x29, x30, [sp, #-16]!
177130
// mov x29, sp
178131
sp += 16;
179132
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-
}
186133
} else if (ip > entry + 3 && !nm->isFrameCompleteAt(ip) &&
187134
(isEntryBarrier(ip) || isEntryBarrier(ip + 1))) {
188135
// Frame should be complete at this point
189136
sp += nm->frameSize() * sizeof(void *);
190137
fp = ((uintptr_t *)sp)[-2];
191138
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_TIME, duration);
197-
}
198139
} else {
199140
// Just try
200141
pc = link();
201142
}
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_TIME, duration);
207-
}
208143
return true;
209144
}
210145

211146
bool StackFrame::unwindAtomicStub(const void*& pc) {
212147
// VM threads may call generated atomic stubs, which are not normally walkable
213-
const u64 startTime = TSC::ticks();
214148
const void* lr = (const void*)link();
215149
if (VMStructs::libjvm()->contains(lr)) {
216150
NMethod* nm = CodeHeap::findNMethod(pc);
217151
if (nm != NULL && strncmp(nm->name(), "Stub", 4) == 0) {
218152
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_TIME, duration);
224-
}
225153
return true;
226154
}
227155
}
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_TIME, duration);
233-
}
234156
return false;
235157
}
236158

‎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

0 commit comments

Comments
 (0)