Commit ae4415b9 authored by Matthew Pickering's avatar Matthew Pickering Committed by Marge Bot

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.
parent 7915afc6
...@@ -114,6 +114,11 @@ Compiler ...@@ -114,6 +114,11 @@ Compiler
only convenient workaround was to enable `-fobject-code` for all only convenient workaround was to enable `-fobject-code` for all
modules. 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 GHCi
~~~~ ~~~~
......
...@@ -72,13 +72,25 @@ Sample event types ...@@ -72,13 +72,25 @@ Sample event types
A sample (consisting of a list of break-down classes, e.g. cost centres, and 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. 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,
* ``EVENT_HEAP_PROF_SAMPLE_BEGIN`` * ``EVENT_HEAP_PROF_SAMPLE_BEGIN``
* ``Word64``: sample number * ``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 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 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 ``EVENT_HEAP_PROF_SAMPLE`` events. The precise format of the census entries is
......
...@@ -179,6 +179,7 @@ ...@@ -179,6 +179,7 @@
#define EVENT_HEAP_PROF_SAMPLE_COST_CENTRE 163 #define EVENT_HEAP_PROF_SAMPLE_COST_CENTRE 163
#define EVENT_HEAP_PROF_SAMPLE_STRING 164 #define EVENT_HEAP_PROF_SAMPLE_STRING 164
#define EVENT_HEAP_PROF_SAMPLE_END 165 #define EVENT_HEAP_PROF_SAMPLE_END 165
#define EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN 166
#define EVENT_USER_BINARY_MSG 181 #define EVENT_USER_BINARY_MSG 181
......
...@@ -81,6 +81,10 @@ initLDVCtr( counter *ctr ) ...@@ -81,6 +81,10 @@ initLDVCtr( counter *ctr )
typedef struct { typedef struct {
double time; // the time in MUT time when the census is made 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; HashTable * hash;
counter * ctrs; counter * ctrs;
Arena * arena; Arena * arena;
...@@ -769,9 +773,18 @@ dumpCensus( Census *census ) ...@@ -769,9 +773,18 @@ dumpCensus( Census *census )
ssize_t count; ssize_t count;
printSample(true, census->time); printSample(true, census->time);
if (RtsFlags.ProfFlags.doHeapProfile == HEAP_BY_LDV) {
traceHeapBioProfSampleBegin(era, census->rtime);
} else {
traceHeapProfSampleBegin(era); traceHeapProfSampleBegin(era);
}
#if defined(PROFILING) #if defined(PROFILING)
/* change typecast to uint64_t to remove /* change typecast to uint64_t to remove
* print formatting warning. See #12636 */ * print formatting warning. See #12636 */
if (RtsFlags.ProfFlags.doHeapProfile == HEAP_BY_LDV) { if (RtsFlags.ProfFlags.doHeapProfile == HEAP_BY_LDV) {
...@@ -788,6 +801,23 @@ dumpCensus( Census *census ) ...@@ -788,6 +801,23 @@ dumpCensus( Census *census )
(uint64_t)(census->prim * sizeof(W_))); (uint64_t)(census->prim * sizeof(W_)));
fprintf(hp_file, "DRAG\t%" FMT_Word64 "\n", fprintf(hp_file, "DRAG\t%" FMT_Word64 "\n",
(uint64_t)(census->drag_total * sizeof(W_))); (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); printSample(false, census->time);
return; return;
} }
...@@ -856,7 +886,8 @@ dumpCensus( Census *census ) ...@@ -856,7 +886,8 @@ dumpCensus( Census *census )
rs->id = -(rs->id); rs->id = -(rs->id);
// report in the unit of bytes: * sizeof(StgWord) // 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; break;
} }
#endif #endif
...@@ -1156,6 +1187,8 @@ void heapCensus (Time t) ...@@ -1156,6 +1187,8 @@ void heapCensus (Time t)
census = &censuses[era]; census = &censuses[era];
census->time = mut_user_time_until(t); census->time = mut_user_time_until(t);
census->rtime = TimeToNS(stat_getElapsedTime());
// calculate retainer sets if necessary // calculate retainer sets if necessary
#if defined(PROFILING) #if defined(PROFILING)
......
...@@ -17,6 +17,7 @@ ...@@ -17,6 +17,7 @@
#include "RetainerSet.h" #include "RetainerSet.h"
#include "Arena.h" #include "Arena.h"
#include "Profiling.h" #include "Profiling.h"
#include "Trace.h"
#include <string.h> #include <string.h>
...@@ -230,7 +231,7 @@ printRetainer(FILE *f, retainer ccs) ...@@ -230,7 +231,7 @@ printRetainer(FILE *f, retainer ccs)
* -------------------------------------------------------------------------- */ * -------------------------------------------------------------------------- */
#if defined(SECOND_APPROACH) #if defined(SECOND_APPROACH)
void 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]; char tmp[max_length + 1];
uint32_t size; uint32_t size;
...@@ -262,6 +263,7 @@ printRetainerSetShort(FILE *f, RetainerSet *rs, uint32_t max_length) ...@@ -262,6 +263,7 @@ printRetainerSetShort(FILE *f, RetainerSet *rs, uint32_t max_length)
} }
} }
fputs(tmp, f); fputs(tmp, f);
traceHeapProfSampleString(0, tmp, total_size);
} }
#endif /* SECOND_APPROACH */ #endif /* SECOND_APPROACH */
......
...@@ -140,7 +140,7 @@ RetainerSet *addElement(retainer, RetainerSet *); ...@@ -140,7 +140,7 @@ RetainerSet *addElement(retainer, RetainerSet *);
#if defined(SECOND_APPROACH) #if defined(SECOND_APPROACH)
// Prints a single retainer set. // Prints a single retainer set.
void printRetainerSetShort(FILE *, RetainerSet *, uint32_t); void printRetainerSetShort(FILE *, RetainerSet *, W_, uint32_t);
#endif #endif
// Print the statistics on all the retainer sets. // Print the statistics on all the retainer sets.
......
...@@ -615,6 +615,12 @@ void traceHeapProfBegin(StgWord8 profile_id) ...@@ -615,6 +615,12 @@ void traceHeapProfBegin(StgWord8 profile_id)
postHeapProfBegin(profile_id); postHeapProfBegin(profile_id);
} }
} }
void traceHeapBioProfSampleBegin(StgInt era, StgWord64 time)
{
if (eventlog_enabled) {
postHeapBioProfSampleBegin(era, time);
}
}
void traceHeapProfSampleBegin(StgInt era) void traceHeapProfSampleBegin(StgInt era)
{ {
......
...@@ -288,6 +288,7 @@ void traceTaskDelete_ (Task *task); ...@@ -288,6 +288,7 @@ void traceTaskDelete_ (Task *task);
void traceHeapProfBegin(StgWord8 profile_id); void traceHeapProfBegin(StgWord8 profile_id);
void traceHeapProfSampleBegin(StgInt era); void traceHeapProfSampleBegin(StgInt era);
void traceHeapBioProfSampleBegin(StgInt era, StgWord64 time);
void traceHeapProfSampleEnd(StgInt era); void traceHeapProfSampleEnd(StgInt era);
void traceHeapProfSampleString(StgWord8 profile_id, void traceHeapProfSampleString(StgWord8 profile_id,
const char *label, StgWord residency); const char *label, StgWord residency);
...@@ -336,6 +337,7 @@ void flushTrace(void); ...@@ -336,6 +337,7 @@ void flushTrace(void);
#define traceHeapProfBegin(profile_id) /* nothing */ #define traceHeapProfBegin(profile_id) /* nothing */
#define traceHeapProfCostCentre(ccID, label, module, srcloc, is_caf) /* nothing */ #define traceHeapProfCostCentre(ccID, label, module, srcloc, is_caf) /* nothing */
#define traceHeapProfSampleBegin(era) /* nothing */ #define traceHeapProfSampleBegin(era) /* nothing */
#define traceHeapBioProfSampleBegin(era, time) /* nothing */
#define traceHeapProfSampleEnd(era) /* nothing */ #define traceHeapProfSampleEnd(era) /* nothing */
#define traceHeapProfSampleCostCentre(profile_id, stack, residency) /* nothing */ #define traceHeapProfSampleCostCentre(profile_id, stack, residency) /* nothing */
#define traceHeapProfSampleString(profile_id, label, residency) /* nothing */ #define traceHeapProfSampleString(profile_id, label, residency) /* nothing */
......
...@@ -103,6 +103,7 @@ char *EventDesc[] = { ...@@ -103,6 +103,7 @@ char *EventDesc[] = {
[EVENT_HEAP_PROF_BEGIN] = "Start of heap profile", [EVENT_HEAP_PROF_BEGIN] = "Start of heap profile",
[EVENT_HEAP_PROF_COST_CENTRE] = "Cost center definition", [EVENT_HEAP_PROF_COST_CENTRE] = "Cost center definition",
[EVENT_HEAP_PROF_SAMPLE_BEGIN] = "Start of heap profile sample", [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_END] = "End of heap profile sample",
[EVENT_HEAP_PROF_SAMPLE_STRING] = "Heap profile string sample", [EVENT_HEAP_PROF_SAMPLE_STRING] = "Heap profile string sample",
[EVENT_HEAP_PROF_SAMPLE_COST_CENTRE] = "Heap profile cost-centre sample", [EVENT_HEAP_PROF_SAMPLE_COST_CENTRE] = "Heap profile cost-centre sample",
...@@ -425,6 +426,10 @@ init_event_types(void) ...@@ -425,6 +426,10 @@ init_event_types(void)
eventTypes[t].size = 8; eventTypes[t].size = 8;
break; break;
case EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN:
eventTypes[t].size = 16;
break;
case EVENT_HEAP_PROF_SAMPLE_END: case EVENT_HEAP_PROF_SAMPLE_END:
eventTypes[t].size = 8; eventTypes[t].size = 8;
break; break;
...@@ -1224,6 +1229,17 @@ void postHeapProfSampleBegin(StgInt era) ...@@ -1224,6 +1229,17 @@ void postHeapProfSampleBegin(StgInt era)
RELEASE_LOCK(&eventBufMutex); 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) void postHeapProfSampleEnd(StgInt era)
{ {
ACQUIRE_LOCK(&eventBufMutex); ACQUIRE_LOCK(&eventBufMutex);
......
...@@ -140,6 +140,7 @@ void postTaskDeleteEvent (EventTaskId taskId); ...@@ -140,6 +140,7 @@ void postTaskDeleteEvent (EventTaskId taskId);
void postHeapProfBegin(StgWord8 profile_id); void postHeapProfBegin(StgWord8 profile_id);
void postHeapProfSampleBegin(StgInt era); void postHeapProfSampleBegin(StgInt era);
void postHeapBioProfSampleBegin(StgInt era, StgWord64 time_ns);
void postHeapProfSampleEnd(StgInt era); void postHeapProfSampleEnd(StgInt era);
void postHeapProfSampleString(StgWord8 profile_id, void postHeapProfSampleString(StgWord8 profile_id,
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment