eventlog: Add biographical and retainer profiling traces
authorMatthew Pickering <matthewtpickering@gmail.com>
Tue, 2 Jul 2019 09:38:13 +0000 (10:38 +0100)
committerMarge Bot <ben+marge-bot@smart-cactus.org>
Tue, 17 Sep 2019 23:21:10 +0000 (19:21 -0400)
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.

docs/users_guide/8.10.1-notes.rst
docs/users_guide/eventlog-formats.rst
includes/rts/EventLogFormat.h
rts/ProfHeap.c
rts/RetainerSet.c
rts/RetainerSet.h
rts/Trace.c
rts/Trace.h
rts/eventlog/EventLog.c
rts/eventlog/EventLog.h

index 786ea11..f0cd900 100644 (file)
@@ -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
 ~~~~
 
index 0590fc6..27bd37c 100644 (file)
@@ -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
index 462e036..ad983e7 100644 (file)
 #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
 
index cc99e37..55541f7 100644 (file)
@@ -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)
index 59103dd..634035b 100644 (file)
@@ -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 */
 
index 2f9aeea..44ec519 100644 (file)
@@ -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.
index d5c4319..de647f7 100644 (file)
@@ -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)
 {
index 17e3dc7..9985adc 100644 (file)
@@ -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 */
index 0651de2..5c6a1ca 100644 (file)
@@ -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);
index 8935e61..d8a614b 100644 (file)
@@ -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,