diff options
-rw-r--r-- | docs/users_guide/eventlog-formats.rst | 31 | ||||
-rw-r--r-- | docs/users_guide/expected-undocumented-flags.txt | 2 | ||||
-rw-r--r-- | docs/users_guide/profiling.rst | 20 | ||||
-rw-r--r-- | includes/rts/EventLogFormat.h | 5 | ||||
-rw-r--r-- | includes/rts/Flags.h | 1 | ||||
-rw-r--r-- | rts/Proftimer.c | 16 | ||||
-rw-r--r-- | rts/Proftimer.h | 1 | ||||
-rw-r--r-- | rts/RtsFlags.c | 18 | ||||
-rw-r--r-- | rts/RtsStartup.c | 11 | ||||
-rw-r--r-- | rts/Ticky.c | 21 | ||||
-rw-r--r-- | rts/Ticky.h | 9 | ||||
-rw-r--r-- | rts/eventlog/EventLog.c | 59 | ||||
-rw-r--r-- | rts/eventlog/EventLog.h | 5 | ||||
-rw-r--r-- | rts/sm/GC.c | 12 |
14 files changed, 204 insertions, 7 deletions
diff --git a/docs/users_guide/eventlog-formats.rst b/docs/users_guide/eventlog-formats.rst index 9be662d058..af172758bf 100644 --- a/docs/users_guide/eventlog-formats.rst +++ b/docs/users_guide/eventlog-formats.rst @@ -755,3 +755,34 @@ 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 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 counter statistics at a moment in time. diff --git a/docs/users_guide/expected-undocumented-flags.txt b/docs/users_guide/expected-undocumented-flags.txt index 9b47e70a03..23b5a4abe7 100644 --- a/docs/users_guide/expected-undocumented-flags.txt +++ b/docs/users_guide/expected-undocumented-flags.txt @@ -118,5 +118,3 @@ -syslib -this-component-id -ticky-LNE --ticky-allocd --ticky-dyn-thunk diff --git a/docs/users_guide/profiling.rst b/docs/users_guide/profiling.rst index 0b075429b5..ac1137ac84 100644 --- a/docs/users_guide/profiling.rst +++ b/docs/users_guide/profiling.rst @@ -1681,11 +1681,27 @@ Using “ticky-ticky” profiling (for implementors) single: ticky-ticky profiling .. ghc-flag:: -ticky - :shortdesc: :ref:`Turn on ticky-ticky profiling <ticky-ticky>` + :shortdesc: Turn on :ref:`ticky-ticky profiling <ticky-ticky>` :type: dynamic :category: - Enable ticky-ticky profiling. + Enable ticky-ticky profiling. By default this only tracks the allocations + *by* each closure type. See :ghc-flag:`-ticky-allocd` to keep track of + allocations *of* each closure type as well. + +.. ghc-flag:: -ticky-allocd + :shortdesc: Track the number of times each closure type is allocated. + :type: dynamic + :category: + + Keep track of how much each closure type is allocated. + +.. ghc-flag:: -ticky-dyn-thunk + :shortdesc: Track allocations of dynamic thunks + :type: dynamic + :category: + + Track allocations of dynamic thunks. Because ticky-ticky profiling requires a certain familiarity with GHC internals, we have moved the documentation to the GHC developers wiki. diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h index 89a07bf5e1..d069ec6595 100644 --- a/includes/rts/EventLogFormat.h +++ b/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 */ diff --git a/includes/rts/Flags.h b/includes/rts/Flags.h index 9455892cdb..35b45b0940 100644 --- a/includes/rts/Flags.h +++ b/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; diff --git a/rts/Proftimer.c b/rts/Proftimer.c index 24f82ead6d..00b92a227d 100644 --- a/rts/Proftimer.c +++ b/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 (RELAXED_LOAD(&do_heap_prof_ticks)) { ticks_to_heap_profile--; if (ticks_to_heap_profile <= 0) { diff --git a/rts/Proftimer.h b/rts/Proftimer.h index 89fb100b44..ad50ccb9a6 100644 --- a/rts/Proftimer.h +++ b/rts/Proftimer.h @@ -17,5 +17,6 @@ void stopHeapProfTimer ( void ); void startHeapProfTimer ( void ); extern bool performHeapProfile; +extern bool performTickySample; #include "EndPrivate.h" diff --git a/rts/RtsFlags.c b/rts/RtsFlags.c index e7375a0746..b23b19752b 100644 --- a/rts/RtsFlags.c +++ b/rts/RtsFlags.c @@ -235,6 +235,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 @@ -403,6 +404,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)", @@ -1855,6 +1859,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) @@ -2297,6 +2306,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; diff --git a/rts/RtsStartup.c b/rts/RtsStartup.c index 02e32106d2..107a74dc5b 100644 --- a/rts/RtsStartup.c +++ b/rts/RtsStartup.c @@ -487,6 +487,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(); diff --git a/rts/Ticky.c b/rts/Ticky.c index b46f91b204..83ba70887c 100644 --- a/rts/Ticky.c +++ b/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 */ diff --git a/rts/Ticky.h b/rts/Ticky.h index 1a5357d8db..a8c2f1ae9b 100644 --- a/rts/Ticky.h +++ b/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" diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 11e8a5e0b6..d093d595c7 100644 --- a/rts/eventlog/EventLog.c +++ b/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,53 @@ 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); +} + +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); diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h index eca76619cd..cf94a25ed6 100644 --- a/rts/eventlog/EventLog.h +++ b/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, diff --git a/rts/sm/GC.c b/rts/sm/GC.c index 0dc92a29a0..0edc5f72ca 100644 --- a/rts/sm/GC.c +++ b/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> @@ -903,6 +905,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); |