From a609027da31c7c9103d8b9741ba3fc6807b7b7b9 Mon Sep 17 00:00:00 2001 From: Duncan Coutts Date: Mon, 15 Oct 2012 00:52:32 +0100 Subject: [PATCH] Add a new traceMarker# primop for use in profiling output In time-based profiling visualisations (e.g. heap profiles and ThreadScope) it would be useful to be able to mark particular points in the execution and have those points in time marked in the visualisation. The traceMarker# primop currently emits an event into the eventlog. In principle it could be extended to do something in the heap profiling too. --- compiler/prelude/primops.txt.pp | 11 +++++++++++ includes/rts/EventLogFormat.h | 6 +++--- includes/stg/MiscClosures.h | 1 + rts/Linker.c | 1 + rts/PrimOps.cmm | 25 +++++++++++++++++++++++++ rts/RtsProbes.d | 1 + rts/Trace.c | 22 ++++++++++++++++++++++ rts/Trace.h | 10 ++++++++++ rts/eventlog/EventLog.c | 23 +++++++++++++++++++++++ rts/eventlog/EventLog.h | 2 ++ 10 files changed, 99 insertions(+), 3 deletions(-) diff --git a/compiler/prelude/primops.txt.pp b/compiler/prelude/primops.txt.pp index 2e56e981a5..7730106c46 100644 --- a/compiler/prelude/primops.txt.pp +++ b/compiler/prelude/primops.txt.pp @@ -2203,6 +2203,17 @@ primop TraceEventOp "traceEvent#" GenPrimOp has_side_effects = True out_of_line = True +primop TraceMarkerOp "traceMarker#" GenPrimOp + Addr# -> State# s -> State# s + { Emits a marker event via the RTS tracing framework. The contents + of the event is the zero-terminated byte string passed as the first + argument. The event will be emitted either to the .eventlog file, + or to stderr, depending on the runtime RTS flags. } + with + has_side_effects = True + out_of_line = True + + ------------------------------------------------------------------------ --- --- ------------------------------------------------------------------------ diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h index 82d3f683cc..e08a44996f 100644 --- a/includes/rts/EventLogFormat.h +++ b/includes/rts/EventLogFormat.h @@ -161,8 +161,8 @@ #define EVENT_TASK_CREATE 55 /* (taskID, cap, tid) */ #define EVENT_TASK_MIGRATE 56 /* (taskID, cap, new_cap) */ #define EVENT_TASK_DELETE 57 /* (taskID) */ - -/* Range 58 - 59 is available for new GHC and common events. */ +#define EVENT_USER_MARKER 58 /* (marker_name) */ +/* 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/ @@ -177,7 +177,7 @@ * 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 58 +#define NUM_GHC_EVENT_TAGS 59 #if 0 /* DEPRECATED EVENTS: */ /* we don't actually need to record the thread, it's implicit */ diff --git a/includes/stg/MiscClosures.h b/includes/stg/MiscClosures.h index b7b24a8632..760a59da49 100644 --- a/includes/stg/MiscClosures.h +++ b/includes/stg/MiscClosures.h @@ -431,6 +431,7 @@ RTS_FUN_DECL(stg_noDuplicatezh); RTS_FUN_DECL(stg_traceCcszh); RTS_FUN_DECL(stg_traceEventzh); +RTS_FUN_DECL(stg_traceMarkerzh); /* Other misc stuff */ // See wiki:Commentary/Compiler/Backends/PprC#Prototypes diff --git a/rts/Linker.c b/rts/Linker.c index 2d7e7d78a7..dca8a52813 100644 --- a/rts/Linker.c +++ b/rts/Linker.c @@ -1309,6 +1309,7 @@ typedef struct _RtsSymbolVal { SymI_HasProto(n_capabilities) \ SymI_HasProto(stg_traceCcszh) \ SymI_HasProto(stg_traceEventzh) \ + SymI_HasProto(stg_traceMarkerzh) \ SymI_HasProto(getMonotonicNSec) \ SymI_HasProto(lockFile) \ SymI_HasProto(unlockFile) \ diff --git a/rts/PrimOps.cmm b/rts/PrimOps.cmm index 1a531b2149..fb46cee0b5 100644 --- a/rts/PrimOps.cmm +++ b/rts/PrimOps.cmm @@ -2034,3 +2034,28 @@ stg_traceEventzh ( W_ msg ) return (); } +// Same code as stg_traceEventzh above but a different kind of event +// Before changing this code, read the comments in the impl above +stg_traceMarkerzh ( W_ msg ) +{ +#if defined(TRACING) || defined(DEBUG) + + ccall traceUserMarker(MyCapability() "ptr", msg "ptr"); + +#elif defined(DTRACE) + + W_ enabled; + +#if !defined(solaris2_TARGET_OS) + (enabled) = ccall __dtrace_isenabled$HaskellEvent$user__marker$v1(); +#else + enabled = 1; +#endif + if (enabled != 0) { + ccall dtraceUserMarkerWrapper(MyCapability() "ptr", msg "ptr"); + } + +#endif + return (); +} + diff --git a/rts/RtsProbes.d b/rts/RtsProbes.d index fd47b7574d..13f40f8201 100644 --- a/rts/RtsProbes.d +++ b/rts/RtsProbes.d @@ -99,4 +99,5 @@ provider HaskellEvent { /* probe log__msg (char *); */ /* we don't need EVENT_BLOCK_MARKER with dtrace */ probe user__msg (EventCapNo, char *); + probe user__marker (EventCapNo, char *); }; diff --git a/rts/Trace.c b/rts/Trace.c index 7a08c0f817..9da2115e2e 100644 --- a/rts/Trace.c +++ b/rts/Trace.c @@ -708,6 +708,28 @@ void traceUserMsg(Capability *cap, char *msg) traceFormatUserMsg(cap, "%s", msg); } +void traceUserMarker(Capability *cap, char *markername) +{ + /* Note: traceUserMarker is special since it has no wrapper (it's called + from cmm code), so we check eventlog_enabled and TRACE_user here. + */ +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR && TRACE_user) { + ACQUIRE_LOCK(&trace_utx); + tracePreface(); + debugBelch("cap %d: User marker: %s\n", cap->no, markername); + RELEASE_LOCK(&trace_utx); + } else +#endif + { + if (eventlog_enabled && TRACE_user) { + postUserMarker(cap, markername); + } + } + dtraceUserMarker(cap->no, markername); +} + + void traceThreadLabel_(Capability *cap, StgTSO *tso, char *label) diff --git a/rts/Trace.h b/rts/Trace.h index 4f1ac3bf0a..31aefcb58d 100644 --- a/rts/Trace.h +++ b/rts/Trace.h @@ -197,6 +197,12 @@ void trace_(char *msg, ...); */ void traceUserMsg(Capability *cap, char *msg); +/* + * A marker event emitted by the program + * Used by Debug.Trace.{traceMarker, traceMarkerIO} + */ +void traceUserMarker(Capability *cap, char *msg); + /* * An event to record a Haskell thread's label/name * Used by GHC.Conc.labelThread @@ -310,6 +316,7 @@ INLINE_HEADER void traceEventStartup_ (int n_caps STG_UNUSED) {}; #if !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) void dtraceUserMsgWrapper(Capability *cap, char *msg); +void dtraceUserMarkerWrapper(Capability *cap, char *msg); #endif /* !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) */ @@ -356,6 +363,8 @@ INLINE_HEADER void dtraceStartup (int num_caps) { HASKELLEVENT_CAP_DISABLE(cap) #define dtraceUserMsg(cap, msg) \ HASKELLEVENT_USER_MSG(cap, msg) +#define dtraceUserMarker(cap, msg) \ + HASKELLEVENT_USER_MARKER(cap, msg) #define dtraceGcIdle(cap) \ HASKELLEVENT_GC_IDLE(cap) #define dtraceGcWork(cap) \ @@ -435,6 +444,7 @@ INLINE_HEADER void dtraceStartup (int num_caps) { #define dtraceThreadLabel(cap, tso, label) /* nothing */ INLINE_HEADER void dtraceStartup (int num_caps STG_UNUSED) {}; #define dtraceUserMsg(cap, msg) /* nothing */ +#define dtraceUserMarker(cap, msg) /* nothing */ #define dtraceGcIdle(cap) /* nothing */ #define dtraceGcWork(cap) /* nothing */ #define dtraceGcDone(cap) /* nothing */ diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 81aaecb67d..ef6f69c6dd 100644 --- a/rts/eventlog/EventLog.c +++ b/rts/eventlog/EventLog.c @@ -80,6 +80,7 @@ char *EventDesc[] = { [EVENT_CREATE_SPARK_THREAD] = "Create spark thread", [EVENT_LOG_MSG] = "Log message", [EVENT_USER_MSG] = "User message", + [EVENT_USER_MARKER] = "User marker", [EVENT_GC_IDLE] = "GC idle", [EVENT_GC_WORK] = "GC working", [EVENT_GC_DONE] = "GC done", @@ -369,6 +370,7 @@ initEventLogging(void) case EVENT_LOG_MSG: // (msg) case EVENT_USER_MSG: // (msg) + case EVENT_USER_MARKER: // (markername) case EVENT_RTS_IDENTIFIER: // (capset, str) case EVENT_PROGRAM_ARGS: // (capset, strvec) case EVENT_PROGRAM_ENV: // (capset, strvec) @@ -1086,6 +1088,27 @@ void postEventStartup(EventCapNo n_caps) RELEASE_LOCK(&eventBufMutex); } +void postUserMarker(Capability *cap, char *markername) +{ + EventsBuf *eb; + int size = strlen(markername); + + eb = &capEventBuf[cap->no]; + + if (!hasRoomForVariableEvent(eb, size)){ + printAndClearEventBuf(eb); + + if (!hasRoomForVariableEvent(eb, size)){ + // Event size exceeds buffer size, bail out: + return; + } + } + + postEventHeader(eb, EVENT_USER_MARKER); + postPayloadSize(eb, size); + postBuf(eb, (StgWord8*) markername, size); +} + void postThreadLabel(Capability *cap, EventThreadID id, char *label) diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h index 5861f64757..85370e9843 100644 --- a/rts/eventlog/EventLog.h +++ b/rts/eventlog/EventLog.h @@ -49,6 +49,8 @@ void postUserMsg(Capability *cap, char *msg, va_list ap); void postCapMsg(Capability *cap, char *msg, va_list ap); +void postUserMarker(Capability *cap, char *markername); + void postEventStartup(EventCapNo n_caps); /* -- GitLab