[Git][ghc/ghc][wip/ticky-eventlog] 2 commits: rts: Post ticky entry counts to the eventlog
Ben Gamari
gitlab at gitlab.haskell.org
Tue May 26 18:53:22 UTC 2020
Ben Gamari pushed to branch wip/ticky-eventlog at Glasgow Haskell Compiler / GHC
Commits:
c95667f5 by Ben Gamari at 2020-05-26T14:53:11-04:00
rts: Post ticky entry counts to the eventlog
We currently only post the entry counters, not the other global
counters as in my experience the former are more useful. We use the heap
profiler's census period to decide when to dump.
Also adds documentation for a few more ticky flags.
- - - - -
43201e39 by Ben Gamari at 2020-05-26T14:53:11-04:00
users guide: Fix a few sundry formatting issues
- - - - -
17 changed files:
- docs/users_guide/eventlog-formats.rst
- docs/users_guide/expected-undocumented-flags.txt
- docs/users_guide/extending_ghc.rst
- docs/users_guide/profiling.rst
- docs/users_guide/runtime_control.rst
- docs/users_guide/using-warnings.rst
- includes/rts/EventLogFormat.h
- includes/rts/Flags.h
- rts/Proftimer.c
- rts/Proftimer.h
- rts/RtsFlags.c
- rts/RtsStartup.c
- rts/Ticky.c
- rts/Ticky.h
- rts/eventlog/EventLog.c
- rts/eventlog/EventLog.h
- rts/sm/GC.c
Changes:
=====================================
docs/users_guide/eventlog-formats.rst
=====================================
@@ -755,3 +755,37 @@ intended to provide insight into fragmentation of the non-moving heap.
:field Word32: number of live blocks.
Describes the occupancy of the *blk_sz* sub-heap.
+
+.. _ticky-counter-events:
+
+Ticky counters
+~~~~~~~~~~~~~~
+
+Programs compiled with :ghc-flag:`-ticky` and :ghc-flag:`-eventlog` and invoked
+with ``+RTS -lT`` will emit periodic samples of the ticky entry counters to the
+eventlog.
+
+.. event-type:: TICKY_COUNTER_DEF
+
+ :tag: 210
+ :length: variable
+ :field Word64: counter ID
+ :field Word16: arity/field count
+ :field String: argument kinds. This is the same as the synonymous field in the
+ textual ticky summary.
+ :field String: counter name
+
+ Defines a ticky counter.
+
+.. event-type:: TICKY_COUNTER_SAMPLE
+
+ :tag: 211
+ :length: fixed
+ :field Word64: counter ID
+ :field Word64: number of times closures of this type has been entered.
+ :field Word64: number of allocations (words)
+ :field Word64: number of times this has been allocated (words). Only
+ produced for modules compiled with :ghc-flag:`-ticky-allocd`.
+
+ Records the number of entries, and allocations by/of a particular
+ closure since the last sample.
=====================================
docs/users_guide/expected-undocumented-flags.txt
=====================================
@@ -167,6 +167,3 @@
-split-objs
-syslib
-this-component-id
--ticky-LNE
--ticky-allocd
--ticky-dyn-thunk
=====================================
docs/users_guide/extending_ghc.rst
=====================================
@@ -775,7 +775,7 @@ each case:
package/field-n
To read an interface file from an external tool without linking to GHC, the format
-is described at `Extensible Interface Files<https://gitlab.haskell.org/ghc/ghc/wikis/Extensible-Interface-Files>`_.
+is described at `Extensible Interface Files <https://gitlab.haskell.org/ghc/ghc/wikis/Extensible-Interface-Files>`_.
Source plugin example
^^^^^^^^^^^^^^^^^^^^^
=====================================
docs/users_guide/profiling.rst
=====================================
@@ -1630,11 +1630,46 @@ Using “ticky-ticky” profiling (for implementors)
Enable ticky-ticky profiling.
+.. ghc-flag:: -ticky-allocd
+ :shortdesc: Enable ticky-ticky counters for number of thunk allocations.
+ :type: dynamic
+ :category:
+
+ By default ticky reports only the amount of allocation done *by* a closure.
+ With :ghc-flag:`-ticky-allocd`, it also reports on allocation *of* a
+ closure.
+
+.. ghc-flag:: -ticky-LNE
+ :shortdesc: Enable ticky-ticky counters for let-no-escape bindings.
+ :type: dynamic
+ :category:
+
+ Enable ticky-ticky counters for let-no-escape bindings (i.e. join points).
+
+.. ghc-flag:: -ticky-dyn-thunk
+ :shortdesc: Enable ticky-ticky counters on dynamic closures.
+ :type: dynamic
+ :category:
+
+ By default ticky reports counts only for *static* closures. With
+ :ghc-flag:`-ticky-dyn-thunk` it will also report counts for
+ dynamically-allocated thunks. Note that this will significantly
+ increase instrumentation costs.
+
Because ticky-ticky profiling requires a certain familiarity with GHC
internals, we have moved the documentation to the GHC developers wiki.
Take a look at its
:ghc-wiki:`overview of the profiling options <commentary/profiling>`,
-which includeds a link to the ticky-ticky profiling page.
+which includes a link to the ticky-ticky profiling page.
+
+Note that GHC can also periodically emit samples of ticky counters to
+the :ghc-flag:`eventlog <-eventlog>` by enabling the :rts-flag:`+RTS -lT <-l
+⟨flags⟩>` event flag. The sampling period can be set via :rts-flag:`-i ⟨secs⟩`
+RTS flag. See the :ref:`eventlog formats <ticky-counter-events>` section for
+details on the eventlog representation.
+
+Note that the traditional text output (e.g. :rts-flag:`-r`) and
+the eventlog output are mutually exclusive.
.. [1]
:ghc-flag:`-fprof-auto` was known as ``-auto-all`` prior to
=====================================
docs/users_guide/runtime_control.rst
=====================================
@@ -1169,6 +1169,9 @@ When the program is linked with the :ghc-flag:`-eventlog` option
- ``f`` — parallel sparks (fully accurate). Disabled by default.
+ - ``T`` — :ref:`ticky-ticky <ticky-ticky>` profiler counter samples.
+ Disabled by default.
+
- ``u`` — user events. These are events emitted from Haskell code using
functions such as ``Debug.Trace.traceEvent``. Enabled by default.
@@ -1192,10 +1195,10 @@ When the program is linked with the :ghc-flag:`-eventlog` option
The format of the log file is described in this users guide in
:ref:`eventlog-encodings` It can be parsed in Haskell using the
- `ghc-events <http://hackage.haskell.org/package/ghc-events>`__
+ `ghc-events <http://hackage.haskell.org/package/ghc-events>`_
library. To dump the contents of a ``.eventlog`` file as text, use
the tool ``ghc-events show`` that comes with the
- `ghc-events <http://hackage.haskell.org/package/ghc-events>`__
+ `ghc-events <http://hackage.haskell.org/package/ghc-events>`_
package.
Each event is associated with a timestamp which is the number of
=====================================
docs/users_guide/using-warnings.rst
=====================================
@@ -239,8 +239,8 @@ of ``-W(no-)*``.
- ``Data.List`` due to the future addition of ``Data.List.singleton`` and
specialisation of exports to the ``[]`` type. See the
- :ref:`mailing list
- <https://groups.google.com/forum/#!topic/haskell-core-libraries/q3zHLmzBa5E>`
+ `mailing list
+ <https://groups.google.com/forum/#!topic/haskell-core-libraries/q3zHLmzBa5E>`_
for details.
This warning can be addressed by either adding an explicit import list or
=====================================
includes/rts/EventLogFormat.h
=====================================
@@ -154,12 +154,15 @@
#define EVENT_CONC_UPD_REM_SET_FLUSH 206
#define EVENT_NONMOVING_HEAP_CENSUS 207
+#define EVENT_TICKY_COUNTER_DEF 210
+#define EVENT_TICKY_COUNTER_SAMPLE 211
+
/*
* 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 208
+#define NUM_GHC_EVENT_TAGS 212
#if 0 /* DEPRECATED EVENTS: */
/* we don't actually need to record the thread, it's implicit */
=====================================
includes/rts/Flags.h
=====================================
@@ -176,6 +176,7 @@ typedef struct _TRACE_FLAGS {
bool nonmoving_gc; /* trace nonmoving GC events */
bool sparks_sampled; /* trace spark events by a sampled method */
bool sparks_full; /* trace spark events 100% accurately */
+ bool ticky; /* trace ticky-ticky samples */
bool user; /* trace user events (emitted from Haskell code) */
char *trace_output; /* output filename for eventlog */
} TRACE_FLAGS;
=====================================
rts/Proftimer.c
=====================================
@@ -20,6 +20,12 @@ static bool do_prof_ticks = false; // enable profiling ticks
static bool do_heap_prof_ticks = false; // enable heap profiling ticks
+// Sampling of Ticky-Ticky profiler to eventlog
+#if defined(TICKY_TICKY) && defined(TRACING)
+static int ticks_to_ticky_sample = 0;
+bool performTickySample = false;
+#endif
+
// Number of ticks until next heap census
static int ticks_to_heap_profile;
@@ -83,6 +89,16 @@ handleProfTick(void)
}
#endif
+#if defined(TICKY_TICKY) && defined(TRACING)
+ if (RtsFlags.TraceFlags.ticky) {
+ ticks_to_ticky_sample--;
+ if (ticks_to_ticky_sample <= 0) {
+ ticks_to_ticky_sample = RtsFlags.ProfFlags.heapProfileIntervalTicks;
+ performTickySample = true;
+ }
+ }
+#endif
+
if (do_heap_prof_ticks) {
ticks_to_heap_profile--;
if (ticks_to_heap_profile <= 0) {
=====================================
rts/Proftimer.h
=====================================
@@ -17,5 +17,6 @@ void stopHeapProfTimer ( void );
void startHeapProfTimer ( void );
extern bool performHeapProfile;
+extern bool performTickySample;
#include "EndPrivate.h"
=====================================
rts/RtsFlags.c
=====================================
@@ -234,6 +234,7 @@ void initRtsFlagsDefaults(void)
RtsFlags.TraceFlags.sparks_sampled= false;
RtsFlags.TraceFlags.sparks_full = false;
RtsFlags.TraceFlags.user = false;
+ RtsFlags.TraceFlags.ticky = false;
RtsFlags.TraceFlags.trace_output = NULL;
#endif
@@ -386,6 +387,9 @@ usage_text[] = {
" p par spark events (sampled)",
" f par spark events (full detail)",
" u user events (emitted from Haskell code)",
+#if defined(TICKY_TICKY)
+" T ticky-ticky counter samples",
+#endif
" a all event classes above",
# if defined(DEBUG)
" t add time stamps (only useful with -v)",
@@ -1791,6 +1795,11 @@ static void normaliseRtsOpts (void)
"the compacting collector.");
errorUsage();
}
+
+ if (RtsFlags.TraceFlags.ticky && RtsFlags.TickyFlags.showTickyStats) {
+ barf("The ticky-ticky eventlog output cannot be used in conjunction with\n"
+ "+RTS -r<file>.");
+ }
}
static void errorUsage (void)
@@ -2233,6 +2242,15 @@ static void read_trace_flags(const char *arg)
RtsFlags.TraceFlags.user = enabled;
enabled = true;
break;
+ case 'T':
+#if defined(TICKY_TICKY)
+ RtsFlags.TraceFlags.ticky = enabled;
+ enabled = true;
+ break;
+#else
+ errorBelch("Program not compiled with ticky-ticky support");
+ break;
+#endif
default:
errorBelch("unknown trace option: %c",*c);
break;
=====================================
rts/RtsStartup.c
=====================================
@@ -415,6 +415,17 @@ hs_exit_(bool wait_foreign)
*/
exitTimer(true);
+ /*
+ * Dump the ticky counter definitions
+ * We do this at the end of execution since tickers are registered in the
+ * course of program execution.
+ */
+#if defined(TICKY_TICKY) && defined(TRACING)
+ if (RtsFlags.TraceFlags.ticky) {
+ emitTickyCounterDefs();
+ }
+#endif
+
// set the terminal settings back to what they were
#if !defined(mingw32_HOST_OS)
resetTerminalSettings();
=====================================
rts/Ticky.c
=====================================
@@ -10,6 +10,8 @@
#include "PosixSource.h"
#include "Rts.h"
+#include "eventlog/EventLog.h"
+
/* Catch-all top-level counter struct. Allocations from CAFs will go
* here.
*/
@@ -46,6 +48,10 @@ static void printRegisteredCounterInfo (FILE *); /* fwd decl */
void
PrintTickyInfo(void)
{
+ if (RtsFlags.TraceFlags.ticky) {
+ barf("Ticky eventlog output can't be used with +RTS -r<file>");
+ }
+
unsigned long i;
unsigned long tot_thk_enters = ENT_STATIC_THK_MANY_ctr + ENT_DYN_THK_MANY_ctr
@@ -374,4 +380,19 @@ printRegisteredCounterInfo (FILE *tf)
}
}
+
+void emitTickyCounterDefs()
+{
+#if defined(TRACING)
+ postTickyCounterDefs(ticky_entry_ctrs);
+#endif
+}
+
+void emitTickyCounterSamples()
+{
+#if defined(TRACING)
+ postTickyCounterSamples(ticky_entry_ctrs);
+#endif
+}
+
#endif /* TICKY_TICKY */
=====================================
rts/Ticky.h
=====================================
@@ -8,4 +8,11 @@
#pragma once
-RTS_PRIVATE void PrintTickyInfo(void);
+#include "BeginPrivate.h"
+
+void PrintTickyInfo(void);
+
+void emitTickyCounterSamples(void);
+void emitTickyCounterDefs(void);
+
+#include "EndPrivate.h"
=====================================
rts/eventlog/EventLog.c
=====================================
@@ -119,7 +119,9 @@ char *EventDesc[] = {
[EVENT_CONC_SWEEP_BEGIN] = "Begin concurrent sweep",
[EVENT_CONC_SWEEP_END] = "End concurrent sweep",
[EVENT_CONC_UPD_REM_SET_FLUSH] = "Update remembered set flushed",
- [EVENT_NONMOVING_HEAP_CENSUS] = "Nonmoving heap census"
+ [EVENT_NONMOVING_HEAP_CENSUS] = "Nonmoving heap census",
+ [EVENT_TICKY_COUNTER_DEF] = "Ticky-ticky entry counter definition",
+ [EVENT_TICKY_COUNTER_SAMPLE] = "Ticky-ticky entry counter sample",
};
// Event type.
@@ -487,6 +489,14 @@ init_event_types(void)
eventTypes[t].size = 13;
break;
+ case EVENT_TICKY_COUNTER_DEF: // (counter_id, arity, arg_kinds, name)
+ eventTypes[t].size = EVENT_SIZE_DYNAMIC;
+ break;
+
+ case EVENT_TICKY_COUNTER_SAMPLE: // (counter_id, entry_count, allocs, allocd)
+ eventTypes[t].size = 8*4;
+ break;
+
default:
continue; /* ignore deprecated events */
}
@@ -1472,6 +1482,58 @@ void postProfBegin(void)
}
#endif /* PROFILING */
+#if defined(TICKY_TICKY)
+static void postTickyCounterDef(EventsBuf *eb, StgEntCounter *p)
+{
+ StgWord len = 8 + 2 + strlen(p->arg_kinds)+1 + strlen(p->str)+1;
+ ensureRoomForVariableEvent(eb, len);
+ postEventHeader(eb, EVENT_TICKY_COUNTER_DEF);
+ postPayloadSize(eb, len);
+ postWord64(eb, (uint64_t) p);
+ postWord16(eb, (uint16_t) p->arity);
+ postString(eb, p->arg_kinds);
+ postString(eb, p->str);
+}
+
+void postTickyCounterDefs(StgEntCounter *counters)
+{
+ ACQUIRE_LOCK(&eventBufMutex);
+ for (StgEntCounter *p = counters; p != NULL; p = p->link) {
+ postTickyCounterDef(&eventBuf, p);
+ }
+ RELEASE_LOCK(&eventBufMutex);
+}
+
+static void postTickyCounterSample(EventsBuf *eb, StgEntCounter *p)
+{
+ if ( p->entry_count == 0
+ && p->allocs == 0
+ && p->allocd == 0)
+ return;
+
+ ensureRoomForEvent(eb, EVENT_TICKY_COUNTER_SAMPLE);
+ postEventHeader(eb, EVENT_TICKY_COUNTER_SAMPLE);
+ postWord64(eb, (uint64_t) p);
+ postWord64(eb, p->entry_count);
+ postWord64(eb, p->allocs);
+ postWord64(eb, p->allocd);
+
+ // Zero the ticker counts for the next sample.
+ p->entry_count = 0;
+ p->allocs = 0;
+ p->allocd = 0;
+}
+
+void postTickyCounterSamples(StgEntCounter *counters)
+{
+ ACQUIRE_LOCK(&eventBufMutex);
+ for (StgEntCounter *p = counters; p != NULL; p = p->link) {
+ postTickyCounterSample(&eventBuf, p);
+ }
+ RELEASE_LOCK(&eventBufMutex);
+}
+#endif /* TICKY_TICKY */
+
void printAndClearEventBuf (EventsBuf *ebuf)
{
closeBlockMarker(ebuf);
=====================================
rts/eventlog/EventLog.h
=====================================
@@ -173,6 +173,11 @@ void postConcMarkEnd(StgWord32 marked_obj_count);
void postNonmovingHeapCensus(int log_blk_size,
const struct NonmovingAllocCensus *census);
+#if defined(TICKY_TICKY)
+void postTickyCounterDefs(StgEntCounter *p);
+void postTickyCounterSamples(StgEntCounter *p);
+#endif /* TICKY_TICKY */
+
#else /* !TRACING */
INLINE_HEADER void postSchedEvent (Capability *cap STG_UNUSED,
=====================================
rts/sm/GC.c
=====================================
@@ -38,6 +38,7 @@
#include "Sanity.h"
#include "BlockAlloc.h"
#include "ProfHeap.h"
+#include "Proftimer.h"
#include "Weak.h"
#include "Prelude.h"
#include "RtsSignals.h"
@@ -52,6 +53,7 @@
#include "CNF.h"
#include "RtsFlags.h"
#include "NonMoving.h"
+#include "Ticky.h"
#include <string.h> // for memset()
#include <unistd.h>
@@ -860,6 +862,16 @@ GarbageCollect (uint32_t collect_gen,
ACQUIRE_SM_LOCK;
}
+#if defined(TICKY_TICKY)
+ // Post ticky counter sample.
+ // We do this at the end of execution since tickers are registered in the
+ // course of program execution.
+ if (performTickySample) {
+ emitTickyCounterSamples();
+ performTickySample = false;
+ }
+#endif
+
// send exceptions to any threads which were about to die
RELEASE_SM_LOCK;
resurrectThreads(resurrected_threads);
View it on GitLab: https://gitlab.haskell.org/ghc/ghc/-/compare/85683db81c3bf7a12a28236f1701599985bf0969...43201e39a98a30364c1108c5646de828dfc11878
--
View it on GitLab: https://gitlab.haskell.org/ghc/ghc/-/compare/85683db81c3bf7a12a28236f1701599985bf0969...43201e39a98a30364c1108c5646de828dfc11878
You're receiving this email because of your account on gitlab.haskell.org.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.haskell.org/pipermail/ghc-commits/attachments/20200526/4d99e416/attachment-0001.html>
More information about the ghc-commits
mailing list