Skip to content

Commit 8b2fd87

Browse files
author
Andrei Pangin
authored
#49: Ability to start profiler together with JVM and dump profile on exit
1 parent 5887145 commit 8b2fd87

7 files changed

Lines changed: 93 additions & 84 deletions

File tree

‎profiler.sh‎

Lines changed: 27 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -27,8 +27,25 @@ usage() {
2727
exit 1
2828
}
2929

30+
mirror_output() {
31+
# Mirror output from temporary file to local terminal
32+
if [[ $USE_TMP ]]; then
33+
if [[ -f $FILE ]]; then
34+
cat $FILE
35+
rm $FILE
36+
fi
37+
fi
38+
}
39+
40+
check_if_terminated() {
41+
if ! kill -0 $PID 2> /dev/null; then
42+
mirror_output
43+
exit 0
44+
fi
45+
}
46+
3047
jattach() {
31-
$JATTACH $PID load $PROFILER true $1 > /dev/null
48+
$JATTACH $PID load "$PROFILER" true $1 > /dev/null
3249
RET=$?
3350

3451
# Check if jattach failed
@@ -37,21 +54,15 @@ jattach() {
3754
echo "Failed to inject profiler into $PID"
3855
UNAME_S=$(uname -s)
3956
if [ "$UNAME_S" == "Darwin" ]; then
40-
otool -L $PROFILER
57+
otool -L "$PROFILER"
4158
else
42-
ldd $PROFILER
59+
ldd "$PROFILER"
4360
fi
4461
fi
4562
exit $RET
4663
fi
4764

48-
# Duplicate output from temporary file to local terminal
49-
if [[ $USE_TMP ]]; then
50-
if [[ -f $FILE ]]; then
51-
cat $FILE
52-
rm $FILE
53-
fi
54-
fi
65+
mirror_output
5566
}
5667

5768
function abspath() {
@@ -139,7 +150,7 @@ fi
139150

140151
case $ACTION in
141152
start)
142-
jattach start,event=$EVENT,file=$FILE$INTERVAL$FRAMEBUF$THREADS
153+
jattach start,event=$EVENT,file=$FILE$INTERVAL$FRAMEBUF$THREADS,$OUTPUT
143154
;;
144155
stop)
145156
jattach stop,file=$FILE,$OUTPUT
@@ -151,8 +162,11 @@ case $ACTION in
151162
jattach list,file=$FILE
152163
;;
153164
collect)
154-
jattach start,event=$EVENT,file=$FILE$INTERVAL$FRAMEBUF$THREADS
155-
sleep $DURATION
165+
jattach start,event=$EVENT,file=$FILE$INTERVAL$FRAMEBUF$THREADS,$OUTPUT
166+
while (( DURATION-- > 0 )); do
167+
check_if_terminated
168+
sleep 1
169+
done
156170
jattach stop,file=$FILE,$OUTPUT
157171
;;
158172
esac

‎src/arguments.cpp‎

Lines changed: 9 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -46,10 +46,13 @@ const Error Error::OK(NULL);
4646
//
4747
// It is possible to specify multiple dump options at the same time
4848

49-
Error Arguments::parse(char* args) {
50-
if (strlen(args) >= sizeof(_buf)) {
49+
Error Arguments::parse(const char* args) {
50+
if (args == NULL) {
51+
return Error::OK;
52+
} else if (strlen(args) >= sizeof(_buf)) {
5153
return Error("Argument list too long");
5254
}
55+
5356
strcpy(_buf, args);
5457

5558
for (char* arg = strtok(_buf, ","); arg != NULL; arg = strtok(NULL, ",")) {
@@ -70,17 +73,13 @@ Error Arguments::parse(char* args) {
7073
}
7174
_event = value;
7275
} else if (strcmp(arg, "collapsed") == 0 || strcmp(arg, "folded") == 0) {
73-
_action = ACTION_DUMP;
7476
_dump_collapsed = true;
7577
_counter = value == NULL || strcmp(value, "samples") == 0 ? COUNTER_SAMPLES : COUNTER_TOTAL;
7678
} else if (strcmp(arg, "summary") == 0) {
77-
_action = ACTION_DUMP;
7879
_dump_summary = true;
7980
} else if (strcmp(arg, "traces") == 0) {
80-
_action = ACTION_DUMP;
8181
_dump_traces = value == NULL ? INT_MAX : atoi(value);
8282
} else if (strcmp(arg, "flat") == 0) {
83-
_action = ACTION_DUMP;
8483
_dump_flat = value == NULL ? INT_MAX : atoi(value);
8584
} else if (strcmp(arg, "interval") == 0) {
8685
if (value == NULL || (_interval = atol(value)) <= 0) {
@@ -100,5 +99,9 @@ Error Arguments::parse(char* args) {
10099
}
101100
}
102101

102+
if (dumpRequested() && (_action == ACTION_NONE || _action == ACTION_STOP)) {
103+
_action = ACTION_DUMP;
104+
}
105+
103106
return Error::OK;
104107
}

‎src/arguments.h‎

Lines changed: 5 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -49,9 +49,6 @@ class Error {
4949
public:
5050
static const Error OK;
5151

52-
Error() {
53-
}
54-
5552
explicit Error(const char* message) : _message(message) {
5653
}
5754

@@ -68,9 +65,6 @@ class Error {
6865
class Arguments {
6966
private:
7067
char _buf[1024];
71-
Error _error;
72-
73-
Error parse(char* args);
7468

7569
public:
7670
Action _action;
@@ -85,7 +79,7 @@ class Arguments {
8579
int _dump_traces;
8680
int _dump_flat;
8781

88-
Arguments(char* args) :
82+
Arguments() :
8983
_action(ACTION_NONE),
9084
_counter(COUNTER_SAMPLES),
9185
_event(EVENT_CPU),
@@ -97,12 +91,13 @@ class Arguments {
9791
_dump_summary(false),
9892
_dump_traces(0),
9993
_dump_flat(0) {
100-
_error = parse(args);
10194
}
10295

103-
Error error() {
104-
return _error;
96+
bool dumpRequested() {
97+
return _dump_collapsed || _dump_summary || _dump_traces > 0 || _dump_flat > 0;
10598
}
99+
100+
Error parse(const char* args);
106101
};
107102

108103
#endif // _ARGUMENTS_H

‎src/profiler.cpp‎

Lines changed: 23 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -247,21 +247,6 @@ int Profiler::getJavaTraceAsync(void* ucontext, ASGCT_CallFrame* frames, int max
247247
return 0;
248248
}
249249

250-
int Profiler::getJavaTraceJVMTI(jvmtiFrameInfo* jvmti_frames, ASGCT_CallFrame* frames, int max_depth) {
251-
jint num_frames;
252-
if (VM::jvmti()->GetStackTrace(NULL, 0, max_depth, jvmti_frames, &num_frames) == 0 && num_frames > 0) {
253-
// Profiler expects stack trace in AsyncGetCallTrace format; convert it now
254-
for (int i = 0; i < num_frames; i++) {
255-
frames[i].method_id = jvmti_frames[i].method;
256-
frames[i].bci = 0;
257-
}
258-
return num_frames;
259-
}
260-
261-
atomicInc(_failures[-ticks_no_Java_frame]);
262-
return 0;
263-
}
264-
265250
int Profiler::makeEventFrame(ASGCT_CallFrame* frames, jint event_type, jmethodID event) {
266251
frames[0].bci = event_type;
267252
frames[0].method_id = event;
@@ -298,19 +283,12 @@ void Profiler::recordSample(void* ucontext, u64 counter, jint event_type, jmetho
298283

299284
atomicInc(_total_counter, counter);
300285

301-
ASGCT_CallFrame* frames = _calltrace_buffer[lock_index]._asgct_frames;
302-
int num_frames;
286+
ASGCT_CallFrame* frames = _calltrace_buffer[lock_index];
303287
int tid = PerfEvents::tid();
304288

305-
if (event == NULL) {
306-
num_frames = getNativeTrace(tid, frames);
307-
num_frames += getJavaTraceAsync(ucontext, frames + num_frames, MAX_STACK_FRAMES - 1 - num_frames);
308-
} else {
309-
// Events like object allocation happen at known places where it is safe to call JVM TI
310-
jvmtiFrameInfo* jvmti_frames = _calltrace_buffer[lock_index]._jvmti_frames;
311-
num_frames = makeEventFrame(frames, event_type, event);
312-
num_frames += getJavaTraceJVMTI(jvmti_frames + num_frames, frames + num_frames, MAX_STACK_FRAMES - 1 - num_frames);
313-
}
289+
int num_frames = event != NULL ? makeEventFrame(frames, event_type, event) : 0;
290+
num_frames += getNativeTrace(tid, frames);
291+
num_frames += getJavaTraceAsync(ucontext, frames + num_frames, MAX_STACK_FRAMES - 1 - num_frames);
314292

315293
if (_threads) {
316294
num_frames += makeEventFrame(frames + num_frames, BCI_THREAD_ID, (jmethodID)(uintptr_t)tid);
@@ -324,6 +302,13 @@ void Profiler::recordSample(void* ucontext, u64 counter, jint event_type, jmetho
324302
_locks[lock_index].unlock();
325303
}
326304

305+
void Profiler::initStateLock() {
306+
pthread_mutexattr_t attr;
307+
pthread_mutexattr_init(&attr);
308+
pthread_mutexattr_settype(&attr, PTHREAD_MUTEX_RECURSIVE);
309+
pthread_mutex_init(&_state_lock, &attr);
310+
}
311+
327312
void Profiler::resetSymbols() {
328313
for (int i = 0; i < _native_lib_count; i++) {
329314
delete _native_libs[i];
@@ -585,3 +570,15 @@ void Profiler::run(Arguments& args) {
585570
}
586571
}
587572
}
573+
574+
void Profiler::shutdown(Arguments& args) {
575+
MutexLocker ml(_state_lock);
576+
577+
// The last chance to dump profile before VM terminates
578+
if (_state == RUNNING && args.dumpRequested()) {
579+
args._action = ACTION_DUMP;
580+
run(args);
581+
}
582+
583+
_state = TERMINATED;
584+
}

‎src/profiler.h‎

Lines changed: 4 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -40,12 +40,6 @@ static inline int cmp64(u64 a, u64 b) {
4040
}
4141

4242

43-
union CallTraceBuffer {
44-
ASGCT_CallFrame _asgct_frames[MAX_STACK_FRAMES];
45-
jvmtiFrameInfo _jvmti_frames[MAX_STACK_FRAMES];
46-
};
47-
48-
4943
class CallTraceSample {
5044
private:
5145
u64 _samples;
@@ -130,7 +124,7 @@ class Profiler {
130124
MethodSample _methods[MAX_CALLTRACES];
131125

132126
SpinLock _locks[CONCURRENCY_LEVEL];
133-
CallTraceBuffer _calltrace_buffer[CONCURRENCY_LEVEL];
127+
ASGCT_CallFrame _calltrace_buffer[CONCURRENCY_LEVEL][MAX_STACK_FRAMES];
134128
ASGCT_CallFrame* _frame_buffer;
135129
int _frame_buffer_size;
136130
volatile int _frame_buffer_index;
@@ -153,14 +147,14 @@ class Profiler {
153147
const char* findNativeMethod(const void* address);
154148
int getNativeTrace(int tid, ASGCT_CallFrame* frames);
155149
int getJavaTraceAsync(void* ucontext, ASGCT_CallFrame* frames, int max_depth);
156-
int getJavaTraceJVMTI(jvmtiFrameInfo* jvmti_frames, ASGCT_CallFrame* frames, int max_depth);
157150
int makeEventFrame(ASGCT_CallFrame* frames, jint event_type, jmethodID event);
158151
bool fillTopFrame(const void* pc, ASGCT_CallFrame* frame);
159152
u64 hashCallTrace(int num_frames, ASGCT_CallFrame* frames);
160153
void storeCallTrace(int num_frames, ASGCT_CallFrame* frames, u64 counter);
161154
void copyToFrameBuffer(int num_frames, ASGCT_CallFrame* frames, CallTraceSample* trace);
162155
u64 hashMethod(jmethodID method);
163156
void storeMethod(jmethodID method, jint bci, u64 counter);
157+
void initStateLock();
164158
void resetSymbols();
165159
void setSignalHandler();
166160
void runInternal(Arguments& args, std::ostream& out);
@@ -177,14 +171,15 @@ class Profiler {
177171
_java_methods(),
178172
_runtime_stubs("[stubs]"),
179173
_native_lib_count(0) {
180-
pthread_mutex_init(&_state_lock, NULL);
174+
initStateLock();
181175
}
182176

183177
u64 total_samples() { return _total_samples; }
184178
u64 total_counter() { return _total_counter; }
185179
time_t uptime() { return time(NULL) - _start_time; }
186180

187181
void run(Arguments& args);
182+
void shutdown(Arguments& args);
188183
Error start(const char* event, long interval, int frame_buffer_size, bool threads);
189184
Error stop();
190185
void dumpSummary(std::ostream& out);
@@ -194,11 +189,6 @@ class Profiler {
194189
void recordSample(void* ucontext, u64 counter, jint event_type, jmethodID event);
195190
NativeCodeCache* jvmLibrary();
196191

197-
static void JNICALL VMDeath(jvmtiEnv* jvmti, JNIEnv* jni) {
198-
MutexLocker ml(_instance._state_lock);
199-
_instance._state = TERMINATED;
200-
}
201-
202192
// CompiledMethodLoad is also needed to enable DebugNonSafepoints info by default
203193
static void JNICALL CompiledMethodLoad(jvmtiEnv* jvmti, jmethodID method,
204194
jint code_size, const void* code_addr,

‎src/vmEntry.cpp‎

Lines changed: 23 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,8 @@
2323
#include "lockTracer.h"
2424

2525

26+
static Arguments _agent_args;
27+
2628
JavaVM* VM::_vm;
2729
jvmtiEnv* VM::_jvmti = NULL;
2830
AsyncGetCallTrace VM::_asyncGetCallTrace;
@@ -47,7 +49,7 @@ void VM::init(JavaVM* vm, bool attach) {
4749

4850
jvmtiEventCallbacks callbacks = {0};
4951
callbacks.VMInit = VMInit;
50-
callbacks.VMDeath = Profiler::VMDeath;
52+
callbacks.VMDeath = VMDeath;
5153
callbacks.ClassLoad = ClassLoad;
5254
callbacks.ClassPrepare = ClassPrepare;
5355
callbacks.CompiledMethodLoad = Profiler::CompiledMethodLoad;
@@ -71,13 +73,13 @@ void VM::init(JavaVM* vm, bool attach) {
7173

7274
_asyncGetCallTrace = (AsyncGetCallTrace)dlsym(RTLD_DEFAULT, "AsyncGetCallTrace");
7375
if (_asyncGetCallTrace == NULL) {
74-
// Unable to locate AsyncGetCallTrace, it is likely that JVM has been started
75-
// by JNI_CreateJavaVM() via dynamically loaded libjvm.so from a C/C++ program
76+
// Unable to locate AsyncGetCallTrace, it is likely that JVM has been started
77+
// by JNI_CreateJavaVM() via dynamically loaded libjvm.so from a C/C++ program
7678
void* libjvm_handle = dlopen("libjvm.so", RTLD_NOW);
7779
if (!libjvm_handle) {
7880
std::cerr << "Failed to load libjvm.so: " << dlerror() << std::endl;
7981
}
80-
// Try loading AGCT after opening libjvm.so
82+
// Try loading AGCT after opening libjvm.so
8183
_asyncGetCallTrace = (AsyncGetCallTrace)dlsym(libjvm_handle, "AsyncGetCallTrace");
8284
}
8385

@@ -107,32 +109,41 @@ void VM::loadAllMethodIDs(jvmtiEnv* jvmti) {
107109
}
108110
}
109111

112+
void JNICALL VM::VMInit(jvmtiEnv* jvmti, JNIEnv* jni, jthread thread) {
113+
loadAllMethodIDs(jvmti);
114+
// Delayed start of profiler if agent has been loaded at VM bootstrap
115+
Profiler::_instance.run(_agent_args);
116+
}
117+
118+
void JNICALL VM::VMDeath(jvmtiEnv* jvmti, JNIEnv* jni) {
119+
Profiler::_instance.shutdown(_agent_args);
120+
}
121+
110122

111123
extern "C" JNIEXPORT jint JNICALL
112124
Agent_OnLoad(JavaVM* vm, char* options, void* reserved) {
113125
VM::init(vm, false);
114126

115-
Arguments args(options);
116-
if (args.error()) {
117-
std::cerr << args.error().message() << std::endl;
127+
Error error = _agent_args.parse(options);
128+
if (error) {
129+
std::cerr << error.message() << std::endl;
118130
return -1;
119131
}
120132

121-
Profiler::_instance.run(args);
122133
return 0;
123134
}
124135

125136
extern "C" JNIEXPORT jint JNICALL
126137
Agent_OnAttach(JavaVM* vm, char* options, void* reserved) {
127138
VM::init(vm, true);
128139

129-
Arguments args(options);
130-
if (args.error()) {
131-
std::cerr << args.error().message() << std::endl;
140+
Error error = _agent_args.parse(options);
141+
if (error) {
142+
std::cerr << error.message() << std::endl;
132143
return -1;
133144
}
134145

135-
Profiler::_instance.run(args);
146+
Profiler::_instance.run(_agent_args);
136147
return 0;
137148
}
138149

0 commit comments

Comments
 (0)