Event tracer (-o trace)

src/arguments.cpp

@@ -87,6 +87,8 @@ Error Arguments::parse(const char* args) {
                 return Error("event must not be empty");
             }
             _event = value;
+        } else if (strcmp(arg, "trace") == 0) {
+            _trace = true;
         } else if (strcmp(arg, "collapsed") == 0 || strcmp(arg, "folded") == 0) {
             _dump_collapsed = true;
             _counter = value == NULL || strcmp(value, "samples") == 0 ? COUNTER_SAMPLES : COUNTER_TOTAL;

src/arguments.h

@@ -89,6 +89,7 @@ class Arguments {
     bool _simple;
     bool _annotate;
     char* _file;
+    bool _trace;
     bool _dump_collapsed;
     bool _dump_flamegraph;
     bool _dump_tree;
@@ -115,6 +116,7 @@ class Arguments {
         _simple(false),
         _annotate(false),
         _file(NULL),
+        _trace(false),
         _dump_collapsed(false),
         _dump_flamegraph(false),
         _dump_tree(false),

src/profiler.cpp

@@ -376,6 +376,7 @@ void Profiler::recordSample(void* ucontext, u64 counter, jint event_type, jmetho
     if (num_frames > 0) {
         storeMethod(frames[0].method_id, frames[0].bci, counter);
         int call_trace_id = storeCallTrace(num_frames, frames, counter);
+        _tracer.recordExecutionSample(tid, call_trace_id, counter);
         _jfr.recordExecutionSample(lock_index, tid, call_trace_id);
     }
 
@@ -508,7 +509,12 @@ Error Profiler::start(Arguments& args) {
     VMStructs::init(libjvm);
     initJvmtiFunctions(libjvm);
 
-    if (args._dump_jfr) {
+    if (args._trace) {
+        Error error = _tracer.start(args);
+        if (error) {
+            return error;
+        }
+    } else if (args._dump_jfr) {
         Error error = _jfr.start(args._file);
         if (error) {
             return error;
@@ -518,6 +524,7 @@ Error Profiler::start(Arguments& args) {
     _engine = selectEngine(args._event);
     Error error = _engine->start(args);
     if (error) {
+        _tracer.stop();
         _jfr.stop();
         return error;
     }
@@ -542,6 +549,7 @@ Error Profiler::stop() {
 
     // Acquire all spinlocks to avoid race with remaining signals
     for (int i = 0; i < CONCURRENCY_LEVEL; i++) _locks[i].lock();
+    _tracer.stop();
     _jfr.stop();
     for (int i = 0; i < CONCURRENCY_LEVEL; i++) _locks[i].unlock();
 
@@ -793,7 +801,7 @@ void Profiler::runInternal(Arguments& args, std::ostream& out) {
 }
 
 void Profiler::run(Arguments& args) {
-    if (args._file == NULL || args._dump_jfr) {
+    if (args._file == NULL || args._trace || args._dump_jfr) {
         runInternal(args, std::cout);
     } else {
         std::ofstream out(args._file, std::ios::out | std::ios::trunc);

src/profiler.h

@@ -27,6 +27,7 @@
 #include "mutex.h"
 #include "spinLock.h"
 #include "codeCache.h"
+#include "tracer.h"
 #include "vmEntry.h"
 
 
@@ -53,33 +54,26 @@ union CallTraceBuffer {
 
 
 class CallTraceSample {
-  private:
+  public:
     u64 _samples;
     u64 _counter;
     int _start_frame; // Offset in frame buffer
     int _num_frames;
 
-  public:
     static int comparator(const void* s1, const void* s2) {
         return cmp64(((CallTraceSample*)s2)->_counter, ((CallTraceSample*)s1)->_counter);
     }
-
-    friend class Profiler;
-    friend class Recording;
 };
 
 class MethodSample {
-  private:
+  public:
     u64 _samples;
     u64 _counter;
     ASGCT_CallFrame _method;
 
-  public:
     static int comparator(const void* s1, const void* s2) {
         return cmp64(((MethodSample*)s2)->_counter, ((MethodSample*)s1)->_counter);
     }
-
-    friend class Profiler;
 };
 
 
@@ -113,6 +107,7 @@ class Profiler {
     State _state;
     Mutex _thread_names_lock;
     std::map<int, std::string> _thread_names;
+    Tracer _tracer;
     FlightRecorder _jfr;
     Engine* _engine;
     time_t _start_time;
@@ -175,6 +170,7 @@ class Profiler {
 
     Profiler() :
         _state(IDLE),
+        _tracer(),
         _jfr(),
         _frame_buffer(NULL),
         _thread_events_state(JVMTI_DISABLE),
@@ -236,6 +232,7 @@ class Profiler {
     }
 
     friend class Recording;
+    friend class Tracer;
 };
 
 #endif // _PROFILER_H

src/tracer.cpp

@@ -0,0 +1,127 @@
+/*
+ * Copyright 2018 Andrei Pangin
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <set>
+#include <errno.h>
+#include <unistd.h>
+#include "tracer.h"
+#include "frameName.h"
+#include "os.h"
+#include "profiler.h"
+#include "vmEntry.h"
+
+
+struct TracerEvent {
+    u64 timestamp;
+    int tid;
+    int call_trace_id;
+    u64 counter;
+};
+
+
+Error Tracer::start(Arguments& args) {
+    if (args._file == NULL || args._file[0] == 0) {
+        return Error("Tracer output file is not specified");
+    }
+
+    _out = fopen(args._file, "w");
+    if (_out == NULL) {
+        return Error("Cannot open Tracer output file");
+    }
+
+    if (pipe(_pipefd) != 0) {
+        fclose(_out);
+        return Error("Unable to create poll pipe");
+    }
+
+    _simple = args._simple;
+    _annotate = args._annotate;
+
+    if (pthread_create(&_thread, NULL, threadEntry, this) != 0) {
+        close(_pipefd[1]);
+        close(_pipefd[0]);
+        fclose(_out);
+        return Error("Unable to create tracer thread");
+    }
+
+    _running = true;
+    return Error::OK;
+}
+
+void Tracer::stop() {
+    if (_running) {
+        close(_pipefd[1]);
+        pthread_join(_thread, NULL);
+        close(_pipefd[0]);
+        fclose(_out);
+        _running = false;
+    }
+}
+
+void Tracer::recordExecutionSample(int tid, int call_trace_id, u64 counter) {
+    if (_running && tid != _tracer_tid && call_trace_id != 0) {
+        TracerEvent event;
+        event.timestamp = OS::millis();
+        event.tid = tid;
+        event.call_trace_id = call_trace_id;
+        event.counter = counter;
+
+        ssize_t result = write(_pipefd[1], &event, sizeof(event));
+        (void)result;
+    }
+}
+
+void Tracer::tracerLoop() {
+    _tracer_tid = OS::threadId();
+    TracerEvent event_buf[256];
+    std::set<int> written_traces;
+
+    void* env;
+    JavaVMAttachArgs attach_args = {JNI_VERSION_1_6, (char*)"async-profiler tracer", NULL};
+    VM::vm()->AttachCurrentThreadAsDaemon(&env, &attach_args);
+
+    FrameName fn(_simple, _annotate, false,
+                 Profiler::_instance._thread_names_lock, Profiler::_instance._thread_names);
+
+    while (true) {
+        ssize_t bytes = read(_pipefd[0], event_buf, sizeof(event_buf));
+        if (bytes == 0 || (bytes < 0 && errno != EINTR)) {
+            break;
+        }
+
+        for (TracerEvent* event = event_buf; (bytes -= sizeof(TracerEvent)) >= 0; event++) {
+            int call_trace_id = event->call_trace_id;
+            if (written_traces.insert(call_trace_id).second) {
+                // The stacktrace with this id was not yet written
+                CallTraceSample* trace = &Profiler::_instance._traces[call_trace_id];
+                ASGCT_CallFrame* frame_buffer = &Profiler::_instance._frame_buffer[trace->_start_frame];
+
+                fprintf(_out, "[stacktrace] id=%d ", call_trace_id);
+                for (int i = trace->_num_frames - 1; i >= 0; i--) {
+                    const char* frame_name = fn.name(frame_buffer[i]);
+                    fprintf(_out, (i == 0 ? "%s" : "%s;"), frame_name);
+                }
+                fprintf(_out, "\n");
+            }
+
+            fprintf(_out, "[event] time=%llu thread=%d stacktrace=%d counter=%llu\n",
+                    event->timestamp, event->tid, event->call_trace_id, event->counter);
+            fflush(_out);
+        }
+    }
+
+    VM::vm()->DetachCurrentThread();
+}

src/tracer.h

@@ -0,0 +1,53 @@
+/*
+ * Copyright 2018 Andrei Pangin
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef _TRACER_H
+#define _TRACER_H
+
+#include <pthread.h>
+#include <stdio.h>
+#include "arch.h"
+#include "arguments.h"
+
+
+class Tracer {
+  private:
+    FILE* _out;
+    int _pipefd[2];
+    pthread_t _thread;
+    volatile int _tracer_tid;
+    bool _simple;
+    bool _annotate;
+    bool _running;
+
+    void tracerLoop();
+
+    static void* threadEntry(void* tracer) {
+        ((Tracer*)tracer)->tracerLoop();
+        return NULL;
+    }
+
+  public:
+    Tracer() : _running(false) {
+    }
+
+    Error start(Arguments& args);
+    void stop();
+
+    void recordExecutionSample(int tid, int call_trace_id, u64 counter);
+};
+
+#endif // _TRACER_H

src/vmEntry.h

@@ -55,6 +55,10 @@ class VM {
 
     static void init(JavaVM* vm, bool attach);
 
+    static JavaVM* vm() {
+        return _vm;
+    }
+
     static jvmtiEnv* jvmti() {
         return _jvmti;
     }