Add events to show when GC threads are idle/working

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) */

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)
 {

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 */

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)

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 */ }

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 @@ scavenge_until_all_done (void)
     // 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 @@ scavenge_until_all_done (void)
         // 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)