eventlog: Add biographical and retainer profiling traces

This patch adds a new eventlog event which indicates the start of
a biographical profiler sample. These are different to normal events as
they also include the timestamp of when the census took place. This is
because the LDV profiler only emits samples at the end of the run.

Now all the different profiling modes emit consumable events to the
eventlog.

10 files changed, 83 insertions, 5 deletions

diff --git a/docs/users_guide/8.10.1-notes.rst b/docs/users_guide/8.10.1-notes.rst
index 786ea117ce..f0cd9006ad 100644
--- a/docs/users_guide/8.10.1-notes.rst
+++ b/docs/users_guide/8.10.1-notes.rst
@@ -114,6 +114,11 @@ Compiler
   only convenient workaround was to enable `-fobject-code` for all
   modules.
 
+- The eventlog now contains events for biographical and retainer profiling.
+  The biographical profiling events all appear at the end of the eventlog but
+  the sample start event contains a timestamp of when the census occurred.
+  The retainer profiling events are emitted using the standard events.
+
 GHCi
 ~~~~
 
diff --git a/docs/users_guide/eventlog-formats.rst b/docs/users_guide/eventlog-formats.rst
index 0590fc65db..27bd37cd3f 100644
--- a/docs/users_guide/eventlog-formats.rst
+++ b/docs/users_guide/eventlog-formats.rst
@@ -72,13 +72,25 @@ Sample event types
 A sample (consisting of a list of break-down classes, e.g. cost centres, and
 heap residency sizes), is to be encoded in the body of one or more events.
 
-We mark the beginning of a new sample with an ``EVENT_HEAP_PROF_SAMPLE_BEGIN``
+We normally mark the beginning of a new sample with an ``EVENT_HEAP_PROF_SAMPLE_BEGIN``
 event,
 
  * ``EVENT_HEAP_PROF_SAMPLE_BEGIN``
 
    * ``Word64``: sample number
 
+Biographical profiling samples start with the ``EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN``
+event. These events also include a timestamp which indicates when the sample
+was taken. This is because all these samples will appear at the end of
+the eventlog due to how the biographical profiling mode works. You can
+use the timestamp to reorder the samples relative to the other events.
+
+ * ``EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN``
+
+   * ``Word64``: sample number
+   * ``Word64``: eventlog timestamp in ns
+
+
 A heap residency census will follow. Since events may only be up to 2^16^ bytes
 in length a single sample may need to be split among multiple
 ``EVENT_HEAP_PROF_SAMPLE`` events. The precise format of the census entries is
diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h
index 462e036d90..ad983e70b3 100644
--- a/includes/rts/EventLogFormat.h
+++ b/includes/rts/EventLogFormat.h
@@ -179,6 +179,7 @@
 #define EVENT_HEAP_PROF_SAMPLE_COST_CENTRE 163
 #define EVENT_HEAP_PROF_SAMPLE_STRING      164
 #define EVENT_HEAP_PROF_SAMPLE_END         165
+#define EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN   166
 
 #define EVENT_USER_BINARY_MSG              181
 
diff --git a/rts/ProfHeap.c b/rts/ProfHeap.c
index cc99e37fdc..55541f70cc 100644
--- a/rts/ProfHeap.c
+++ b/rts/ProfHeap.c
@@ -81,6 +81,10 @@ initLDVCtr( counter *ctr )
 
 typedef struct {
     double      time;    // the time in MUT time when the census is made
+    StgWord64   rtime;   // The eventlog time the census was made. This is used
+                         // for the LDV profiling events because they are all
+                         // emitted at the end of compilation so we need to know
+                         // when the sample actually took place.
     HashTable * hash;
     counter   * ctrs;
     Arena     * arena;
@@ -769,9 +773,18 @@ dumpCensus( Census *census )
     ssize_t count;
 
     printSample(true, census->time);
-    traceHeapProfSampleBegin(era);
+
+
+    if (RtsFlags.ProfFlags.doHeapProfile == HEAP_BY_LDV) {
+      traceHeapBioProfSampleBegin(era, census->rtime);
+    } else {
+      traceHeapProfSampleBegin(era);
+    }
+
+
 
 #if defined(PROFILING)
+
     /* change typecast to uint64_t to remove
      * print formatting warning. See #12636 */
     if (RtsFlags.ProfFlags.doHeapProfile == HEAP_BY_LDV) {
@@ -788,6 +801,23 @@ dumpCensus( Census *census )
                 (uint64_t)(census->prim * sizeof(W_)));
         fprintf(hp_file, "DRAG\t%" FMT_Word64 "\n",
                 (uint64_t)(census->drag_total * sizeof(W_)));
+
+
+        // Eventlog
+        traceHeapProfSampleString(0, "VOID",
+                (census->void_total * sizeof(W_)));
+        traceHeapProfSampleString(0, "LAG",
+                ((census->not_used - census->void_total) *
+                                     sizeof(W_)));
+        traceHeapProfSampleString(0, "USE",
+                ((census->used - census->drag_total) *
+                                     sizeof(W_)));
+        traceHeapProfSampleString(0, "INHERENT_USE",
+                (census->prim * sizeof(W_)));
+        traceHeapProfSampleString(0, "DRAG",
+                (census->drag_total * sizeof(W_)));
+
+        traceHeapProfSampleEnd(era);
         printSample(false, census->time);
         return;
     }
@@ -856,7 +886,8 @@ dumpCensus( Census *census )
                 rs->id = -(rs->id);
 
             // report in the unit of bytes: * sizeof(StgWord)
-            printRetainerSetShort(hp_file, rs, RtsFlags.ProfFlags.ccsLength);
+            printRetainerSetShort(hp_file, rs, (W_)count * sizeof(W_)
+                                             , RtsFlags.ProfFlags.ccsLength);
             break;
         }
 #endif
@@ -1156,6 +1187,8 @@ void heapCensus (Time t)
 
   census = &censuses[era];
   census->time  = mut_user_time_until(t);
+  census->rtime = TimeToNS(stat_getElapsedTime());
+
 
   // calculate retainer sets if necessary
 #if defined(PROFILING)
diff --git a/rts/RetainerSet.c b/rts/RetainerSet.c
index 59103ddf61..634035b0d0 100644
--- a/rts/RetainerSet.c
+++ b/rts/RetainerSet.c
@@ -17,6 +17,7 @@
 #include "RetainerSet.h"
 #include "Arena.h"
 #include "Profiling.h"
+#include "Trace.h"
 
 #include <string.h>
 
@@ -230,7 +231,7 @@ printRetainer(FILE *f, retainer ccs)
  * -------------------------------------------------------------------------- */
 #if defined(SECOND_APPROACH)
 void
-printRetainerSetShort(FILE *f, RetainerSet *rs, uint32_t max_length)
+printRetainerSetShort(FILE *f, RetainerSet *rs, W_ total_size, uint32_t max_length)
 {
     char tmp[max_length + 1];
     uint32_t size;
@@ -262,6 +263,7 @@ printRetainerSetShort(FILE *f, RetainerSet *rs, uint32_t max_length)
         }
     }
     fputs(tmp, f);
+    traceHeapProfSampleString(0, tmp, total_size);
 }
 #endif /* SECOND_APPROACH */
 
diff --git a/rts/RetainerSet.h b/rts/RetainerSet.h
index 2f9aeea644..44ec519c68 100644
--- a/rts/RetainerSet.h
+++ b/rts/RetainerSet.h
@@ -140,7 +140,7 @@ RetainerSet *addElement(retainer, RetainerSet *);
 
 #if defined(SECOND_APPROACH)
 // Prints a single retainer set.
-void printRetainerSetShort(FILE *, RetainerSet *, uint32_t);
+void printRetainerSetShort(FILE *, RetainerSet *, W_, uint32_t);
 #endif
 
 // Print the statistics on all the retainer sets.
diff --git a/rts/Trace.c b/rts/Trace.c
index d5c4319076..de647f762b 100644
--- a/rts/Trace.c
+++ b/rts/Trace.c
@@ -615,6 +615,12 @@ void traceHeapProfBegin(StgWord8 profile_id)
         postHeapProfBegin(profile_id);
     }
 }
+void traceHeapBioProfSampleBegin(StgInt era, StgWord64 time)
+{
+    if (eventlog_enabled) {
+        postHeapBioProfSampleBegin(era, time);
+    }
+}
 
 void traceHeapProfSampleBegin(StgInt era)
 {
diff --git a/rts/Trace.h b/rts/Trace.h
index 17e3dc7040..9985adc52f 100644
--- a/rts/Trace.h
+++ b/rts/Trace.h
@@ -288,6 +288,7 @@ void traceTaskDelete_ (Task       *task);
 
 void traceHeapProfBegin(StgWord8 profile_id);
 void traceHeapProfSampleBegin(StgInt era);
+void traceHeapBioProfSampleBegin(StgInt era, StgWord64 time);
 void traceHeapProfSampleEnd(StgInt era);
 void traceHeapProfSampleString(StgWord8 profile_id,
                                const char *label, StgWord residency);
@@ -336,6 +337,7 @@ void flushTrace(void);
 #define traceHeapProfBegin(profile_id) /* nothing */
 #define traceHeapProfCostCentre(ccID, label, module, srcloc, is_caf) /* nothing */
 #define traceHeapProfSampleBegin(era) /* nothing */
+#define traceHeapBioProfSampleBegin(era, time) /* nothing */
 #define traceHeapProfSampleEnd(era) /* nothing */
 #define traceHeapProfSampleCostCentre(profile_id, stack, residency) /* nothing */
 #define traceHeapProfSampleString(profile_id, label, residency) /* nothing */
diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c
index 0651de268c..5c6a1ca48a 100644
--- a/rts/eventlog/EventLog.c
+++ b/rts/eventlog/EventLog.c
@@ -103,6 +103,7 @@ char *EventDesc[] = {
   [EVENT_HEAP_PROF_BEGIN]     = "Start of heap profile",
   [EVENT_HEAP_PROF_COST_CENTRE]   = "Cost center definition",
   [EVENT_HEAP_PROF_SAMPLE_BEGIN]  = "Start of heap profile sample",
+  [EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN]  = "Start of heap profile (biographical) sample",
   [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",
@@ -425,6 +426,10 @@ init_event_types(void)
             eventTypes[t].size = 8;
             break;
 
+        case EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN:
+            eventTypes[t].size = 16;
+            break;
+
         case EVENT_HEAP_PROF_SAMPLE_END:
             eventTypes[t].size = 8;
             break;
@@ -1224,6 +1229,17 @@ void postHeapProfSampleBegin(StgInt era)
     RELEASE_LOCK(&eventBufMutex);
 }
 
+
+void postHeapBioProfSampleBegin(StgInt era, StgWord64 time)
+{
+    ACQUIRE_LOCK(&eventBufMutex);
+    ensureRoomForEvent(&eventBuf, EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN);
+    postEventHeader(&eventBuf, EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN);
+    postWord64(&eventBuf, era);
+    postWord64(&eventBuf, time);
+    RELEASE_LOCK(&eventBufMutex);
+}
+
 void postHeapProfSampleEnd(StgInt era)
 {
     ACQUIRE_LOCK(&eventBufMutex);
diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h
index 8935e61985..d8a614b45c 100644
--- a/rts/eventlog/EventLog.h
+++ b/rts/eventlog/EventLog.h
@@ -140,6 +140,7 @@ void postTaskDeleteEvent (EventTaskId taskId);
 void postHeapProfBegin(StgWord8 profile_id);
 
 void postHeapProfSampleBegin(StgInt era);
+void postHeapBioProfSampleBegin(StgInt era, StgWord64 time_ns);
 void postHeapProfSampleEnd(StgInt era);
 
 void postHeapProfSampleString(StgWord8 profile_id,