eventlog: Dump cost centre stack on each samplewip/ccs-sample-events

With this change it is possible to reconstruct the timing portion of a
`.prof` file after the fact. By logging the stacks at each time point
a more precise executation trace of the program can be observed rather
than all identical cost centres being identified in the report.

There are two new events:

1. `EVENT_PROF_BEGIN` - emitted at the start of profiling to communicate
the tick interval
2. `EVENT_PROF_SAMPLE_COST_CENTRE` - emitted on each tick to communicate the
current call stack.

Fixes #17322

10 files changed, 129 insertions, 14 deletions

diff --git a/docs/users_guide/8.10.1-notes.rst b/docs/users_guide/8.10.1-notes.rst
index 7566f3f019..1dea59a063 100644
--- a/docs/users_guide/8.10.1-notes.rst
+++ b/docs/users_guide/8.10.1-notes.rst
@@ -144,6 +144,9 @@ Compiler
   the sample start event contains a timestamp of when the census occurred.
   The retainer profiling events are emitted using the standard events.
 
+- The eventlog now logs the cost centre stack on each sample. This enables
+  the `.prof` file to be partially reconstructed from the eventlog.
+
 - Add new flag :ghc-flag:`-fkeep-going` which makes the compiler
   continue as far as it can despite errors.
 
diff --git a/docs/users_guide/eventlog-formats.rst b/docs/users_guide/eventlog-formats.rst
index 27bd37cd3f..a3ed47fc3c 100644
--- a/docs/users_guide/eventlog-formats.rst
+++ b/docs/users_guide/eventlog-formats.rst
@@ -134,3 +134,33 @@ A variable-length event encoding a heap sample broken down by,
    * ``Word8``: Profile ID
    * ``Word64``: heap residency in bytes
    * ``String``: type or closure description, or module name
+
+.. _time-profiler-events:
+
+Time profiler event log output
+------------------------------
+
+The time profiling mode enabled by ``-p`` also emits sample events to the eventlog.
+At the start of profiling the tick interval is emitted to the eventlog and then
+on each tick the current cost centre stack is emitted. Together these enable
+a user to construct an approximate track of the executation of their program.
+
+Profile begin event
+^^^^^^^^^^^^^^^^^^^
+
+ * ``EVENT_PROF_BEGIN``
+
+   * ``Word64``: Tick interval, in nanoseconds
+
+
+Tick sample event
+^^^^^^^^^^^^^^^^^^
+
+A variable-length packet encoding a profile sample.
+
+* ``EVENT_PROF_SAMPLE_COST_CENTRE``
+
+  * ``Word32``: Capability
+  * ``Word64``: Current profiling tick
+  * ``Word8``: stack depth
+  * ``Word32[]``: cost centre stack starting with inner-most (cost centre numbers)
diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h
index ad983e70b3..7b989b014b 100644
--- a/includes/rts/EventLogFormat.h
+++ b/includes/rts/EventLogFormat.h
@@ -180,6 +180,8 @@
 #define EVENT_HEAP_PROF_SAMPLE_STRING      164
 #define EVENT_HEAP_PROF_SAMPLE_END         165
 #define EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN   166
+#define EVENT_PROF_SAMPLE_COST_CENTRE      167
+#define EVENT_PROF_BEGIN                   168
 
 #define EVENT_USER_BINARY_MSG              181
 
diff --git a/rts/ProfHeap.c b/rts/ProfHeap.c
index 77e0e6962a..c35b4bae4e 100644
--- a/rts/ProfHeap.c
+++ b/rts/ProfHeap.c
@@ -341,18 +341,6 @@ printSample(bool beginSample, StgDouble sampleValue)
     }
 }
 
-static void
-dumpCostCentresToEventLog(void)
-{
-#if defined(PROFILING)
-    CostCentre *cc, *next;
-    for (cc = CC_LIST; cc != NULL; cc = next) {
-        next = cc->link;
-        traceHeapProfCostCentre(cc->ccID, cc->label, cc->module,
-                                cc->srcloc, cc->is_caf);
-    }
-#endif
-}
 
 void freeHeapProfiling (void)
 {
@@ -466,7 +454,6 @@ initHeapProfiling(void)
 #endif
 
     traceHeapProfBegin(0);
-    dumpCostCentresToEventLog();
 }
 
 void
diff --git a/rts/Profiling.c b/rts/Profiling.c
index b91129ed98..a4247c7809 100644
--- a/rts/Profiling.c
+++ b/rts/Profiling.c
@@ -25,7 +25,7 @@
 #include <fs_rts.h>
 #include <string.h>
 
-#if defined(DEBUG)
+#if defined(DEBUG) || defined(PROFILING)
 #include "Trace.h"
 #endif
 
@@ -132,6 +132,19 @@ static  void              initProfilingLogFile ( void );
    Initialise the profiling environment
    -------------------------------------------------------------------------- */
 
+static void
+dumpCostCentresToEventLog(void)
+{
+#if defined(PROFILING)
+    CostCentre *cc, *next;
+    for (cc = CC_LIST; cc != NULL; cc = next) {
+        next = cc->link;
+        traceHeapProfCostCentre(cc->ccID, cc->label, cc->module,
+                                cc->srcloc, cc->is_caf);
+    }
+#endif
+}
+
 void initProfiling (void)
 {
     // initialise our arena
@@ -187,8 +200,12 @@ void initProfiling (void)
     if (RtsFlags.CcFlags.doCostCentres) {
         initTimeProfiling();
     }
+
+    dumpCostCentresToEventLog();
 }
 
+
+
 //
 // Should be called after loading any new Haskell code.
 //
@@ -278,6 +295,7 @@ initProfilingLogFile(void)
 void
 initTimeProfiling(void)
 {
+    traceProfBegin();
     /* Start ticking */
     startProfTimer();
 };
diff --git a/rts/Proftimer.c b/rts/Proftimer.c
index eb4a932cdb..68a73a5446 100644
--- a/rts/Proftimer.c
+++ b/rts/Proftimer.c
@@ -12,6 +12,7 @@
 #include "Profiling.h"
 #include "Proftimer.h"
 #include "Capability.h"
+#include "Trace.h"
 
 #if defined(PROFILING)
 static bool do_prof_ticks = false;       // enable profiling ticks
@@ -77,6 +78,7 @@ handleProfTick(void)
         uint32_t n;
         for (n=0; n < n_capabilities; n++) {
             capabilities[n]->r.rCCCS->time_ticks++;
+            traceProfSampleCostCentre(capabilities[n], capabilities[n]->r.rCCCS, total_ticks);
         }
     }
 #endif
diff --git a/rts/Trace.c b/rts/Trace.c
index de647f762b..c8a951a510 100644
--- a/rts/Trace.c
+++ b/rts/Trace.c
@@ -656,6 +656,7 @@ void traceHeapProfCostCentre(StgWord32 ccID,
     }
 }
 
+// This one is for .hp samples
 void traceHeapProfSampleCostCentre(StgWord8 profile_id,
                                    CostCentreStack *stack, StgWord residency)
 {
@@ -663,6 +664,21 @@ void traceHeapProfSampleCostCentre(StgWord8 profile_id,
         postHeapProfSampleCostCentre(profile_id, stack, residency);
     }
 }
+
+// This one is for .prof samples
+void traceProfSampleCostCentre(Capability *cap,
+                               CostCentreStack *stack, StgWord tick)
+{
+    if (eventlog_enabled) {
+        postProfSampleCostCentre(cap, stack, tick);
+    }
+}
+void traceProfBegin(void)
+{
+    if (eventlog_enabled) {
+        postProfBegin();
+    }
+}
 #endif
 
 #if defined(DEBUG)
diff --git a/rts/Trace.h b/rts/Trace.h
index d3bb226000..b7db0ca912 100644
--- a/rts/Trace.h
+++ b/rts/Trace.h
@@ -301,6 +301,10 @@ void traceHeapProfCostCentre(StgWord32 ccID,
                              StgBool is_caf);
 void traceHeapProfSampleCostCentre(StgWord8 profile_id,
                                    CostCentreStack *stack, StgWord residency);
+
+void traceProfSampleCostCentre(Capability *cap,
+                               CostCentreStack *stack, StgWord ticks);
+void traceProfBegin(void);
 #endif /* PROFILING */
 
 void flushTrace(void);
diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c
index 5c6a1ca48a..6d7b487152 100644
--- a/rts/eventlog/EventLog.c
+++ b/rts/eventlog/EventLog.c
@@ -107,6 +107,8 @@ char *EventDesc[] = {
   [EVENT_HEAP_PROF_SAMPLE_END]    = "End of heap profile sample",
   [EVENT_HEAP_PROF_SAMPLE_STRING] = "Heap profile string sample",
   [EVENT_HEAP_PROF_SAMPLE_COST_CENTRE] = "Heap profile cost-centre sample",
+  [EVENT_PROF_SAMPLE_COST_CENTRE] = "Time profile cost-centre stack",
+  [EVENT_PROF_BEGIN] = "Start of a time profile",
   [EVENT_USER_BINARY_MSG]     = "User binary message"
 };
 
@@ -442,6 +444,14 @@ init_event_types(void)
             eventTypes[t].size = EVENT_SIZE_DYNAMIC;
             break;
 
+        case EVENT_PROF_SAMPLE_COST_CENTRE:
+            eventTypes[t].size = EVENT_SIZE_DYNAMIC;
+            break;
+
+        case EVENT_PROF_BEGIN:
+            eventTypes[t].size = 8;
+            break;
+
         case EVENT_USER_BINARY_MSG:
             eventTypes[t].size = EVENT_SIZE_DYNAMIC;
             break;
@@ -1312,6 +1322,44 @@ void postHeapProfSampleCostCentre(StgWord8 profile_id,
         postWord32(&eventBuf, ccs->cc->ccID);
     RELEASE_LOCK(&eventBufMutex);
 }
+
+
+void postProfSampleCostCentre(Capability *cap,
+                              CostCentreStack *stack,
+                              StgWord64 tick)
+{
+    ACQUIRE_LOCK(&eventBufMutex);
+    StgWord depth = 0;
+    CostCentreStack *ccs;
+    for (ccs = stack; ccs != NULL && ccs != CCS_MAIN; ccs = ccs->prevStack)
+        depth++;
+    if (depth > 0xff) depth = 0xff;
+
+    StgWord len = 4+8+1+depth*4;
+    ensureRoomForVariableEvent(&eventBuf, len);
+    postEventHeader(&eventBuf, EVENT_PROF_SAMPLE_COST_CENTRE);
+    postPayloadSize(&eventBuf, len);
+    postWord32(&eventBuf, cap->no);
+    postWord64(&eventBuf, tick);
+    postWord8(&eventBuf, depth);
+    for (ccs = stack;
+         depth>0 && ccs != NULL && ccs != CCS_MAIN;
+         ccs = ccs->prevStack, depth--)
+        postWord32(&eventBuf, ccs->cc->ccID);
+    RELEASE_LOCK(&eventBufMutex);
+}
+
+// This event is output at the start of profiling so the tick interval can
+// be reported. Once the tick interval is reported the total executation time
+// can be calculuated from how many samples there are.
+void postProfBegin(void)
+{
+    ACQUIRE_LOCK(&eventBufMutex);
+    postEventHeader(&eventBuf, EVENT_PROF_BEGIN);
+    // The interval that each tick was sampled, in nanoseconds
+    postWord64(&eventBuf, TimeToNS(RtsFlags.MiscFlags.tickInterval));
+    RELEASE_LOCK(&eventBufMutex);
+}
 #endif /* PROFILING */
 
 void printAndClearEventBuf (EventsBuf *ebuf)
diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h
index d8a614b45c..ec9a5f34e3 100644
--- a/rts/eventlog/EventLog.h
+++ b/rts/eventlog/EventLog.h
@@ -157,6 +157,11 @@ void postHeapProfCostCentre(StgWord32 ccID,
 void postHeapProfSampleCostCentre(StgWord8 profile_id,
                                   CostCentreStack *stack,
                                   StgWord64 residency);
+
+void postProfSampleCostCentre(Capability *cap,
+                              CostCentreStack *stack,
+                              StgWord64 ticks);
+void postProfBegin(void);
 #endif /* PROFILING */
 
 #else /* !TRACING */