Add spark counter tracing

A new eventlog event containing 7 spark counters/statistics: sparks
created, dud, overflowed, converted, GC'd, fizzled and remaining.
These are maintained and logged separately for each capability.
We log them at startup, on each GC (minor and major) and on shutdown.

8 files changed, 109 insertions, 19 deletions

diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h
index 1bbb2f0074..1ea8d67e73 100644
--- a/includes/rts/EventLogFormat.h
+++ b/includes/rts/EventLogFormat.h
@@ -133,6 +133,7 @@
 #define EVENT_PROGRAM_ENV         31 /* (capset, environment_vector)  */
 #define EVENT_OSPROCESS_PID       32 /* (capset, pid)          */
 #define EVENT_OSPROCESS_PPID      33 /* (capset, parent_pid)   */
+#define EVENT_SPARK_COUNTERS      34 /* (crt,dud,ovf,cnv,fiz,gcd,rem) */
 
 
 /* Range 34 - 59 is available for new events */
@@ -146,7 +147,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_EVENT_TAGS            34
+#define NUM_EVENT_TAGS            35
 
 #if 0  /* DEPRECATED EVENTS: */
 /* ghc changed how it handles sparks so these are no longer applicable */
diff --git a/rts/Capability.c b/rts/Capability.c
index d8c3b2d53c..3c06f5adb5 100644
--- a/rts/Capability.c
+++ b/rts/Capability.c
@@ -265,6 +265,9 @@ initCapability( Capability *cap, nat i )
     cap->pinned_object_block = NULL;
 
     traceCapsetAssignCap(CAPSET_OSPROCESS_DEFAULT, i);
+#if defined(THREADED_RTS)
+    traceSparkCounters(cap);
+#endif
 }
 
 /* ---------------------------------------------------------------------------
@@ -829,7 +832,9 @@ shutdownCapability (Capability *cap,
     // threads performing foreign calls that will eventually try to 
     // return via resumeThread() and attempt to grab cap->lock.
     // closeMutex(&cap->lock);
-    
+
+    traceSparkCounters(cap);
+
 #endif /* THREADED_RTS */
 
     traceCapsetRemoveCap(CAPSET_OSPROCESS_DEFAULT, cap->no);
diff --git a/rts/RtsProbes.d b/rts/RtsProbes.d
index bd32fca385..cd3c0f73e6 100644
--- a/rts/RtsProbes.d
+++ b/rts/RtsProbes.d
@@ -67,4 +67,8 @@ provider HaskellEvent {
   probe capset__assign__cap(EventCapsetID, EventCapNo);
   probe capset__remove__cap(EventCapsetID, EventCapNo);
 
+  probe spark__counters(EventCapNo,
+                        StgWord, StgWord, StgWord
+                        StgWord, StgWord, StgWord
+                        StgWord);
 };
diff --git a/rts/Schedule.c b/rts/Schedule.c
index 222220053a..2a2cc22a66 100644
--- a/rts/Schedule.c
+++ b/rts/Schedule.c
@@ -1449,6 +1449,8 @@ delete_threads_and_gc:
 #endif
     traceEventGcEnd(cap);
 
+    traceSparkCounters(cap);
+
     if (recent_activity == ACTIVITY_INACTIVE && force_major)
     {
         // We are doing a GC because the system has been idle for a
diff --git a/rts/Trace.c b/rts/Trace.c
index 70f4a39742..0c32737e1b 100644
--- a/rts/Trace.c
+++ b/rts/Trace.c
@@ -335,6 +335,22 @@ void traceOSProcessInfo_(void) {
     }
 }
 
+void traceSparkCounters_ (Capability *cap,
+                          SparkCounters counters,
+                          StgWord remaining)
+{
+#ifdef DEBUG
+    if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
+        /* we currently don't do debug tracing of spark stats but we must
+           test for TRACE_STDERR because of the !eventlog_enabled case. */
+    } else
+#endif
+    {
+        postSparkCountersEvent(cap, counters, remaining);
+    }
+}
+
+
 void traceEvent_ (Capability *cap, EventTypeNum tag)
 {
 #ifdef DEBUG
diff --git a/rts/Trace.h b/rts/Trace.h
index dd396904e7..910afbdaf8 100644
--- a/rts/Trace.h
+++ b/rts/Trace.h
@@ -184,6 +184,10 @@ void traceCapsetModify_ (EventTypeNum tag,
 
 void traceOSProcessInfo_ (void);
 
+void traceSparkCounters_ (Capability *cap,
+                          SparkCounters counters,
+                          StgWord remaining);
+
 #else /* !TRACING */
 
 #define traceSchedEvent(cap, tag, tso, other) /* nothing */
@@ -197,6 +201,7 @@ void traceOSProcessInfo_ (void);
 INLINE_HEADER void traceEventStartup_ (int n_caps STG_UNUSED) {};
 #define traceCapsetModify_(tag, capset, other) /* nothing */
 #define traceOSProcessInfo_() /* nothing */
+#define traceSparkCounters_(cap, counters, remaining) /* nothing */
 
 #endif /* TRACING */
 
@@ -262,6 +267,8 @@ INLINE_HEADER void dtraceStartup (int num_caps) {
     HASKELLEVENT_CAPSET_ASSIGN_CAP(capset, capno)
 #define dtraceCapsetRemoveCap(capset, capno)            \
     HASKELLEVENT_CAPSET_REMOVE_CAP(capset, capno)
+#define dtraceSparkCounters(cap, a, b, c, d, e, f, g) \
+    HASKELLEVENT_SPARK_COUNTERS(cap, a, b, c, d, e, f, g)
 
 #else /* !defined(DTRACE) */
 
@@ -288,6 +295,7 @@ INLINE_HEADER void dtraceStartup (int num_caps STG_UNUSED) {};
 #define dtraceCapsetDelete(capset)                      /* nothing */
 #define dtraceCapsetAssignCap(capset, capno)            /* nothing */
 #define dtraceCapsetRemoveCap(capset, capno)            /* nothing */
+#define dtraceSparkCounters(cap, a, b, c, d, e, f, g)   /* nothing */
 
 #endif
 
@@ -352,22 +360,6 @@ INLINE_HEADER void traceEventMigrateThread(Capability *cap     STG_UNUSED,
                         (EventCapNo)new_cap);
 }
 
-INLINE_HEADER void traceEventRunSpark(Capability *cap STG_UNUSED, 
-                                      StgTSO     *tso STG_UNUSED)
-{
-    traceSchedEvent(cap, EVENT_RUN_SPARK, tso, 0);
-    dtraceRunSpark((EventCapNo)cap->no, (EventThreadID)tso->id);
-}
-
-INLINE_HEADER void traceEventStealSpark(Capability *cap        STG_UNUSED, 
-                                        StgTSO     *tso        STG_UNUSED,
-                                        nat         victim_cap STG_UNUSED)
-{
-    traceSchedEvent(cap, EVENT_STEAL_SPARK, tso, victim_cap);
-    dtraceStealSpark((EventCapNo)cap->no, (EventThreadID)tso->id,
-                     (EventCapNo)victim_cap);
-}
-
 INLINE_HEADER void traceEventShutdown(Capability *cap STG_UNUSED)
 {
     traceSchedEvent(cap, EVENT_SHUTDOWN, 0, 0);
@@ -407,6 +399,22 @@ INLINE_HEADER void traceEventRequestParGc(Capability *cap STG_UNUSED)
     dtraceRequestParGc((EventCapNo)cap->no);
 }
 
+INLINE_HEADER void traceEventRunSpark(Capability *cap STG_UNUSED, 
+                                      StgTSO     *tso STG_UNUSED)
+{
+    traceSchedEvent(cap, EVENT_RUN_SPARK, tso, 0);
+    dtraceRunSpark((EventCapNo)cap->no, (EventThreadID)tso->id);
+}
+
+INLINE_HEADER void traceEventStealSpark(Capability *cap        STG_UNUSED, 
+                                        StgTSO     *tso        STG_UNUSED,
+                                        nat         victim_cap STG_UNUSED)
+{
+    traceSchedEvent(cap, EVENT_STEAL_SPARK, tso, victim_cap);
+    dtraceStealSpark((EventCapNo)cap->no, (EventThreadID)tso->id,
+                     (EventCapNo)victim_cap);
+}
+
 INLINE_HEADER void traceEventCreateSparkThread(Capability  *cap      STG_UNUSED, 
                                                StgThreadID spark_tid STG_UNUSED)
 {
@@ -480,6 +488,24 @@ INLINE_HEADER void traceOSProcessInfo(void)
      * is available to DTrace directly */
 }
 
+INLINE_HEADER void traceSparkCounters(Capability *cap STG_UNUSED)
+{
+#ifdef THREADED_RTS
+    if (RTS_UNLIKELY(TRACE_sched)) {
+        traceSparkCounters_(cap, cap->spark_stats, sparkPoolSize(cap->sparks));
+    }
+#endif
+    dtraceSparkCounters((EventCapNo)cap->no,
+                        cap->spark_stats.created,
+                        cap->spark_stats.dud,
+                        cap->spark_stats.overflowed,
+                        cap->spark_stats.converted,
+                        cap->spark_stats.gcd,
+                        cap->spark_stats.fizzled,
+                        sparkPoolSize(cap->sparks));
+}
+
+
 #include "EndPrivate.h"
 
 #endif /* TRACE_H */
diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c
index cea313e660..1e63a94c88 100644
--- a/rts/eventlog/EventLog.c
+++ b/rts/eventlog/EventLog.c
@@ -84,7 +84,8 @@ char *EventDesc[] = {
   [EVENT_PROGRAM_ARGS]        = "Program arguments",
   [EVENT_PROGRAM_ENV]         = "Program environment variables",
   [EVENT_OSPROCESS_PID]       = "Process ID",
-  [EVENT_OSPROCESS_PPID]      = "Parent process ID"
+  [EVENT_OSPROCESS_PPID]      = "Parent process ID",
+  [EVENT_SPARK_COUNTERS]      = "Spark counters"
 };
 
 // Event type. 
@@ -314,6 +315,10 @@ initEventLogging(void)
             eventTypes[t].size = 0xffff;
             break;
 
+        case EVENT_SPARK_COUNTERS:   // (cap, 7*counter)
+            eventTypes[t].size = 7 * sizeof(StgWord64);
+            break;
+
         case EVENT_BLOCK_MARKER:
             eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp) + 
                 sizeof(EventCapNo);
@@ -478,6 +483,30 @@ postSchedEvent (Capability *cap,
     }
 }
 
+void
+postSparkCountersEvent (Capability *cap, 
+                        SparkCounters counters,
+                        StgWord remaining)
+{
+    EventsBuf *eb;
+
+    eb = &capEventBuf[cap->no];
+
+    if (!hasRoomForEvent(eb, EVENT_SPARK_COUNTERS)) {
+        // Flush event buffer to make room for new event.
+        printAndClearEventBuf(eb);
+    }
+    
+    postEventHeader(eb, EVENT_SPARK_COUNTERS);
+    postWord64(eb,counters.created);
+    postWord64(eb,counters.dud);
+    postWord64(eb,counters.overflowed);
+    postWord64(eb,counters.converted);
+    postWord64(eb,counters.gcd);
+    postWord64(eb,counters.fizzled);
+    postWord64(eb,remaining);
+}
+
 void postCapsetModifyEvent (EventTypeNum tag,
                             EventCapsetID capset,
                             StgWord32 other)
diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h
index 602ac2c87b..431292732f 100644
--- a/rts/eventlog/EventLog.h
+++ b/rts/eventlog/EventLog.h
@@ -69,6 +69,13 @@ void postCapsetVecEvent (EventTypeNum tag,
                          int argc,
                          char *msg[]);
 
+/*
+ * Post an event with several counters relating to `par` sparks.
+ */
+void postSparkCountersEvent (Capability *cap, 
+                             SparkCounters counters,
+                             StgWord remaining);
+
 #else /* !TRACING */
 
 INLINE_HEADER void postSchedEvent (Capability *cap  STG_UNUSED,