From 1f56fae4a10f7fb56b8fbab5ab9ad95add1ed1dd Mon Sep 17 00:00:00 2001 From: Simon Marlow Date: Thu, 15 Oct 2009 10:02:12 +0000 Subject: [PATCH] Add events to show when GC threads are idle/working --- includes/rts/EventLogFormat.h | 5 ++++- rts/Trace.c | 21 +++++++++++++++++++++ rts/Trace.h | 12 ++++++++++++ rts/eventlog/EventLog.c | 21 +++++++++++++++++++++ rts/eventlog/EventLog.h | 12 +++++++++++- rts/sm/GC.c | 11 ++++++----- 6 files changed, 75 insertions(+), 7 deletions(-) diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h index eaad0f2..ced4d10 100644 --- a/includes/rts/EventLogFormat.h +++ b/includes/rts/EventLogFormat.h @@ -117,8 +117,11 @@ #define EVENT_STARTUP 17 /* (num_capabilities) */ #define EVENT_BLOCK_MARKER 18 /* (size, end_time, capability) */ #define EVENT_USER_MSG 19 /* (message ...) */ +#define EVENT_GC_IDLE 20 /* () */ +#define EVENT_GC_WORK 21 /* () */ +#define EVENT_GC_DONE 22 /* () */ -#define NUM_EVENT_TAGS 20 +#define NUM_EVENT_TAGS 23 #if 0 /* DEPRECATED EVENTS: */ #define EVENT_CREATE_SPARK 13 /* (cap, thread) */ diff --git a/rts/Trace.c b/rts/Trace.c index 81a2eb2..7cfb78c 100644 --- a/rts/Trace.c +++ b/rts/Trace.c @@ -193,6 +193,15 @@ static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag, case EVENT_GC_END: // (cap) debugBelch("cap %d: finished GC\n", cap->no); break; + case EVENT_GC_IDLE: // (cap) + debugBelch("cap %d: GC idle\n", cap->no); + break; + case EVENT_GC_WORK: // (cap) + debugBelch("cap %d: GC working\n", cap->no); + break; + case EVENT_GC_DONE: // (cap) + debugBelch("cap %d: GC done\n", cap->no); + break; default: debugBelch("cap %2d: thread %lu: event %d\n\n", cap->no, (lnat)tso->id, tag); @@ -216,6 +225,18 @@ void traceSchedEvent_ (Capability *cap, EventTypeNum tag, } } +void traceEvent_ (Capability *cap, EventTypeNum tag) +{ +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) { + traceSchedEvent_stderr(cap, tag, 0, 0); + } else +#endif + { + postEvent(cap,tag); + } +} + #ifdef DEBUG static void traceCap_stderr(Capability *cap, char *msg, va_list ap) { diff --git a/rts/Trace.h b/rts/Trace.h index f422b5f..21828d2 100644 --- a/rts/Trace.h +++ b/rts/Trace.h @@ -79,6 +79,17 @@ void traceEnd (void); void traceSchedEvent_ (Capability *cap, EventTypeNum tag, StgTSO *tso, StgWord64 other); + +/* + * Record a nullary event + */ +#define traceEvent(cap, tag) \ + if (RTS_UNLIKELY(TRACE_sched)) { \ + traceEvent_(cap, tag); \ + } + +void traceEvent_ (Capability *cap, EventTypeNum tag); + // variadic macros are C99, and supported by gcc. However, the // ##__VA_ARGS syntax is a gcc extension, which allows the variable // argument list to be empty (see gcc docs for details). @@ -133,6 +144,7 @@ void traceThreadStatus_ (StgTSO *tso); #else /* !TRACING */ #define traceSchedEvent(cap, tag, tso, other) /* nothing */ +#define traceEvent(cap, tag) /* nothing */ #define traceCap(class, cap, msg, ...) /* nothing */ #define trace(class, msg, ...) /* nothing */ #define debugTrace(class, str, ...) /* nothing */ diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 65eff8a..a48c92e 100644 --- a/rts/eventlog/EventLog.c +++ b/rts/eventlog/EventLog.c @@ -64,6 +64,9 @@ char *EventDesc[] = { [EVENT_LOG_MSG] = "Log message", [EVENT_USER_MSG] = "User message", [EVENT_STARTUP] = "Startup", + [EVENT_GC_IDLE] = "GC idle", + [EVENT_GC_WORK] = "GC working", + [EVENT_GC_DONE] = "GC done", [EVENT_BLOCK_MARKER] = "Block marker" }; @@ -239,6 +242,9 @@ initEventLogging(void) case EVENT_GC_START: // (cap) case EVENT_GC_END: // (cap) case EVENT_STARTUP: + case EVENT_GC_IDLE: + case EVENT_GC_WORK: + case EVENT_GC_DONE: eventTypes[t].size = 0; break; @@ -393,6 +399,21 @@ postSchedEvent (Capability *cap, } } +void +postEvent (Capability *cap, EventTypeNum tag) +{ + EventsBuf *eb; + + eb = &capEventBuf[cap->no]; + + if (!hasRoomForEvent(eb, tag)) { + // Flush event buffer to make room for new event. + printAndClearEventBuf(eb); + } + + postEventHeader(eb, tag); +} + #define BUF 512 void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap) diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h index 557ee77..e2b8043 100644 --- a/rts/eventlog/EventLog.h +++ b/rts/eventlog/EventLog.h @@ -26,11 +26,17 @@ void endEventLogging(void); void freeEventLogging(void); /* - * Post an event to the capability's event buffer. + * Post a scheduler event to the capability's event buffer (an event + * that has an associated thread). */ void postSchedEvent(Capability *cap, EventTypeNum tag, StgThreadID id, StgWord64 other); +/* + * Post a nullary event. + */ +void postEvent(Capability *cap, EventTypeNum tag); + void postMsg(char *msg, va_list ap); void postUserMsg(Capability *cap, char *msg); @@ -45,6 +51,10 @@ INLINE_HEADER void postSchedEvent (Capability *cap STG_UNUSED, StgWord64 other STG_UNUSED) { /* nothing */ } +INLINE_HEADER void postEvent (Capability *cap STG_UNUSED, + EventTypeNum tag STG_UNUSED) +{ /* nothing */ } + INLINE_HEADER void postMsg (char *msg STG_UNUSED, va_list ap STG_UNUSED) { /* nothing */ } diff --git a/rts/sm/GC.c b/rts/sm/GC.c index 07cf2b5..5097483 100644 --- a/rts/sm/GC.c +++ b/rts/sm/GC.c @@ -1020,9 +1020,10 @@ scavenge_until_all_done (void) { nat r; - debugTrace(DEBUG_gc, "GC thread %d working", gct->thread_index); loop: + traceEvent(&capabilities[gct->thread_index], EVENT_GC_WORK); + #if defined(THREADED_RTS) if (n_gc_threads > 1) { scavenge_loop(); @@ -1036,8 +1037,9 @@ loop: // scavenge_loop() only exits when there's no work to do r = dec_running(); - debugTrace(DEBUG_gc, "GC thread %d idle (%d still running)", - gct->thread_index, r); + traceEvent(&capabilities[gct->thread_index], EVENT_GC_IDLE); + + debugTrace(DEBUG_gc, "%d GC threads still running", r); while (gc_running_threads != 0) { // usleep(1); @@ -1051,8 +1053,7 @@ loop: // scavenge_loop() to perform any pending work. } - // All threads are now stopped - debugTrace(DEBUG_gc, "GC thread %d finished.", gct->thread_index); + traceEvent(&capabilities[gct->thread_index], EVENT_GC_DONE); } #if defined(THREADED_RTS) -- 1.7.10.4