rts: Tracing support for nonmoving collection events
authorBen Gamari <ben@well-typed.com>
Tue, 5 Feb 2019 16:51:52 +0000 (11:51 -0500)
committerBen Gamari <ben@smart-cactus.org>
Fri, 17 May 2019 17:02:09 +0000 (13:02 -0400)
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.

includes/rts/EventLogFormat.h
rts/Trace.c
rts/Trace.h
rts/eventlog/EventLog.c
rts/eventlog/EventLog.h
rts/sm/NonMoving.c
rts/sm/NonMovingMark.c

index 63303c9..7be4527 100644 (file)
 
 #define EVENT_USER_BINARY_MSG              181
 
+#define EVENT_CONC_MARK_BEGIN              200
+#define EVENT_CONC_MARK_END                201
+#define EVENT_CONC_SYNC_BEGIN              202
+#define EVENT_CONC_SYNC_END                203
+#define EVENT_CONC_SWEEP_BEGIN             204
+#define EVENT_CONC_SWEEP_END               205
+#define EVENT_CONC_UPD_REM_SET_FLUSH       206
+
 /*
  * The highest event code +1 that ghc itself emits. Note that some event
  * 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        182
+#define NUM_GHC_EVENT_TAGS        207
 
 #if 0  /* DEPRECATED EVENTS: */
 /* we don't actually need to record the thread, it's implicit */
index 4475054..5dd5004 100644 (file)
@@ -789,6 +789,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)
index a7c0cb2..e7f3041 100644 (file)
@@ -301,6 +301,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 */
@@ -339,6 +347,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 */
index ff79425..7b8f923 100644 (file)
@@ -105,7 +105,14 @@ char *EventDesc[] = {
   [EVENT_HEAP_PROF_SAMPLE_BEGIN]  = "Start 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.
@@ -442,6 +449,23 @@ postHeaderEvents(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 */
         }
@@ -986,6 +1010,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];
@@ -1111,6 +1144,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)
index 1fb7c4a..605fdcc 100644 (file)
@@ -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);
@@ -157,6 +158,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,
@@ -170,6 +174,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 */ }
index 5444baa..427c0c4 100644 (file)
@@ -712,6 +712,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
@@ -721,6 +723,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)
 
index 66fd48f..65bb468 100644 (file)
@@ -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;
             }
         }