Add eventlog/trace stuff for capabilities: create/delete/enable/disable

Now that we can adjust the number of capabilities on the fly, we need
this reflected in the eventlog. Previously the eventlog had a single
startup event that declared a static number of capabilities. Obviously
that's no good anymore.

For compatability we're keeping the EVENT_STARTUP but adding new
EVENT_CAP_CREATE/DELETE. The EVENT_CAP_DELETE is actually just the old
EVENT_SHUTDOWN but renamed and extended (using the existing mechanism
to extend eventlog events in a compatible way). So we now emit both
EVENT_STARTUP and EVENT_CAP_CREATE. One day we will drop EVENT_STARTUP.

Since reducing the number of capabilities at runtime does not really
delete them, it just disables them, then we also have new events for
disable/enable.

The old EVENT_SHUTDOWN was in the scheduler class of events. The new
EVENT_CAP_* events are in the unconditional class, along with the
EVENT_CAPSET_* ones. Knowing when capabilities are created and deleted
is crucial to making sense of eventlogs, you always want those events.
In any case, they're extremely low volume.

includes/rts/EventLogFormat.h

@@ -104,8 +104,7 @@
 #define EVENT_STOP_THREAD          2 /* (thread, status, blockinfo) */
 #define EVENT_THREAD_RUNNABLE      3 /* (thread)               */
 #define EVENT_MIGRATE_THREAD       4 /* (thread, new_cap)      */
-/* 5, 6 deprecated */
-#define EVENT_SHUTDOWN             7 /* ()                     */
+/* 5, 6, 7 deprecated */
 #define EVENT_THREAD_WAKEUP        8 /* (thread, other_cap)    */
 #define EVENT_GC_START             9 /* ()                     */
 #define EVENT_GC_END              10 /* ()                     */
@@ -114,6 +113,7 @@
 /* 13, 14 deprecated */
 #define EVENT_CREATE_SPARK_THREAD 15 /* (spark_thread)         */
 #define EVENT_LOG_MSG             16 /* (message ...)          */
+/* EVENT_STARTUP should be deprecated at some point */
 #define EVENT_STARTUP             17 /* (num_capabilities)     */
 #define EVENT_BLOCK_MARKER        18 /* (size, end_time, capability) */
 #define EVENT_USER_MSG            19 /* (message ...)          */
@@ -143,8 +143,12 @@
 #define EVENT_INTERN_STRING       42 /* (string, id) {not used by ghc} */
 #define EVENT_WALL_CLOCK_TIME     43 /* (capset, unix_epoch_seconds, nanoseconds) */
 #define EVENT_THREAD_LABEL        44 /* (thread, name_string)  */
+#define EVENT_CAP_CREATE          45 /* (cap)                  */
+#define EVENT_CAP_DELETE          46 /* (cap)                  */
+#define EVENT_CAP_DISABLE         47 /* (cap)                  */
+#define EVENT_CAP_ENABLE          48 /* (cap)                  */
 
-/* Range 45 - 59 is available for new GHC and common events */
+/* Range 49 - 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/
@@ -157,12 +161,14 @@
  * 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        45
+#define NUM_GHC_EVENT_TAGS        49
 
 #if 0  /* DEPRECATED EVENTS: */
 /* we don't actually need to record the thread, it's implicit */
 #define EVENT_RUN_SPARK            5 /* (thread)               */
 #define EVENT_STEAL_SPARK          6 /* (thread, victim_cap)   */
+/* shutdown replaced by EVENT_CAP_DELETE */
+#define EVENT_SHUTDOWN             7 /* ()                     */
 /* ghc changed how it handles sparks so these are no longer applicable */
 #define EVENT_CREATE_SPARK        13 /* (cap, thread) */
 #define EVENT_SPARK_TO_THREAD     14 /* (cap, thread, spark_thread) */

rts/Capability.c

@@ -281,6 +281,7 @@ initCapability( Capability *cap, nat i )
     cap->r.rCCCS = NULL;
 #endif
 
+    traceCapCreate(cap);
     traceCapsetAssignCap(CAPSET_OSPROCESS_DEFAULT, i);
     traceCapsetAssignCap(CAPSET_CLOCKDOMAIN_DEFAULT, i);
 #if defined(THREADED_RTS)
@@ -843,6 +844,8 @@ tryGrabCapability (Capability *cap, Task *task)
  *
  * ------------------------------------------------------------------------- */
 
+static void traceShutdownCapability (Capability *cap);
+
 void
 shutdownCapability (Capability *cap,
                     Task *task USED_IF_THREADS,
@@ -929,7 +932,7 @@ shutdownCapability (Capability *cap,
             continue;
         }
 
-        traceEventShutdown(cap);
+        traceShutdownCapability(cap);
 	RELEASE_LOCK(&cap->lock);
 	break;
     }
@@ -941,12 +944,20 @@ shutdownCapability (Capability *cap,
     // return via resumeThread() and attempt to grab cap->lock.
     // closeMutex(&cap->lock);
 
-    traceSparkCounters(cap);
-
-#endif /* THREADED_RTS */
+#else /* THREADED_RTS */
+    traceShutdownCapability(cap);
+#endif
+}
 
+static void
+traceShutdownCapability (Capability *cap)
+{
+#if defined(THREADED_RTS)
+    traceSparkCounters(cap);
+#endif
     traceCapsetRemoveCap(CAPSET_OSPROCESS_DEFAULT, cap->no);
     traceCapsetRemoveCap(CAPSET_CLOCKDOMAIN_DEFAULT, cap->no);
+    traceCapDelete(cap);
 }
 
 void

rts/RtsProbes.d

@@ -43,29 +43,33 @@ provider HaskellEvent {
   probe stop__thread (EventCapNo, EventThreadID, EventThreadStatus, EventThreadID);
   probe thread__runnable (EventCapNo, EventThreadID);
   probe migrate__thread (EventCapNo, EventThreadID, EventCapNo);
-  probe shutdown (EventCapNo);
   probe thread_wakeup (EventCapNo, EventThreadID, EventCapNo);
+  probe create__spark__thread (EventCapNo, EventThreadID);
+  probe thread__label (EventCapNo, EventThreadID, char *);
+
+  /* GC and heap events */
   probe gc__start (EventCapNo);
   probe gc__end (EventCapNo);
   probe request__seq__gc (EventCapNo);
   probe request__par__gc (EventCapNo);
-  probe create__spark__thread (EventCapNo, EventThreadID);
-  probe thread__label (EventCapNo, EventThreadID, char *);
-
-  /* other events */
-/* This one doesn't seem to be used at all at the moment: */
-/*  probe log__msg (char *); */
-  probe startup (EventCapNo);
-  /* we don't need EVENT_BLOCK_MARKER with dtrace */
-  probe user__msg (EventCapNo, char *);
   probe gc__idle (EventCapNo);
   probe gc__work (EventCapNo);
   probe gc__done (EventCapNo);
+
+  /* capability events */
+  probe startup (EventCapNo);
+  probe cap__create (EventCapNo);
+  probe cap__delete (EventCapNo);
+  probe cap__enable (EventCapNo);
+  probe cap__disable (EventCapNo);
+
+  /* capset info events */
   probe capset__create(EventCapsetID, EventCapsetType);
   probe capset__delete(EventCapsetID);
   probe capset__assign__cap(EventCapsetID, EventCapNo);
   probe capset__remove__cap(EventCapsetID, EventCapNo);
 
+  /* spark events */
   probe spark__counters(EventCapNo,
                         StgWord, StgWord, StgWord,
                         StgWord, StgWord, StgWord,
@@ -78,4 +82,10 @@ provider HaskellEvent {
   probe spark__steal    (EventCapNo, EventCapNo);
   probe spark__fizzle   (EventCapNo);
   probe spark__gc       (EventCapNo);
+
+  /* other events */
+/* This one doesn't seem to be used at all at the moment: */
+/*  probe log__msg (char *); */
+  /* we don't need EVENT_BLOCK_MARKER with dtrace */
+  probe user__msg (EventCapNo, char *);
 };

rts/Schedule.c

@@ -1985,6 +1985,7 @@ setNumCapabilities (nat new_n_capabilities USED_IF_THREADS)
         //
         for (n = new_n_capabilities; n < enabled_capabilities; n++) {
             capabilities[n].disabled = rtsTrue;
+            traceCapDisable(&capabilities[n]);
         }
         enabled_capabilities = new_n_capabilities;
     }
@@ -1996,6 +1997,7 @@ setNumCapabilities (nat new_n_capabilities USED_IF_THREADS)
         for (n = enabled_capabilities;
              n < new_n_capabilities && n < n_capabilities; n++) {
             capabilities[n].disabled = rtsFalse;
+            traceCapEnable(&capabilities[n]);
         }
         enabled_capabilities = n;
 
@@ -2003,7 +2005,8 @@ setNumCapabilities (nat new_n_capabilities USED_IF_THREADS)
 #if defined(TRACING)
             // Allocate eventlog buffers for the new capabilities.  Note this
             // must be done before calling moreCapabilities(), because that
-            // will emit events to add the new capabilities to capsets.
+            // will emit events about creating the new capabilities and adding
+            // them to existing capsets.
             tracingAddCapapilities(n_capabilities, new_n_capabilities);
 #endif
 

rts/Trace.c

@@ -228,9 +228,6 @@ static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag,
                        cap->no, (lnat)tso->id, thread_stop_reasons[info1]);
         }
         break;
-    case EVENT_SHUTDOWN:        // (cap)
-        debugBelch("cap %d: shutting down\n", cap->no);
-        break;
     default:
         debugBelch("cap %d: thread %lu: event %d\n\n", 
                    cap->no, (lnat)tso->id, tag);
@@ -304,9 +301,41 @@ void traceGcEvent_ (Capability *cap, EventTypeNum tag)
     }
 }
 
-void traceCapsetEvent_ (EventTypeNum tag,
-                        CapsetID capset,
-                        StgWord info)
+void traceCapEvent (Capability   *cap,
+                    EventTypeNum  tag)
+{
+#ifdef DEBUG
+    if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
+        ACQUIRE_LOCK(&trace_utx);
+
+        tracePreface();
+        switch (tag) {
+        case EVENT_CAP_CREATE:   // (cap)
+            debugBelch("cap %d: initialised\n", cap->no);
+            break;
+        case EVENT_CAP_DELETE:   // (cap)
+            debugBelch("cap %d: shutting down\n", cap->no);
+            break;
+        case EVENT_CAP_ENABLE:   // (cap)
+            debugBelch("cap %d: enabling capability\n", cap->no);
+            break;
+        case EVENT_CAP_DISABLE:  // (cap)
+            debugBelch("cap %d: disabling capability\n", cap->no);
+            break;
+        }
+        RELEASE_LOCK(&trace_utx);
+    } else
+#endif
+    {
+        if (eventlog_enabled) {
+            postCapEvent(tag, (EventCapNo)cap->no);
+        }
+    }
+}
+
+void traceCapsetEvent (EventTypeNum tag,
+                       CapsetID     capset,
+                       StgWord      info)
 {
 #ifdef DEBUG
     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR && TRACE_sched)

rts/Trace.h

@@ -199,17 +199,20 @@ void traceThreadStatus_ (StgTSO *tso);
 void traceEventStartup_ (int n_caps);
 
 /*
- * Events for describing capability sets in the eventlog
+ * Events for describing capabilities and capability sets in the eventlog
  *
  * Note: unlike other events, these are not conditional on TRACE_sched or
- * similar because they are not "real" events themselves but provide
- * information and context for other "real" events. Other events depend on
- * the capset info events so for simplicity, rather than working out if
- * they're necessary we always emit them. They should be very low volume.
+ * similar because capabilities and capability sets are important
+ * context for other events. Since other events depend on these events
+ * then for simplicity we always emit them, rather than working out if
+ * they're necessary . They should be very low volume.
  */
-void traceCapsetEvent_ (EventTypeNum tag,
-                        CapsetID capset,
-                        StgWord info);
+void traceCapEvent (Capability   *cap,
+                    EventTypeNum  tag);
+
+void traceCapsetEvent (EventTypeNum tag,
+                       CapsetID     capset,
+                       StgWord      info);
 
 void traceWallClockTime_(void);
 
@@ -233,7 +236,8 @@ void traceSparkCounters_ (Capability *cap,
 #define traceThreadStatus(class, tso) /* nothing */
 #define traceThreadLabel_(cap, tso, label) /* nothing */
 INLINE_HEADER void traceEventStartup_ (int n_caps STG_UNUSED) {};
-#define traceCapsetEvent_(tag, capset, info) /* nothing */
+#define traceCapEvent(cap, tag) /* nothing */
+#define traceCapsetEvent(tag, capset, info) /* nothing */
 #define traceWallClockTime_() /* nothing */
 #define traceOSProcessInfo_() /* nothing */
 #define traceSparkCounters_(cap, counters, remaining) /* nothing */
@@ -265,8 +269,6 @@ void dtraceUserMsgWrapper(Capability *cap, char *msg);
     HASKELLEVENT_THREAD_RUNNABLE(cap, tid)
 #define dtraceMigrateThread(cap, tid, new_cap)          \
     HASKELLEVENT_MIGRATE_THREAD(cap, tid, new_cap)
-#define dtraceShutdown(cap)                             \
-    HASKELLEVENT_SHUTDOWN(cap)
 #define dtraceThreadWakeup(cap, tid, other_cap)         \
     HASKELLEVENT_THREAD_WAKEUP(cap, tid, other_cap)
 #define dtraceGcStart(cap)                              \
@@ -284,6 +286,14 @@ void dtraceUserMsgWrapper(Capability *cap, char *msg);
 INLINE_HEADER void dtraceStartup (int num_caps) {
     HASKELLEVENT_STARTUP(num_caps);
 }
+#define dtraceCapCreate(cap)                            \
+    HASKELLEVENT_CAP_CREATE(cap)
+#define dtraceCapDelete(cap)                            \
+    HASKELLEVENT_CAP_DELETE(cap)
+#define dtraceCapEnable(cap)                            \
+    HASKELLEVENT_CAP_ENABLE(cap)
+#define dtraceCapDisable(cap)                           \
+    HASKELLEVENT_CAP_DISABLE(cap)
 #define dtraceUserMsg(cap, msg)                         \
     HASKELLEVENT_USER_MSG(cap, msg)
 #define dtraceGcIdle(cap)                               \
@@ -324,7 +334,6 @@ INLINE_HEADER void dtraceStartup (int num_caps) {
 #define dtraceStopThread(cap, tid, status, info)        /* nothing */
 #define dtraceThreadRunnable(cap, tid)                  /* nothing */
 #define dtraceMigrateThread(cap, tid, new_cap)          /* nothing */
-#define dtraceShutdown(cap)                             /* nothing */
 #define dtraceThreadWakeup(cap, tid, other_cap)         /* nothing */
 #define dtraceGcStart(cap)                              /* nothing */
 #define dtraceGcEnd(cap)                                /* nothing */
@@ -337,6 +346,10 @@ INLINE_HEADER void dtraceStartup (int num_caps STG_UNUSED) {};
 #define dtraceGcIdle(cap)                               /* nothing */
 #define dtraceGcWork(cap)                               /* nothing */
 #define dtraceGcDone(cap)                               /* nothing */
+#define dtraceCapCreate(cap)                            /* nothing */
+#define dtraceCapDelete(cap)                            /* nothing */
+#define dtraceCapEnable(cap)                            /* nothing */
+#define dtraceCapDisable(cap)                           /* nothing */
 #define dtraceCapsetCreate(capset, capset_type)         /* nothing */
 #define dtraceCapsetDelete(capset)                      /* nothing */
 #define dtraceCapsetAssignCap(capset, capno)            /* nothing */
@@ -413,10 +426,28 @@ INLINE_HEADER void traceEventMigrateThread(Capability *cap     STG_UNUSED,
                         (EventCapNo)new_cap);
 }
 
-INLINE_HEADER void traceEventShutdown(Capability *cap STG_UNUSED)
+INLINE_HEADER void traceCapCreate(Capability *cap STG_UNUSED)
+{
+    traceCapEvent(cap, EVENT_CAP_CREATE);
+    dtraceCapCreate((EventCapNo)cap->no);
+}
+
+INLINE_HEADER void traceCapDelete(Capability *cap STG_UNUSED)
+{
+    traceCapEvent(cap, EVENT_CAP_DELETE);
+    dtraceCapDelete((EventCapNo)cap->no);
+}
+
+INLINE_HEADER void traceCapEnable(Capability *cap STG_UNUSED)
+{
+    traceCapEvent(cap, EVENT_CAP_ENABLE);
+    dtraceCapEnable((EventCapNo)cap->no);
+}
+
+INLINE_HEADER void traceCapDisable(Capability *cap STG_UNUSED)
 {
-    traceSchedEvent(cap, EVENT_SHUTDOWN, 0, 0);
-    dtraceShutdown((EventCapNo)cap->no);
+    traceCapEvent(cap, EVENT_CAP_DISABLE);
+    dtraceCapDisable((EventCapNo)cap->no);
 }
 
 INLINE_HEADER void traceEventThreadWakeup(Capability *cap       STG_UNUSED, 
@@ -497,27 +528,27 @@ INLINE_HEADER void traceEventStartup(void)
 INLINE_HEADER void traceCapsetCreate(CapsetID   capset      STG_UNUSED,
                                      CapsetType capset_type STG_UNUSED)
 {
-    traceCapsetEvent_(EVENT_CAPSET_CREATE, capset, capset_type);
+    traceCapsetEvent(EVENT_CAPSET_CREATE, capset, capset_type);
     dtraceCapsetCreate(capset, capset_type);
 }
 
 INLINE_HEADER void traceCapsetDelete(CapsetID capset STG_UNUSED)
 {
-    traceCapsetEvent_(EVENT_CAPSET_DELETE, capset, 0);
+    traceCapsetEvent(EVENT_CAPSET_DELETE, capset, 0);
     dtraceCapsetDelete(capset);
 }
 
 INLINE_HEADER void traceCapsetAssignCap(CapsetID capset STG_UNUSED,
                                         nat      capno  STG_UNUSED)
 {
-    traceCapsetEvent_(EVENT_CAPSET_ASSIGN_CAP, capset, capno);
+    traceCapsetEvent(EVENT_CAPSET_ASSIGN_CAP, capset, capno);
     dtraceCapsetAssignCap(capset, capno);
 }
 
 INLINE_HEADER void traceCapsetRemoveCap(CapsetID capset STG_UNUSED,
                                         nat      capno  STG_UNUSED)
 {
-    traceCapsetEvent_(EVENT_CAPSET_REMOVE_CAP, capset, capno);
+    traceCapsetEvent(EVENT_CAPSET_REMOVE_CAP, capset, capno);
     dtraceCapsetRemoveCap(capset, capno);
 }
 

rts/eventlog/EventLog.c

@@ -60,9 +60,13 @@ char *EventDesc[] = {
   [EVENT_STOP_THREAD]         = "Stop thread",
   [EVENT_THREAD_RUNNABLE]     = "Thread runnable",
   [EVENT_MIGRATE_THREAD]      = "Migrate thread",
-  [EVENT_SHUTDOWN]            = "Shutdown",
   [EVENT_THREAD_WAKEUP]       = "Wakeup thread",
   [EVENT_THREAD_LABEL]        = "Thread label",
+  [EVENT_STARTUP]             = "Create capabilities",
+  [EVENT_CAP_CREATE]          = "Create capability",
+  [EVENT_CAP_DELETE]          = "Delete capability",
+  [EVENT_CAP_DISABLE]         = "Disable capability",
+  [EVENT_CAP_ENABLE]          = "Enable capability",
   [EVENT_GC_START]            = "Starting GC",
   [EVENT_GC_END]              = "Finished GC",
   [EVENT_REQUEST_SEQ_GC]      = "Request sequential GC",
@@ -70,7 +74,6 @@ char *EventDesc[] = {
   [EVENT_CREATE_SPARK_THREAD] = "Create spark thread",
   [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",
@@ -287,7 +290,11 @@ initEventLogging(void)
                 sizeof(EventThreadID) + sizeof(StgWord16) + sizeof(EventThreadID);
             break;
 
-        case EVENT_STARTUP:         // (cap count)
+        case EVENT_STARTUP:         // (cap_count)
+        case EVENT_CAP_CREATE:      // (cap)
+        case EVENT_CAP_DELETE:      // (cap)
+        case EVENT_CAP_ENABLE:      // (cap)
+        case EVENT_CAP_DISABLE:     // (cap)
             eventTypes[t].size = sizeof(EventCapNo);
             break;
 
@@ -322,7 +329,6 @@ initEventLogging(void)
                 sizeof(EventCapNo);
             break;
 
-        case EVENT_SHUTDOWN:        // (cap)
         case EVENT_REQUEST_SEQ_GC:  // (cap)
         case EVENT_REQUEST_PAR_GC:  // (cap)
         case EVENT_GC_START:        // (cap)
@@ -519,11 +525,6 @@ postSchedEvent (Capability *cap,
         break;
     }
 
-    case EVENT_SHUTDOWN:        // (cap)
-    {
-        break;
-    }
-
     default:
         barf("postSchedEvent: unknown event tag %d", tag);
     }
@@ -597,6 +598,36 @@ postSparkCountersEvent (Capability *cap,
     postWord64(eb,remaining);
 }
 
+void
+postCapEvent (EventTypeNum  tag,
+              EventCapNo    capno)
+{
+    ACQUIRE_LOCK(&eventBufMutex);
+
+    if (!hasRoomForEvent(&eventBuf, tag)) {
+        // Flush event buffer to make room for new event.
+        printAndClearEventBuf(&eventBuf);
+    }
+    
+    postEventHeader(&eventBuf, tag);
+
+    switch (tag) {
+    case EVENT_CAP_CREATE:   // (cap)
+    case EVENT_CAP_DELETE:   // (cap)
+    case EVENT_CAP_ENABLE:   // (cap)
+    case EVENT_CAP_DISABLE:  // (cap)
+    {
+        postCapNo(&eventBuf,capno);
+        break;
+    }
+
+    default:
+        barf("postCapEvent: unknown event tag %d", tag);
+    }
+
+    RELEASE_LOCK(&eventBufMutex);
+}
+
 void postCapsetEvent (EventTypeNum tag,
                       EventCapsetID capset,
                       StgWord info)

rts/eventlog/EventLog.h

@@ -48,6 +48,12 @@ void postCapMsg(Capability *cap, char *msg, va_list ap);
 
 void postEventStartup(EventCapNo n_caps);
 
+/*
+ * Post an event relating to a capability itself (create/delete/etc)
+ */
+void postCapEvent (EventTypeNum  tag,
+                   EventCapNo    capno);
+
 /*
  * Post an event that is associated with a capability set
  */