diff options
| -rw-r--r-- | compiler/main/DynFlags.hs | 1 | ||||
| -rw-r--r-- | compiler/main/Packages.hs | 4 | ||||
| -rw-r--r-- | docs/users_guide/8.2.1-notes.rst | 4 | ||||
| -rw-r--r-- | docs/users_guide/eventlog-formats.rst | 119 | ||||
| -rw-r--r-- | docs/users_guide/index.rst | 1 | ||||
| -rw-r--r-- | docs/users_guide/profiling.rst | 24 | ||||
| -rw-r--r-- | includes/rts/Config.h | 8 | ||||
| -rw-r--r-- | includes/rts/EventLogFormat.h | 11 | ||||
| -rw-r--r-- | mk/config.mk.in | 23 | ||||
| -rw-r--r-- | mk/ways.mk | 49 | ||||
| -rw-r--r-- | rts/ProfHeap.c | 32 | ||||
| -rw-r--r-- | rts/Trace.c | 43 | ||||
| -rw-r--r-- | rts/Trace.h | 19 | ||||
| -rw-r--r-- | rts/eventlog/EventLog.c | 183 | ||||
| -rw-r--r-- | rts/eventlog/EventLog.h | 20 |
15 files changed, 501 insertions, 40 deletions
diff --git a/compiler/main/DynFlags.hs b/compiler/main/DynFlags.hs index ffb5b33689..24746d6836 100644 --- a/compiler/main/DynFlags.hs +++ b/compiler/main/DynFlags.hs @@ -1264,6 +1264,7 @@ allowed_combination way = and [ x `allowedWith` y (WayCustom {}) `allowedWith` _ = True WayThreaded `allowedWith` WayProf = True WayThreaded `allowedWith` WayEventLog = True + WayProf `allowedWith` WayEventLog = True _ `allowedWith` _ = False mkBuildTag :: [Way] -> String diff --git a/compiler/main/Packages.hs b/compiler/main/Packages.hs index 4710de1a20..ecec982422 100644 --- a/compiler/main/Packages.hs +++ b/compiler/main/Packages.hs @@ -1233,8 +1233,8 @@ packageHsLibs dflags p = map (mkDynName . addSuffix) (hsLibraries p) -- the name of a shared library is libHSfoo-ghc<version>.so -- we leave out the _dyn, because it is superfluous - -- debug RTS includes support for -eventlog - ways2 | WayDebug `elem` ways1 + -- debug and profiled RTSs include support for -eventlog + ways2 | WayDebug `elem` ways1 || WayProf `elem` ways1 = filter (/= WayEventLog) ways1 | otherwise = ways1 diff --git a/docs/users_guide/8.2.1-notes.rst b/docs/users_guide/8.2.1-notes.rst index 7b271cd054..2ae804dc56 100644 --- a/docs/users_guide/8.2.1-notes.rst +++ b/docs/users_guide/8.2.1-notes.rst @@ -56,6 +56,10 @@ Runtime system - TODO FIXME. +- The :ref:`heap profiler <prof-heap>` can now emit heap census data to the GHC + event log, allowing heap profiles to be correlated with other tracing events + (see :ghc-ticket:`11094`). + Build system ~~~~~~~~~~~~ diff --git a/docs/users_guide/eventlog-formats.rst b/docs/users_guide/eventlog-formats.rst new file mode 100644 index 0000000000..74a62f2bd3 --- /dev/null +++ b/docs/users_guide/eventlog-formats.rst @@ -0,0 +1,119 @@ +Eventlog encodings +================== + +This section documents the encodings of the events emitted to GHC's +:ref:`event log <rts-eventlog>`. These events can include information about the +thread scheduling events, garbage collection statistics, profiling information, +user-defined tracing events. + +This section is intended for implementors of tooling which consume these events. + + +.. _heap-profiler-events: + +Heap profiler event log output +------------------------------ + +The heap profiler can produce output to GHC's event log, allowing samples to +be correlated with other event log events over the program's lifecycle. + +This section defines the layout of these events. The ``String`` type below is +defined to be a UTF-8 encoded NUL-terminated string. + +Metadata event types +~~~~~~~~~~~~~~~~~~~~ + +Beginning of sample stream +^^^^^^^^^^^^^^^^^^^^^^^^^^ + +A single fixed-width event emitted during program start-up describing the samples that follow. + + * ``EVENT_HEAP_PROF_BEGIN`` + * ``Word8``: Profile ID + * ``Word64``: Sampling period in nanoseconds + * ``Word32``: Sample break-down type. One of, + * ``SAMPLE_TYPE_COST_CENTER`` (output from ``-hc``) + * ``SAMPLE_TYPE_CLOSURE_DESCR`` (output from ``-hd``) + * ``SAMPLE_TYPE_RETAINER`` (output from ``-hr``) + * ``SAMPLE_TYPE_MODULE`` (output from ``-hm``) + * ``SAMPLE_TYPE_TYPE_DESCR`` (output from ``-hy``) + * ``SAMPLE_TYPE_BIOGRAPHY`` (output from ``-hb``) + * ``String``: Cost centre filter + * ``String``: Closure description filter + * ``String``: Retainer filter + * ``String``: Module filter + * ``String``: Type description filter + +Cost center definitions +^^^^^^^^^^^^^^^^^^^^^^^ + +A variable-length packet produced once for each cost center, + + * ``EVENT_HEAP_PROF_COST_CENTRE`` + * ``Word32``: cost center number + * ``String``: label + * ``String``: module + * ``String``: source location + * ``Word8``: flags + * bit 0: is the cost-center a CAF? + + +Sample event types +~~~~~~~~~~~~~~~~~~ + +A sample (consisting of a list of break-down classes, e.g. cost centers, 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`` +event, + + * ``EVENT_HEAP_PROF_SAMPLE_BEGIN`` + * ``Word64``: sample number + +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 +determined by the break-down type. + + +Cost-center break-down +^^^^^^^^^^^^^^^^^^^^^^ + +A variable-length packet encoding a heap profile sample broken down by, + * cost-center (``-hc``) + * retainer (``-hr``) + + * ``EVENT_HEAP_PROF_SAMPLE`` + * ``Word8``: Profile ID + * ``Word64``: heap residency in bytes + * ``Word8``: stack depth + * ``Word32[]``: cost center stack starting with inner-most (cost center numbers) + + +String break-down +^^^^^^^^^^^^^^^^^ + +A variable-length event encoding a heap sample broken down by, + * type description (``-hy``) + * closure description (``-hd``) + * module (``-hm``) + + * ``EVENT_HEAP_PROF_SAMPLE`` + * ``Word8``: Profile ID + * The event shall contain packed pairs of, + * ``String``: type description + * ``Word64``: heap residency in bytes + + +Biography break-down +^^^^^^^^^^^^^^^^^^^^ + +A fixed-length event encoding a biography heap sample. + + * ``EVENT_HEAP_PROF_SAMPLE`` + * ``Word8``: Profile ID + * ``Word64``: Void + * ``Word64``: Lag + * ``Word64``: Use + * ``Word64``: Inherent use + * ``Word64``: Drag diff --git a/docs/users_guide/index.rst b/docs/users_guide/index.rst index b7ff4c091e..57b04c64a4 100644 --- a/docs/users_guide/index.rst +++ b/docs/users_guide/index.rst @@ -26,6 +26,7 @@ Contents: utils win32-dlls bugs + eventlog-formats editing-guide diff --git a/docs/users_guide/profiling.rst b/docs/users_guide/profiling.rst index 4d0bb3a3ed..daae7805d5 100644 --- a/docs/users_guide/profiling.rst +++ b/docs/users_guide/profiling.rst @@ -425,10 +425,14 @@ To generate a heap profile from your program: 2. Run it with one of the heap profiling options described below (eg. :rts-flag:`-h` for a basic producer profile). This generates the file - ``prog.hp``. + :file:`{prog}.hp`. -3. Run ``hp2ps`` to produce a Postscript file, ``prog.ps``. The - ``hp2ps`` utility is described in detail in :ref:`hp2ps`. + If the :ref:`event log <rts-eventlog>` is enabled (with the :rts-flag:`-l` + runtime system flag) heap samples will additionally be emitted to the GHC + event log (see :ref:`heap-profiler-events` for details about event format). + +3. Run :command:`hp2ps` to produce a Postscript file, :file:`{prog}.ps`. The + :command:`hp2ps` utility is described in detail in :ref:`hp2ps`. 4. Display the heap profile using a postscript viewer such as Ghostview, or print it out on a Postscript-capable printer. @@ -485,6 +489,18 @@ following RTS options select which break-down to use: Break down the graph by biography. Biographical profiling is described in more detail below (:ref:`biography-prof`). +.. rts-flag:: -l + + :noindex: + + .. index:: + single: eventlog; and heap profiling + + Emit profile samples to the :ref:`GHC event log <rts-eventlog>`. + This format is both more expressive than the old ``.hp`` format + and can be correlated with other events over the program's runtime. + See :ref:`heap-profiler-events` for details on the produced event structure. + In addition, the profile can be restricted to heap data which satisfies certain criteria - for example, you might want to display a profile by type but only for data produced by a certain module, or a profile by @@ -747,7 +763,7 @@ Usage: hp2ps [flags] [<file>[.hp]] -The program :command:`hp2ps` program converts a heap profile as produced +The program :command:`hp2ps` program converts a ``.hp`` file produced by the ``-h<break-down>`` runtime option into a PostScript graph of the heap profile. By convention, the file to be processed by :command:`hp2ps` has a ``.hp`` extension. The PostScript output is written to :file:`{file}@.ps`. diff --git a/includes/rts/Config.h b/includes/rts/Config.h index 043bf2deb4..51ee74fdb8 100644 --- a/includes/rts/Config.h +++ b/includes/rts/Config.h @@ -27,12 +27,16 @@ #define USING_LIBBFD 1 #endif -/* DEBUG implies TRACING and TICKY_TICKY - */ +/* DEBUG implies TRACING and TICKY_TICKY */ #if defined(DEBUG) +#if !defined(TRACING) #define TRACING +#endif +#if !defined(TICKY_TICKY) #define TICKY_TICKY #endif +#endif + /* ----------------------------------------------------------------------------- Signals - supported on non-PAR versions of the runtime. See RtsSignals.h. diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h index 68d0d08f55..d6838abd8a 100644 --- a/includes/rts/EventLogFormat.h +++ b/includes/rts/EventLogFormat.h @@ -163,8 +163,6 @@ #define EVENT_USER_MARKER 58 /* (marker_name) */ #define EVENT_HACK_BUG_T9003 59 /* Hack: see trac #9003 */ -/* Range 59 - 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/ */ @@ -173,12 +171,19 @@ /* Range 140 - 159 is reserved for Perf events. */ +/* Range 160 - 180 is reserved for cost-centre heap profiling events. */ + +#define EVENT_HEAP_PROF_BEGIN 160 +#define EVENT_HEAP_PROF_COST_CENTRE 161 +#define EVENT_HEAP_PROF_SAMPLE_BEGIN 162 +#define EVENT_HEAP_PROF_SAMPLE_COST_CENTRE 163 +#define EVENT_HEAP_PROF_SAMPLE_STRING 164 /* * The highest event code +1 that ghc itself emits. Note that some event * 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 60 +#define NUM_GHC_EVENT_TAGS 165 #if 0 /* DEPRECATED EVENTS: */ /* we don't actually need to record the thread, it's implicit */ diff --git a/mk/config.mk.in b/mk/config.mk.in index 47198b942a..56a63fd4d5 100644 --- a/mk/config.mk.in +++ b/mk/config.mk.in @@ -274,14 +274,21 @@ BuildSharedLibs=$(strip $(if $(findstring dyn,$(GhcLibWays)),YES,NO)) # In addition, the RTS is built in some further variations. Ways that # make sense here: # -# thr : threaded -# thr_p : threaded profiled -# debug : debugging (compile with -g for the C compiler, and -DDEBUG) -# debug_p : debugging profiled -# thr_debug : debugging threaded -# thr_debug_p : debugging threaded profiled -# l : event logging -# thr_l : threaded and event logging +# thr : threaded +# thr_p : threaded + profiled + eventlog +# debug : debugging + eventlog +# thr_debug : debugging + threaded, + eventlog +# l : eventlog +# p : profiled + eventlog +# thr_l : threaded + eventlog +# +# Note how there are a few cases which are handled specially (in packageHsLibs) +# to reduce the number of distinct ways, +# +# debug implies eventlog +# profiled implies eventlog +# +# This means, for instance, that there is no debug_l way. # GhcRTSWays=l diff --git a/mk/ways.mk b/mk/ways.mk index 996530e12a..870b4a5460 100644 --- a/mk/ways.mk +++ b/mk/ways.mk @@ -1,6 +1,6 @@ # -# Options for compiling in different `ways'. -# +# Options for compiling in different `ways'. +# # To configure up your own way, have a look at some of the standard ways # such as profiling, and create your own set of WAY_*_OPTS defs below. # After having done that, add your way string to WAYS, and after having @@ -10,7 +10,7 @@ # # Definitions of the different ways: -# +# # * their name: # - tag, e.g., p # - description, e.g., profiling @@ -18,18 +18,26 @@ # - WAY_p_HC_OPTS gives the list of command-line options # to the driver. # +# For consistency, the way name should be formed from the tags in the following +# order (the same ordering defined in DynFlags.Way), +# +# - thr: threaded +# - debug: debugging +# - p: profiled +# - l: eventlog +# - dyn: dynamically-linked # # The ways currently defined. # -ALL_WAYS=v p l debug dyn thr thr_l p_dyn debug_dyn thr_dyn thr_p_dyn thr_debug_dyn thr_p thr_debug debug_p thr_debug_p l_dyn thr_l_dyn +ALL_WAYS=v l debug dyn thr thr_l p_dyn p debug_dyn thr_dyn thr_p_dyn thr_debug_dyn thr_debug debug_p thr_debug_p l_dyn thr_l_dyn thr_p # # The following ways currently are treated specially, # as the driver script treats these guys specially and needs to carefully be told # about the options for these. Hence, we hide the required command line options # for these in the driver, as this is the only place they are needed. -# +# # If you want to add to these default options, fill in the variables below: # Way 'v': @@ -38,7 +46,7 @@ WAY_v_HC_OPTS= -static # Way 'p': WAY_p_NAME=profiling -WAY_p_HC_OPTS= -static -prof +WAY_p_HC_OPTS= -static -prof -eventlog # Way 'l': WAY_l_NAME=event logging @@ -53,8 +61,8 @@ WAY_thr_NAME=threaded WAY_thr_HC_OPTS= -static -optc-DTHREADED_RTS # Way 'thr_p': -WAY_thr_p_NAME=threaded profiled -WAY_thr_p_HC_OPTS= -static -optc-DTHREADED_RTS -prof +WAY_thr_p_NAME=threaded profiling +WAY_thr_p_HC_OPTS= -static -prof -eventlog -optc-DTHREADED_RTS # Way 'thr_l': WAY_thr_l_NAME=threaded event logging @@ -62,29 +70,35 @@ WAY_thr_l_HC_OPTS= -static -optc-DTHREADED_RTS -eventlog # Way 'debug': WAY_debug_NAME=debug -WAY_debug_HC_OPTS= -static -optc-DDEBUG -ticky -DTICKY_TICKY +WAY_debug_HC_OPTS= -static -optc-DDEBUG -ticky -DTICKY_TICKY -eventlog # Way 'debug_p': WAY_debug_p_NAME=debug profiled -WAY_debug_p_HC_OPTS= -static -optc-DDEBUG -prof +WAY_debug_p_HC_OPTS= -static -optc-DDEBUG -prof -eventlog + +# Way 'p': +WAY_p_NAME=profiling +WAY_p_HC_OPTS= -static -prof -eventlog # Way 'thr_debug': WAY_thr_debug_NAME=threaded debug -WAY_thr_debug_HC_OPTS= -static -optc-DTHREADED_RTS -optc-DDEBUG +WAY_thr_debug_HC_OPTS= -static -optc-DTHREADED_RTS -optc-DDEBUG -eventlog # Way 'thr_debug_p': -WAY_thr_debug_p_NAME=threaded debug profiling -WAY_thr_debug_p_HC_OPTS= -static -optc-DTHREADED_RTS -optc-DDEBUG -prof +WAY_thr_debug_p_NAME=threaded debug profiling event logging +WAY_thr_debug_p_HC_OPTS= -static -optc-DTHREADED_RTS -optc-DDEBUG -prof -eventlog # Way 'dyn': build dynamic shared libraries WAY_dyn_NAME=dyn WAY_dyn_HC_OPTS=-fPIC -dynamic +# Way 'p_dyn': WAY_p_dyn_NAME=p_dyn -WAY_p_dyn_HC_OPTS=-fPIC -dynamic -prof +WAY_p_dyn_HC_OPTS=-fPIC -dynamic -prof -eventlog +# Way 'thr_p_dyn': WAY_thr_p_dyn_NAME=thr_p_dyn -WAY_thr_p_dyn_HC_OPTS=-fPIC -dynamic -prof -optc-DTHREADED_RTS +WAY_thr_p_dyn_HC_OPTS=-fPIC -dynamic -prof -eventlog -optc-DTHREADED_RTS # Way 'thr_dyn': WAY_thr_dyn_NAME=thr_dyn @@ -92,11 +106,11 @@ WAY_thr_dyn_HC_OPTS=-fPIC -dynamic -optc-DTHREADED_RTS # Way 'thr_debug_dyn': WAY_thr_debug_dyn_NAME=thr_debug_dyn -WAY_thr_debug_dyn_HC_OPTS=-fPIC -dynamic -optc-DTHREADED_RTS -optc-DDEBUG +WAY_thr_debug_dyn_HC_OPTS=-fPIC -dynamic -optc-DTHREADED_RTS -optc-DDEBUG -eventlog # Way 'debug_dyn': WAY_debug_dyn_NAME=debug_dyn -WAY_debug_dyn_HC_OPTS=-fPIC -dynamic -optc-DDEBUG -ticky -DTICKY_TICKY +WAY_debug_dyn_HC_OPTS=-fPIC -dynamic -optc-DDEBUG -ticky -DTICKY_TICKY -eventlog # Way 'l_dyn': WAY_l_dyn_NAME=event logging dynamic @@ -105,4 +119,3 @@ WAY_l_dyn_HC_OPTS= -fPIC -dynamic -eventlog # Way 'thr_l_dyn': WAY_thr_l_dyn_NAME=threaded event logging dynamic WAY_thr_l_dyn_HC_OPTS= -fPIC -dynamic -optc-DTHREADED_RTS -eventlog - diff --git a/rts/ProfHeap.c b/rts/ProfHeap.c index 18c3e41a32..664ee50d70 100644 --- a/rts/ProfHeap.c +++ b/rts/ProfHeap.c @@ -20,6 +20,7 @@ #include "LdvProfile.h" #include "Arena.h" #include "Printer.h" +#include "Trace.h" #include "sm/GCThread.h" #include <string.h> @@ -371,6 +372,19 @@ printSample(rtsBool beginSample, StgDouble sampleValue) } } +static void +dumpCostCentresToEventLog(void) +{ +#ifdef 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 +} + /* -------------------------------------------------------------------------- * Initialize the heap profilier * ----------------------------------------------------------------------- */ @@ -400,7 +414,7 @@ initHeapProfiling(void) } // max_era = 2^LDV_SHIFT - max_era = 1 << LDV_SHIFT; + max_era = 1 << LDV_SHIFT; n_censuses = 32; censuses = stgMallocBytes(sizeof(Census) * n_censuses, "initHeapProfiling"); @@ -437,6 +451,9 @@ initHeapProfiling(void) } #endif + traceHeapProfBegin(0); + dumpCostCentresToEventLog(); + return 0; } @@ -744,10 +761,12 @@ dumpCensus( Census *census ) ssize_t count; printSample(rtsTrue, census->time); + traceHeapProfSampleBegin(era); #ifdef PROFILING if (RtsFlags.ProfFlags.doHeapProfile == HEAP_BY_LDV) { - fprintf(hp_file, "VOID\t%lu\n", (unsigned long)(census->void_total) * sizeof(W_)); + fprintf(hp_file, "VOID\t%lu\n", + (unsigned long)(census->void_total) * sizeof(W_)); fprintf(hp_file, "LAG\t%lu\n", (unsigned long)(census->not_used - census->void_total) * sizeof(W_)); fprintf(hp_file, "USE\t%lu\n", @@ -788,6 +807,8 @@ dumpCensus( Census *census ) switch (RtsFlags.ProfFlags.doHeapProfile) { case HEAP_BY_CLOSURE_TYPE: fprintf(hp_file, "%s", (char *)ctr->identity); + traceHeapProfSampleString(0, (char *)ctr->identity, + count * sizeof(W_)); break; } #endif @@ -795,12 +816,17 @@ dumpCensus( Census *census ) #ifdef PROFILING switch (RtsFlags.ProfFlags.doHeapProfile) { case HEAP_BY_CCS: - fprint_ccs(hp_file, (CostCentreStack *)ctr->identity, RtsFlags.ProfFlags.ccsLength); + fprint_ccs(hp_file, (CostCentreStack *)ctr->identity, + RtsFlags.ProfFlags.ccsLength); + traceHeapProfSampleCostCentre(0, (CostCentreStack *)ctr->identity, + count * sizeof(W_)); break; case HEAP_BY_MOD: case HEAP_BY_DESCR: case HEAP_BY_TYPE: fprintf(hp_file, "%s", (char *)ctr->identity); + traceHeapProfSampleString(0, (char *)ctr->identity, + count * sizeof(W_)); break; case HEAP_BY_RETAINER: { diff --git a/rts/Trace.c b/rts/Trace.c index 8480f10bbd..fdf80496f8 100644 --- a/rts/Trace.c +++ b/rts/Trace.c @@ -622,6 +622,49 @@ void traceTaskDelete_ (Task *task) } } +void traceHeapProfBegin(StgWord8 profile_id) +{ + if (eventlog_enabled) { + postHeapProfBegin(profile_id); + } +} + +void traceHeapProfSampleBegin(StgInt era) +{ + if (eventlog_enabled) { + postHeapProfSampleBegin(era); + } +} + +void traceHeapProfSampleString(StgWord8 profile_id, + const char *label, StgWord residency) +{ + if (eventlog_enabled) { + postHeapProfSampleString(profile_id, label, residency); + } +} + +#ifdef PROFILING +void traceHeapProfCostCentre(StgWord32 ccID, + const char *label, + const char *module, + const char *srcloc, + StgBool is_caf) +{ + if (eventlog_enabled) { + postHeapProfCostCentre(ccID, label, module, srcloc, is_caf); + } +} + +void traceHeapProfSampleCostCentre(StgWord8 profile_id, + CostCentreStack *stack, StgWord residency) +{ + if (eventlog_enabled) { + postHeapProfSampleCostCentre(profile_id, stack, residency); + } +} +#endif + #ifdef DEBUG static void vtraceCap_stderr(Capability *cap, char *msg, va_list ap) { diff --git a/rts/Trace.h b/rts/Trace.h index cad65b0644..ab79671c4c 100644 --- a/rts/Trace.h +++ b/rts/Trace.h @@ -275,6 +275,20 @@ void traceTaskMigrate_ (Task *task, void traceTaskDelete_ (Task *task); +void traceHeapProfBegin(StgWord8 profile_id); +void traceHeapProfSampleBegin(StgInt era); +void traceHeapProfSampleString(StgWord8 profile_id, + const char *label, StgWord residency); +#ifdef PROFILING +void traceHeapProfCostCentre(StgWord32 ccID, + const char *label, + const char *module, + const char *srcloc, + StgBool is_caf); +void traceHeapProfSampleCostCentre(StgWord8 profile_id, + CostCentreStack *stack, StgWord residency); +#endif /* PROFILING */ + #else /* !TRACING */ #define traceSchedEvent(cap, tag, tso, other) /* nothing */ @@ -304,6 +318,11 @@ void traceTaskDelete_ (Task *task); #define traceTaskCreate_(taskID, cap) /* nothing */ #define traceTaskMigrate_(taskID, cap, new_cap) /* nothing */ #define traceTaskDelete_(taskID) /* nothing */ +#define traceHeapProfBegin(profile_id) /* nothing */ +#define traceHeapProfCostCentre(ccID, label, module, srcloc, is_caf) /* nothing */ +#define traceHeapProfSampleBegin(era) /* nothing */ +#define traceHeapProfSampleCostCentre(profile_id, stack, residency) /* nothing */ +#define traceHeapProfSampleString(profile_id, label, residency) /* nothing */ #endif /* TRACING */ diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 7cb69e8d7d..4e4bdb5191 100644 --- a/rts/eventlog/EventLog.c +++ b/rts/eventlog/EventLog.c @@ -106,6 +106,11 @@ char *EventDesc[] = { [EVENT_TASK_MIGRATE] = "Task migrate", [EVENT_TASK_DELETE] = "Task delete", [EVENT_HACK_BUG_T9003] = "Empty event for bug #9003", + [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_PROF_SAMPLE_STRING] = "Heap profile string sample", + [EVENT_HEAP_PROF_SAMPLE_COST_CENTRE] = "Heap profile cost-centre sample", }; // Event type. @@ -164,6 +169,22 @@ static inline void postBuf(EventsBuf *eb, StgWord8 *buf, uint32_t size) eb->pos += size; } +/* Post a null-terminated string to the event log. + * It is the caller's responsibility to ensure that there is + * enough room for strlen(buf)+1 bytes. + */ +static inline void postString(EventsBuf *eb, const char *buf) +{ + if (buf) { + int len = strlen(buf); + ASSERT(eb->begin + eb->size > eb->pos + len); + memcpy(eb->pos, buf, len); + eb->pos += len; + } + *eb->pos = 0; + eb->pos++; +} + static inline StgWord64 time_ns(void) { return TimeToNS(stat_getElapsedTime()); } @@ -209,6 +230,7 @@ static inline void postInt8(EventsBuf *eb, StgInt8 i) static inline void postInt32(EventsBuf *eb, StgInt32 i) { postWord32(eb, (StgWord32)i); } +#define EVENT_SIZE_DYNAMIC (-1) void initEventLogging(void) @@ -429,6 +451,26 @@ initEventLogging(void) eventTypes[t].size = 0; break; + case EVENT_HEAP_PROF_BEGIN: + eventTypes[t].size = EVENT_SIZE_DYNAMIC; + break; + + case EVENT_HEAP_PROF_COST_CENTRE: + eventTypes[t].size = EVENT_SIZE_DYNAMIC; + break; + + case EVENT_HEAP_PROF_SAMPLE_BEGIN: + eventTypes[t].size = 8; + break; + + case EVENT_HEAP_PROF_SAMPLE_STRING: + eventTypes[t].size = EVENT_SIZE_DYNAMIC; + break; + + case EVENT_HEAP_PROF_SAMPLE_COST_CENTRE: + eventTypes[t].size = EVENT_SIZE_DYNAMIC; + break; + default: continue; /* ignore deprecated events */ } @@ -1098,6 +1140,147 @@ void postBlockMarker (EventsBuf *eb) postCapNo(eb, eb->capno); } +typedef enum { + HEAP_PROF_BREAKDOWN_COST_CENTRE = 0x1, + HEAP_PROF_BREAKDOWN_MODULE, + HEAP_PROF_BREAKDOWN_CLOSURE_DESCR, + HEAP_PROF_BREAKDOWN_TYPE_DESCR, + HEAP_PROF_BREAKDOWN_RETAINER, + HEAP_PROF_BREAKDOWN_BIOGRAPHY, +} HeapProfBreakdown; + +static HeapProfBreakdown getHeapProfBreakdown(void) +{ + switch (RtsFlags.ProfFlags.doHeapProfile) { + case HEAP_BY_CCS: + return HEAP_PROF_BREAKDOWN_COST_CENTRE; + case HEAP_BY_MOD: + return HEAP_PROF_BREAKDOWN_MODULE; + case HEAP_BY_DESCR: + return HEAP_PROF_BREAKDOWN_CLOSURE_DESCR; + case HEAP_BY_TYPE: + return HEAP_PROF_BREAKDOWN_TYPE_DESCR; + case HEAP_BY_RETAINER: + return HEAP_PROF_BREAKDOWN_RETAINER; + case HEAP_BY_LDV: + return HEAP_PROF_BREAKDOWN_BIOGRAPHY; + default: + barf("getHeapProfBreakdown: unknown heap profiling mode"); + } +} + +void postHeapProfBegin(StgWord8 profile_id) +{ + ACQUIRE_LOCK(&eventBufMutex); + PROFILING_FLAGS *flags = &RtsFlags.ProfFlags; + StgWord modSelector_len = + flags->modSelector ? strlen(flags->modSelector) : 0; + StgWord descrSelector_len = + flags->descrSelector ? strlen(flags->descrSelector) : 0; + StgWord typeSelector_len = + flags->typeSelector ? strlen(flags->typeSelector) : 0; + StgWord ccSelector_len = + flags->ccSelector ? strlen(flags->ccSelector) : 0; + StgWord ccsSelector_len = + flags->ccsSelector ? strlen(flags->ccsSelector) : 0; + StgWord retainerSelector_len = + flags->retainerSelector ? strlen(flags->retainerSelector) : 0; + StgWord bioSelector_len = + flags->bioSelector ? strlen(flags->bioSelector) : 0; + StgWord len = + 1+8+4 + modSelector_len + descrSelector_len + + typeSelector_len + ccSelector_len + ccsSelector_len + + retainerSelector_len + bioSelector_len + 7; + ensureRoomForVariableEvent(&eventBuf, len); + postEventHeader(&eventBuf, EVENT_HEAP_PROF_BEGIN); + postPayloadSize(&eventBuf, len); + postWord8(&eventBuf, profile_id); + postWord64(&eventBuf, TimeToNS(flags->heapProfileInterval)); + postWord32(&eventBuf, getHeapProfBreakdown()); + postString(&eventBuf, flags->modSelector); + postString(&eventBuf, flags->descrSelector); + postString(&eventBuf, flags->typeSelector); + postString(&eventBuf, flags->ccSelector); + postString(&eventBuf, flags->ccsSelector); + postString(&eventBuf, flags->retainerSelector); + postString(&eventBuf, flags->bioSelector); + RELEASE_LOCK(&eventBufMutex); +} + +void postHeapProfSampleBegin(StgInt era) +{ + ACQUIRE_LOCK(&eventBufMutex); + ensureRoomForEvent(&eventBuf, EVENT_HEAP_PROF_SAMPLE_BEGIN); + postEventHeader(&eventBuf, EVENT_HEAP_PROF_SAMPLE_BEGIN); + postWord64(&eventBuf, era); + RELEASE_LOCK(&eventBufMutex); +} + +void postHeapProfSampleString(StgWord8 profile_id, + const char *label, + StgWord64 residency) +{ + ACQUIRE_LOCK(&eventBufMutex); + StgWord label_len = strlen(label); + StgWord len = 1+8+label_len+1; + ensureRoomForVariableEvent(&eventBuf, len); + postEventHeader(&eventBuf, EVENT_HEAP_PROF_SAMPLE_STRING); + postPayloadSize(&eventBuf, len); + postWord8(&eventBuf, profile_id); + postWord64(&eventBuf, residency); + postString(&eventBuf, label); + RELEASE_LOCK(&eventBufMutex); +} + +#ifdef PROFILING +void postHeapProfCostCentre(StgWord32 ccID, + const char *label, + const char *module, + const char *srcloc, + StgBool is_caf) +{ + ACQUIRE_LOCK(&eventBufMutex); + StgWord label_len = strlen(label); + StgWord module_len = strlen(module); + StgWord srcloc_len = strlen(srcloc); + StgWord len = 4+label_len+module_len+srcloc_len+3+1; + ensureRoomForVariableEvent(&eventBuf, len); + postEventHeader(&eventBuf, EVENT_HEAP_PROF_COST_CENTRE); + postPayloadSize(&eventBuf, len); + postWord32(&eventBuf, ccID); + postString(&eventBuf, label); + postString(&eventBuf, module); + postString(&eventBuf, srcloc); + postWord8(&eventBuf, is_caf); + RELEASE_LOCK(&eventBufMutex); +} + +void postHeapProfSampleCostCentre(StgWord8 profile_id, + CostCentreStack *stack, + StgWord64 residency) +{ + 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 = 1+8+1+depth*4; + ensureRoomForVariableEvent(&eventBuf, len); + postEventHeader(&eventBuf, EVENT_HEAP_PROF_SAMPLE_COST_CENTRE); + postPayloadSize(&eventBuf, len); + postWord8(&eventBuf, profile_id); + postWord64(&eventBuf, residency); + 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); +} +#endif /* PROFILING */ + void printAndClearEventBuf (EventsBuf *ebuf) { closeBlockMarker(ebuf); diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h index ed783bc361..462f5f594e 100644 --- a/rts/eventlog/EventLog.h +++ b/rts/eventlog/EventLog.h @@ -133,6 +133,26 @@ void postTaskMigrateEvent (EventTaskId taskId, void postTaskDeleteEvent (EventTaskId taskId); +void postHeapProfBegin(StgWord8 profile_id); + +void postHeapProfSampleBegin(StgInt era); + +void postHeapProfSampleString(StgWord8 profile_id, + const char *label, + StgWord64 residency); + +#ifdef PROFILING +void postHeapProfCostCentre(StgWord32 ccID, + const char *label, + const char *module, + const char *srcloc, + StgBool is_caf); + +void postHeapProfSampleCostCentre(StgWord8 profile_id, + CostCentreStack *stack, + StgWord64 residency); +#endif /* PROFILING */ + #else /* !TRACING */ INLINE_HEADER void postSchedEvent (Capability *cap STG_UNUSED, |