Add new eventlog EVENT_WALL_CLOCK_TIME for time matching

Eventlog timestamps are elapsed times (in nanoseconds) relative to the
process start. To be able to merge eventlogs from multiple processes we
need to be able to align their timelines. If they share a clock domain
(or a user judges that their clocks are sufficiently closely
synchronised) then it is sufficient to know how the eventlog timestamps
match up with the clock.

The EVENT_WALL_CLOCK_TIME contains the clock time with (up to)
nanosecond precision. It is otherwise an ordinary event and so contains
the usual timestamp for the same moment in time. It therefore enables
us to match up all the eventlog timestamps with clock time.

5 files changed, 73 insertions, 2 deletions

diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h
index 925aec4ed1..7773bae6a9 100644
--- a/includes/rts/EventLogFormat.h
+++ b/includes/rts/EventLogFormat.h
@@ -141,9 +141,10 @@
 #define EVENT_SPARK_FIZZLE        40 /* ()                     */
 #define EVENT_SPARK_GC            41 /* ()                     */
 #define EVENT_INTERN_STRING       42 /* (string, id) {not used by ghc} */
+#define EVENT_WALL_CLOCK_TIME     43 /* (capset, unix_epoch_seconds, nanoseconds) */
 
 
-/* Range 43 - 59 is available for new GHC and common events */
+/* Range 44 - 59 is available for new GHC and common events */
 
 /* Range 60 - 80 is used by eden for parallel tracing
  * see http://www.mathematik.uni-marburg.de/~eden/
@@ -156,7 +157,7 @@
  * ranges higher than this are reserved but not currently emitted by ghc.
  * This must match the size of the EventDesc[] array in EventLog.c
  */
-#define NUM_GHC_EVENT_TAGS        42
+#define NUM_GHC_EVENT_TAGS        44
 
 #if 0  /* DEPRECATED EVENTS: */
 /* we don't actually need to record the thread, it's implicit */
diff --git a/rts/Trace.c b/rts/Trace.c
index 7aa0f7b444..9d29f2a8fa 100644
--- a/rts/Trace.c
+++ b/rts/Trace.c
@@ -328,6 +328,12 @@ void traceCapsetEvent_ (EventTypeNum tag,
     }
 }
 
+void traceWallClockTime_(void) {
+    if (eventlog_enabled) {
+        postWallClockTime(CAPSET_CLOCKDOMAIN_DEFAULT);
+    }
+}
+
 void traceOSProcessInfo_(void) {
     if (eventlog_enabled) {
         postCapsetEvent(EVENT_OSPROCESS_PID,
diff --git a/rts/Trace.h b/rts/Trace.h
index 7143a5b221..f7894ca994 100644
--- a/rts/Trace.h
+++ b/rts/Trace.h
@@ -37,6 +37,7 @@ enum CapsetType { CapsetTypeCustom = CAPSET_TYPE_CUSTOM,
                   CapsetTypeOsProcess = CAPSET_TYPE_OSPROCESS,
                   CapsetTypeClockdomain = CAPSET_TYPE_CLOCKDOMAIN };
 #define CAPSET_OSPROCESS_DEFAULT 0
+#define CAPSET_CLOCKDOMAIN_DEFAULT 1
 
 // -----------------------------------------------------------------------------
 // Message classes
@@ -199,6 +200,8 @@ void traceCapsetEvent_ (EventTypeNum tag,
                         CapsetID capset,
                         StgWord info);
 
+void traceWallClockTime_(void);
+
 void traceOSProcessInfo_ (void);
 
 void traceSparkCounters_ (Capability *cap,
@@ -219,6 +222,7 @@ void traceSparkCounters_ (Capability *cap,
 #define traceThreadStatus(class, tso) /* nothing */
 INLINE_HEADER void traceEventStartup_ (int n_caps STG_UNUSED) {};
 #define traceCapsetEvent_(tag, capset, info) /* nothing */
+#define traceWallClockTime_() /* nothing */
 #define traceOSProcessInfo_() /* nothing */
 #define traceSparkCounters_(cap, counters, remaining) /* nothing */
 
@@ -492,6 +496,12 @@ INLINE_HEADER void traceCapsetRemoveCap(CapsetID capset STG_UNUSED,
     dtraceCapsetRemoveCap(capset, capno);
 }
 
+INLINE_HEADER void traceWallClockTime(void)
+{
+    traceWallClockTime_();
+    /* Note: no DTrace equivalent because it is available to DTrace directly */
+}
+
 INLINE_HEADER void traceOSProcessInfo(void)
 {
     traceOSProcessInfo_();
diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c
index d5bfd19130..09e12a2fa3 100644
--- a/rts/eventlog/EventLog.c
+++ b/rts/eventlog/EventLog.c
@@ -83,6 +83,7 @@ char *EventDesc[] = {
   [EVENT_PROGRAM_ENV]         = "Program environment variables",
   [EVENT_OSPROCESS_PID]       = "Process ID",
   [EVENT_OSPROCESS_PPID]      = "Parent process ID",
+  [EVENT_WALL_CLOCK_TIME]     = "Wall clock time",
   [EVENT_SPARK_COUNTERS]      = "Spark counters",
   [EVENT_SPARK_CREATE]        = "Spark create",
   [EVENT_SPARK_DUD]           = "Spark dud",
@@ -299,6 +300,11 @@ initEventLogging(void)
                 sizeof(EventCapsetID) + sizeof(StgWord32);
             break;
 
+        case EVENT_WALL_CLOCK_TIME: // (capset, unix_epoch_seconds, nanoseconds)
+            eventTypes[t].size =
+                sizeof(EventCapsetID) + sizeof(StgWord64) + sizeof(StgWord32);
+            break;
+
         case EVENT_SPARK_STEAL:     // (cap, victim_cap)
             eventTypes[t].size =
                 sizeof(EventCapNo);
@@ -668,6 +674,52 @@ void postCapsetVecEvent (EventTypeNum tag,
     RELEASE_LOCK(&eventBufMutex);
 }
 
+void postWallClockTime (EventCapsetID capset)
+{
+    StgWord64 ts;
+    StgWord64 sec;
+    StgWord32 nsec;
+
+    ACQUIRE_LOCK(&eventBufMutex);
+    
+    /* The EVENT_WALL_CLOCK_TIME event is intended to allow programs
+       reading the eventlog to match up the event timestamps with wall
+       clock time. The normal event timestamps measure time since the
+       start of the program. To align eventlogs from concurrent
+       processes we need to be able to match up the timestamps. One way
+       to do this is if we know how the timestamps and wall clock time
+       match up (and of course if both processes have sufficiently
+       synchronised clocks).
+
+       So we want to make sure that the timestamp that we generate for
+       this event matches up very closely with the wall clock time.
+       Unfortunately we currently have to use two different APIs to get
+       the elapsed time vs the wall clock time. So to minimise the
+       difference we just call them very close together.
+     */
+    
+    getUnixEpochTime(&sec, &nsec);  /* Get the wall clock time */
+    ts = time_ns();                 /* Get the eventlog timestamp */
+
+    if (!hasRoomForEvent(&eventBuf, EVENT_WALL_CLOCK_TIME)) {
+        // Flush event buffer to make room for new event.
+        printAndClearEventBuf(&eventBuf);
+    }
+
+    /* Normally we'd call postEventHeader(), but that generates its own
+       timestamp, so we go one level lower so we can write out the
+       timestamp we already generated above. */
+    postEventTypeNum(&eventBuf, EVENT_WALL_CLOCK_TIME);
+    postWord64(&eventBuf, ts);
+    
+    /* EVENT_WALL_CLOCK_TIME (capset, unix_epoch_seconds, nanoseconds) */
+    postCapsetID(&eventBuf, capset);
+    postWord64(&eventBuf, sec);
+    postWord32(&eventBuf, nsec);
+
+    RELEASE_LOCK(&eventBufMutex);
+}
+
 void
 postEvent (Capability *cap, EventTypeNum tag)
 {
diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h
index e09da07e6b..d7368c30bf 100644
--- a/rts/eventlog/EventLog.h
+++ b/rts/eventlog/EventLog.h
@@ -69,6 +69,8 @@ void postCapsetVecEvent (EventTypeNum tag,
                          int argc,
                          char *msg[]);
 
+void postWallClockTime (EventCapsetID capset);
+
 /* 
  * Post a `par` spark event
  */