#884: Record event timestamps early

src/allocTracer.cpp

@@ -6,6 +6,7 @@
 #include "allocTracer.h"
 #include "profiler.h"
 #include "stackFrame.h"
+#include "tsc.h"
 #include "vmStructs.h"
 
 
@@ -55,6 +56,7 @@ void AllocTracer::trapHandler(int signo, siginfo_t* siginfo, void* ucontext) {
 void AllocTracer::recordAllocation(void* ucontext, EventType event_type, uintptr_t rklass,
                                    uintptr_t total_size, uintptr_t instance_size) {
     AllocEvent event;
+    event._start_time = TSC::ticks();
     event._class_id = 0;
     event._total_size = total_size;
     event._instance_size = instance_size;

src/cpuEngine.cpp

@@ -7,9 +7,9 @@
 #include <pthread.h>
 #include "cpuEngine.h"
 #include "j9StackTraces.h"
-#include "os.h"
 #include "profiler.h"
 #include "stackWalker.h"
+#include "tsc.h"
 #include "vmStructs.h"
 
 
@@ -112,7 +112,7 @@ int CpuEngine::createForAllThreads() {
 void CpuEngine::signalHandler(int signo, siginfo_t* siginfo, void* ucontext) {
     if (!_enabled) return;
 
-    ExecutionEvent event;
+    ExecutionEvent event(TSC::ticks());
     Profiler::instance()->recordSample(ucontext, _interval, EXECUTION_SAMPLE, &event);
 }
 

src/event.h

@@ -24,39 +24,39 @@ enum EventType {
 };
 
 class Event {
+};
+
+class EventWithClassId : public Event {
   public:
-    u32 id() {
-        return *(u32*)this;
-    }
+    u32 _class_id;
 };
 
 class ExecutionEvent : public Event {
   public:
+    u64 _start_time;
     ThreadState _thread_state;
 
-    ExecutionEvent() : _thread_state(THREAD_UNKNOWN) {
-    }
+    ExecutionEvent(u64 start_time) : _start_time(start_time), _thread_state(THREAD_UNKNOWN) {}
 };
 
-class AllocEvent : public Event {
+class AllocEvent : public EventWithClassId {
   public:
-    u32 _class_id;
+    u64 _start_time;
     u64 _total_size;
     u64 _instance_size;
 };
 
-class LockEvent : public Event {
+class LockEvent : public EventWithClassId {
   public:
-    u32 _class_id;
     u64 _start_time;
     u64 _end_time;
     uintptr_t _address;
     long long _timeout;
 };
 
-class LiveObject : public Event {
+class LiveObject : public EventWithClassId {
   public:
-    u32 _class_id;
+    u64 _start_time;
     u64 _alloc_size;
     u64 _alloc_time;
 };

src/flightRecorder.cpp

@@ -1146,7 +1146,7 @@ class Recording {
     void recordExecutionSample(Buffer* buf, int tid, u32 call_trace_id, ExecutionEvent* event) {
         int start = buf->skip(1);
         buf->put8(T_EXECUTION_SAMPLE);
-        buf->putVar64(TSC::ticks());
+        buf->putVar64(event->_start_time);
         buf->putVar32(tid);
         buf->putVar32(call_trace_id);
         buf->putVar32(event->_thread_state);
@@ -1156,7 +1156,7 @@ class Recording {
     void recordAllocationInNewTLAB(Buffer* buf, int tid, u32 call_trace_id, AllocEvent* event) {
         int start = buf->skip(1);
         buf->put8(T_ALLOC_IN_NEW_TLAB);
-        buf->putVar64(TSC::ticks());
+        buf->putVar64(event->_start_time);
         buf->putVar32(tid);
         buf->putVar32(call_trace_id);
         buf->putVar32(event->_class_id);
@@ -1168,7 +1168,7 @@ class Recording {
     void recordAllocationOutsideTLAB(Buffer* buf, int tid, u32 call_trace_id, AllocEvent* event) {
         int start = buf->skip(1);
         buf->put8(T_ALLOC_OUTSIDE_TLAB);
-        buf->putVar64(TSC::ticks());
+        buf->putVar64(event->_start_time);
         buf->putVar32(tid);
         buf->putVar32(call_trace_id);
         buf->putVar32(event->_class_id);
@@ -1179,7 +1179,7 @@ class Recording {
     void recordLiveObject(Buffer* buf, int tid, u32 call_trace_id, LiveObject* event) {
         int start = buf->skip(1);
         buf->put8(T_LIVE_OBJECT);
-        buf->putVar64(TSC::ticks());
+        buf->putVar64(event->_start_time);
         buf->putVar32(tid);
         buf->putVar32(call_trace_id);
         buf->putVar32(event->_class_id);

src/instrument.cpp

@@ -8,8 +8,8 @@
 #include <string.h>
 #include "arch.h"
 #include "incbin.h"
-#include "os.h"
 #include "profiler.h"
+#include "tsc.h"
 #include "vmEntry.h"
 #include "instrument.h"
 
@@ -607,7 +607,7 @@ void JNICALL Instrument::recordSample(JNIEnv* jni, jobject unused) {
     if (!_enabled) return;
 
     if (_interval <= 1 || ((atomicInc(_calls) + 1) % _interval) == 0) {
-        ExecutionEvent event;
+        ExecutionEvent event(TSC::ticks());
         Profiler::instance()->recordSample(NULL, _interval, INSTRUMENTED_METHOD, &event);
     }
 }

src/j9StackTraces.cpp

@@ -13,6 +13,7 @@
 #include "j9Ext.h"
 #include "profiler.h"
 #include "perfEvents.h"
+#include "tsc.h"
 
 
 enum {
@@ -101,6 +102,7 @@ void J9StackTraces::timerLoop() {
         ssize_t ptr = 0;
         while (ptr < bytes) {
             J9StackTraceNotification* notif = (J9StackTraceNotification*)(notification_buf + ptr);
+            u64 start_time = TSC::ticks();
 
             jthread thread = known_threads[notif->env];
             jint num_jvmti_frames;
@@ -133,7 +135,7 @@ void J9StackTraces::timerLoop() {
             }
 
             int tid = J9Ext::GetOSThreadID(thread);
-            ExecutionEvent event;
+            ExecutionEvent event(start_time);
             Profiler::instance()->recordExternalSample(notif->counter, tid, EXECUTION_SAMPLE, &event, num_frames, frames);
 
             ptr += notif->size();

src/j9WallClock.cpp

@@ -7,6 +7,7 @@
 #include "j9WallClock.h"
 #include "j9Ext.h"
 #include "profiler.h"
+#include "tsc.h"
 
 
 long J9WallClock::_interval;
@@ -48,6 +49,7 @@ void J9WallClock::timerLoop() {
         jvmtiStackInfoExtended* stack_infos;
         jint thread_count;
         if (J9Ext::GetAllStackTracesExtended(_max_stack_depth, (void**)&stack_infos, &thread_count) == 0) {
+            u64 start_time = TSC::ticks();
             for (int i = 0; i < thread_count; i++) {
                 jvmtiStackInfoExtended* si = &stack_infos[i];
                 for (int j = 0; j < si->frame_count; j++) {
@@ -57,7 +59,7 @@ void J9WallClock::timerLoop() {
                 }
 
                 int tid = J9Ext::GetOSThreadID(si->thread);
-                ExecutionEvent event;
+                ExecutionEvent event(start_time);
                 event._thread_state = (si->state & JVMTI_THREAD_STATE_RUNNABLE) ? THREAD_RUNNING : THREAD_SLEEPING;
                 Profiler::instance()->recordExternalSample(_interval, tid, EXECUTION_SAMPLE, &event, si->frame_count, frames);
             }

src/objectSampler.cpp

@@ -108,6 +108,7 @@ class LiveRefs {
                 jobject obj = jni->NewLocalRef(w);
                 if (obj != NULL) {
                     LiveObject event;
+                    event._start_time = TSC::ticks();
                     event._alloc_size = _values[i].size;
                     event._alloc_time = _values[i].time;
                     event._class_id = lookupClassId(jvmti, jni->GetObjectClass(obj));
@@ -141,6 +142,7 @@ void ObjectSampler::GarbageCollectionStart(jvmtiEnv* jvmti) {
 void ObjectSampler::recordAllocation(jvmtiEnv* jvmti, JNIEnv* jni, EventType event_type,
                                      jobject object, jclass object_klass, jlong size) {
     AllocEvent event;
+    event._start_time = TSC::ticks();
     event._total_size = size > _interval ? size : _interval;
     event._instance_size = size;
     event._class_id = lookupClassId(jvmti, object_klass);

src/perfEvents_linux.cpp

@@ -24,13 +24,13 @@
 #include "fdtransferClient.h"
 #include "j9StackTraces.h"
 #include "log.h"
-#include "os.h"
 #include "perfEvents.h"
 #include "profiler.h"
 #include "spinLock.h"
 #include "stackFrame.h"
 #include "stackWalker.h"
 #include "symbols.h"
+#include "tsc.h"
 #include "vmStructs.h"
 
 
@@ -659,8 +659,8 @@ void PerfEvents::signalHandler(int signo, siginfo_t* siginfo, void* ucontext) {
     }
 
     if (_enabled) {
+        ExecutionEvent event(TSC::ticks());
         u64 counter = readCounter(siginfo, ucontext);
-        ExecutionEvent event;
         Profiler::instance()->recordSample(ucontext, counter, PERF_SAMPLE, &event);
     } else {
         resetBuffer(OS::threadId());

src/profiler.cpp

@@ -637,10 +637,13 @@ u64 Profiler::recordSample(void* ucontext, u64 counter, EventType event_type, Ev
     jvmtiFrameInfo* jvmti_frames = _calltrace_buffer[lock_index]->_jvmti_frames;
 
     int num_frames = 0;
-    if (_add_event_frame && event_type >= ALLOC_SAMPLE && event->id()) {
-        // Convert event_type to frame_type, e.g. ALLOC_SAMPLE -> BCI_ALLOC
-        jint frame_type = BCI_ALLOC - (event_type - ALLOC_SAMPLE);
-        num_frames = makeFrame(frames, frame_type, event->id());
+    if (_add_event_frame && event_type >= ALLOC_SAMPLE && event_type <= PARK_SAMPLE) {
+        u32 class_id = ((EventWithClassId*)event)->_class_id;
+        if (class_id != 0) {
+            // Convert event_type to frame_type, e.g. ALLOC_SAMPLE -> BCI_ALLOC
+            jint frame_type = BCI_ALLOC - (event_type - ALLOC_SAMPLE);
+            num_frames = makeFrame(frames, frame_type, class_id);
+        }
     }
 
     StackContext java_ctx = {0};

src/wallClock.cpp

@@ -9,6 +9,7 @@
 #include "wallClock.h"
 #include "profiler.h"
 #include "stackFrame.h"
+#include "tsc.h"
 
 
 // Maximum number of threads sampled in one iteration. This limit serves as a throttle
@@ -48,7 +49,7 @@ ThreadState WallClock::getThreadState(void* ucontext) {
 }
 
 void WallClock::signalHandler(int signo, siginfo_t* siginfo, void* ucontext) {
-    ExecutionEvent event;
+    ExecutionEvent event(TSC::ticks());
     event._thread_state = _sample_idle_threads ? getThreadState(ucontext) : THREAD_UNKNOWN;
     Profiler::instance()->recordSample(ucontext, _interval, EXECUTION_SAMPLE, &event);
 }