rts: Tracing support for nonmoving collection events

This introduces a few events to mark key points in the nonmoving
garbage collection cycle. These include:

 * `EVENT_CONC_MARK_BEGIN`, denoting the beginning of a round of
   marking. This may happen more than once in a single major collection
   since we the major collector iterates until it hits a fixed point.

 * `EVENT_CONC_MARK_END`, denoting the end of a round of marking.

 * `EVENT_CONC_SYNC_BEGIN`, denoting the beginning of the post-mark
   synchronization phase

 * `EVENT_CONC_UPD_REM_SET_FLUSH`, indicating that a capability has
   flushed its update remembered set.

 * `EVENT_CONC_SYNC_END`, denoting that all mutators have flushed their
   update remembered sets.

 * `EVENT_CONC_SWEEP_BEGIN`, denoting the beginning of the sweep portion
   of the major collection.

 * `EVENT_CONC_SWEEP_END`, denoting the end of the sweep portion of the
   major collection.

6 files changed, 125 insertions, 1 deletions

diff --git a/rts/Trace.c b/rts/Trace.c
index de647f762b..10ad5031ab 100644
--- a/rts/Trace.c
+++ b/rts/Trace.c
@@ -802,6 +802,49 @@ void traceThreadLabel_(Capability *cap,
     }
 }
 
+void traceConcMarkBegin()
+{
+    if (eventlog_enabled)
+        postEventNoCap(EVENT_CONC_MARK_BEGIN);
+}
+
+void traceConcMarkEnd(StgWord32 marked_obj_count)
+{
+    if (eventlog_enabled)
+        postConcMarkEnd(marked_obj_count);
+}
+
+void traceConcSyncBegin()
+{
+    if (eventlog_enabled)
+        postEventNoCap(EVENT_CONC_SYNC_BEGIN);
+}
+
+void traceConcSyncEnd()
+{
+    if (eventlog_enabled)
+        postEventNoCap(EVENT_CONC_SYNC_END);
+}
+
+void traceConcSweepBegin()
+{
+    if (eventlog_enabled)
+        postEventNoCap(EVENT_CONC_SWEEP_BEGIN);
+}
+
+void traceConcSweepEnd()
+{
+    if (eventlog_enabled)
+        postEventNoCap(EVENT_CONC_SWEEP_END);
+}
+
+void traceConcUpdRemSetFlush(Capability *cap)
+{
+    if (eventlog_enabled)
+        postConcUpdRemSetFlush(cap);
+}
+
+
 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
 {
 #if defined(DEBUG)
diff --git a/rts/Trace.h b/rts/Trace.h
index be4d844a6b..9b52c3cb65 100644
--- a/rts/Trace.h
+++ b/rts/Trace.h
@@ -304,6 +304,14 @@ void traceHeapProfSampleCostCentre(StgWord8 profile_id,
                                    CostCentreStack *stack, StgWord residency);
 #endif /* PROFILING */
 
+void traceConcMarkBegin(void);
+void traceConcMarkEnd(StgWord32 marked_obj_count);
+void traceConcSyncBegin(void);
+void traceConcSyncEnd(void);
+void traceConcSweepBegin(void);
+void traceConcSweepEnd(void);
+void traceConcUpdRemSetFlush(Capability *cap);
+
 void flushTrace(void);
 
 #else /* !TRACING */
@@ -344,6 +352,14 @@ void flushTrace(void);
 #define traceHeapProfSampleCostCentre(profile_id, stack, residency) /* nothing */
 #define traceHeapProfSampleString(profile_id, label, residency) /* nothing */
 
+#define traceConcMarkBegin() /* nothing */
+#define traceConcMarkEnd(marked_obj_count) /* nothing */
+#define traceConcSyncBegin() /* nothing */
+#define traceConcSyncEnd() /* nothing */
+#define traceConcSweepBegin() /* nothing */
+#define traceConcSweepEnd() /* nothing */
+#define traceConcUpdRemSetFlush(cap) /* nothing */
+
 #define flushTrace() /* nothing */
 
 #endif /* TRACING */
diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c
index 5c6a1ca48a..60b960998f 100644
--- a/rts/eventlog/EventLog.c
+++ b/rts/eventlog/EventLog.c
@@ -107,7 +107,14 @@ char *EventDesc[] = {
   [EVENT_HEAP_PROF_SAMPLE_END]    = "End of heap profile sample",
   [EVENT_HEAP_PROF_SAMPLE_STRING] = "Heap profile string sample",
   [EVENT_HEAP_PROF_SAMPLE_COST_CENTRE] = "Heap profile cost-centre sample",
-  [EVENT_USER_BINARY_MSG]     = "User binary message"
+  [EVENT_USER_BINARY_MSG]     = "User binary message",
+  [EVENT_CONC_MARK_BEGIN]        = "Begin concurrent mark phase",
+  [EVENT_CONC_MARK_END]          = "End concurrent mark phase",
+  [EVENT_CONC_SYNC_BEGIN]        = "Begin concurrent GC synchronisation",
+  [EVENT_CONC_SYNC_END]          = "End concurrent GC synchronisation",
+  [EVENT_CONC_SWEEP_BEGIN]       = "Begin concurrent sweep",
+  [EVENT_CONC_SWEEP_END]         = "End concurrent sweep",
+  [EVENT_CONC_UPD_REM_SET_FLUSH] = "Update remembered set flushed"
 };
 
 // Event type.
@@ -446,6 +453,23 @@ init_event_types(void)
             eventTypes[t].size = EVENT_SIZE_DYNAMIC;
             break;
 
+        case EVENT_CONC_MARK_BEGIN:
+        case EVENT_CONC_SYNC_BEGIN:
+        case EVENT_CONC_SYNC_END:
+        case EVENT_CONC_SWEEP_BEGIN:
+        case EVENT_CONC_SWEEP_END:
+            eventTypes[t].size = 0;
+            break;
+
+        case EVENT_CONC_MARK_END:
+            eventTypes[t].size = 4;
+            break;
+
+        case EVENT_CONC_UPD_REM_SET_FLUSH: // (cap)
+            eventTypes[t].size =
+                sizeof(EventCapNo);
+            break;
+
         default:
             continue; /* ignore deprecated events */
         }
@@ -1005,6 +1029,15 @@ void postTaskDeleteEvent (EventTaskId taskId)
 }
 
 void
+postEventNoCap (EventTypeNum tag)
+{
+    ACQUIRE_LOCK(&eventBufMutex);
+    ensureRoomForEvent(&eventBuf, tag);
+    postEventHeader(&eventBuf, tag);
+    RELEASE_LOCK(&eventBufMutex);
+}
+
+void
 postEvent (Capability *cap, EventTypeNum tag)
 {
     EventsBuf *eb = &capEventBuf[cap->no];
@@ -1130,6 +1163,23 @@ void postThreadLabel(Capability    *cap,
     postBuf(eb, (StgWord8*) label, strsize);
 }
 
+void postConcUpdRemSetFlush(Capability *cap)
+{
+    EventsBuf *eb = &capEventBuf[cap->no];
+    ensureRoomForEvent(eb, EVENT_CONC_UPD_REM_SET_FLUSH);
+    postEventHeader(eb, EVENT_CONC_UPD_REM_SET_FLUSH);
+    postCapNo(eb, cap->no);
+}
+
+void postConcMarkEnd(StgWord32 marked_obj_count)
+{
+    ACQUIRE_LOCK(&eventBufMutex);
+    ensureRoomForEvent(&eventBuf, EVENT_CONC_MARK_END);
+    postEventHeader(&eventBuf, EVENT_CONC_MARK_END);
+    postWord32(&eventBuf, marked_obj_count);
+    RELEASE_LOCK(&eventBufMutex);
+}
+
 void closeBlockMarker (EventsBuf *ebuf)
 {
     if (ebuf->marker)
diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h
index d8a614b45c..16c7670cb3 100644
--- a/rts/eventlog/EventLog.h
+++ b/rts/eventlog/EventLog.h
@@ -39,6 +39,7 @@ void postSchedEvent(Capability *cap, EventTypeNum tag,
  * Post a nullary event.
  */
 void postEvent(Capability *cap, EventTypeNum tag);
+void postEventNoCap(EventTypeNum tag);
 
 void postEventAtTimestamp (Capability *cap, EventTimestamp ts,
                            EventTypeNum tag);
@@ -159,6 +160,9 @@ void postHeapProfSampleCostCentre(StgWord8 profile_id,
                                   StgWord64 residency);
 #endif /* PROFILING */
 
+void postConcUpdRemSetFlush(Capability *cap);
+void postConcMarkEnd(StgWord32 marked_obj_count);
+
 #else /* !TRACING */
 
 INLINE_HEADER void postSchedEvent (Capability *cap  STG_UNUSED,
@@ -172,6 +176,9 @@ INLINE_HEADER void postEvent (Capability *cap  STG_UNUSED,
                               EventTypeNum tag STG_UNUSED)
 { /* nothing */ }
 
+INLINE_HEADER void postEventNoCap (EventTypeNum tag STG_UNUSED)
+{ /* nothing */ }
+
 INLINE_HEADER void postMsg (char *msg STG_UNUSED,
                             va_list ap STG_UNUSED)
 { /* nothing */ }
diff --git a/rts/sm/NonMoving.c b/rts/sm/NonMoving.c
index 24464a43f9..36df09692b 100644
--- a/rts/sm/NonMoving.c
+++ b/rts/sm/NonMoving.c
@@ -735,6 +735,8 @@ static void nonmovingMark_(MarkQueue *mark_queue, StgWeak **dead_weaks, StgTSO *
      * Sweep
      ****************************************************/
 
+    traceConcSweepBegin();
+
     // Because we can't mark large object blocks (no room for mark bit) we
     // collect them in a map in mark_queue and we pass it here to sweep large
     // objects
@@ -744,6 +746,7 @@ static void nonmovingMark_(MarkQueue *mark_queue, StgWeak **dead_weaks, StgTSO *
     nonmovingSweep();
     ASSERT(nonmovingHeap.sweep_list == NULL);
     debugTrace(DEBUG_nonmoving_gc, "Finished sweeping.");
+    traceConcSweepEnd();
 
     // TODO: Remainder of things done by GarbageCollect (update stats)
 
diff --git a/rts/sm/NonMovingMark.c b/rts/sm/NonMovingMark.c
index 72a3ca69cb..050b7ca24f 100644
--- a/rts/sm/NonMovingMark.c
+++ b/rts/sm/NonMovingMark.c
@@ -238,6 +238,7 @@ void nonmovingFlushCapUpdRemSetBlocks(Capability *cap)
     debugTrace(DEBUG_nonmoving_gc,
                "Capability %d flushing update remembered set: %d",
                cap->no, markQueueLength(&cap->upd_rem_set.queue));
+    traceConcUpdRemSetFlush(cap);
     nonmovingAddUpdRemSetBlocks(&cap->upd_rem_set.queue);
     atomic_inc(&upd_rem_set_flush_count, 1);
     signalCondition(&upd_rem_set_flushed_cond);
@@ -251,6 +252,7 @@ void nonmovingFlushCapUpdRemSetBlocks(Capability *cap)
 void nonmovingBeginFlush(Task *task)
 {
     debugTrace(DEBUG_nonmoving_gc, "Starting update remembered set flush...");
+    traceConcSyncBegin();
     upd_rem_set_flush_count = 0;
     stopAllCapabilitiesWith(NULL, task, SYNC_FLUSH_UPD_REM_SET);
 
@@ -342,6 +344,7 @@ void nonmovingFinishFlush(Task *task)
     upd_rem_set_block_list = NULL;
 
     debugTrace(DEBUG_nonmoving_gc, "Finished update remembered set flush...");
+    traceConcSyncEnd();
     releaseAllCapabilities(n_capabilities, NULL, task);
 }
 #endif
@@ -1434,6 +1437,7 @@ mark_closure (MarkQueue *queue, StgClosure *p, StgClosure **origin)
 GNUC_ATTR_HOT void
 nonmovingMark (MarkQueue *queue)
 {
+    traceConcMarkBegin();
     debugTrace(DEBUG_nonmoving_gc, "Starting mark pass");
     unsigned int count = 0;
     while (true) {
@@ -1474,6 +1478,7 @@ nonmovingMark (MarkQueue *queue)
             } else {
                 // Nothing more to do
                 debugTrace(DEBUG_nonmoving_gc, "Finished mark pass: %d", count);
+                traceConcMarkEnd(count);
                 return;
             }
         }