[sgen] Binary protocol entries for world stop/restart with timestamps.

mono/metadata/sgen-gc.c

@@ -367,6 +367,8 @@ mono_gc_flush_info (void)
 #define TV_ELAPSED SGEN_TV_ELAPSED
 #define TV_ELAPSED_MS SGEN_TV_ELAPSED_MS
 
+SGEN_TV_DECLARE (sgen_init_timestamp);
+
 #define ALIGN_TO(val,align) ((((guint64)val) + ((align) - 1)) & ~((align) - 1))
 
 NurseryClearPolicy nursery_clear_policy = CLEAR_AT_TLAB_CREATION;
@@ -3333,6 +3335,7 @@ major_start_concurrent_collection (const char *reason)
 	g_assert (num_objects_marked == 0);
 
 	MONO_GC_CONCURRENT_START_BEGIN (GENERATION_OLD);
+	binary_protocol_concurrent_start ();
 
 	// FIXME: store reason and pass it when finishing
 	major_start_collection (TRUE, NULL);
@@ -3353,6 +3356,7 @@ major_update_or_finish_concurrent_collection (gboolean force_finish)
 	memset (&unpin_queue, 0, sizeof (unpin_queue));
 
 	MONO_GC_CONCURRENT_UPDATE_FINISH_BEGIN (GENERATION_OLD, major_collector.get_and_reset_num_major_objects_marked ());
+	binary_protocol_concurrent_update_finish ();
 
 	g_assert (sgen_gray_object_queue_is_empty (&gray_queue));
 
@@ -4851,6 +4855,8 @@ mono_gc_base_init (void)
 		}
 	} while (result != 0);
 
+	SGEN_TV_GETTIME (sgen_init_timestamp);
+
 	LOCK_INIT (gc_mutex);
 
 	pagesize = mono_pagesize ();
@@ -5667,4 +5673,12 @@ sgen_gc_event_moves (void)
 	}
 }
 
+gint64
+sgen_timestamp (void)
+{
+	SGEN_TV_DECLARE (timestamp);
+	SGEN_TV_GETTIME (timestamp);
+	return SGEN_TV_ELAPSED (sgen_init_timestamp, timestamp);
+}
+
 #endif /* HAVE_SGEN_GC */

mono/metadata/sgen-gc.h

@@ -1057,6 +1057,7 @@ void sgen_env_var_error (const char *env_var, const char *fallback, const char *
 /* Utilities */
 
 void sgen_qsort (void *base, size_t nel, size_t width, int (*compar) (const void*, const void*)) MONO_INTERNAL;
+gint64 sgen_timestamp (void) MONO_INTERNAL;
 
 #endif /* HAVE_SGEN_GC */
 

mono/metadata/sgen-protocol.c

@@ -230,6 +230,32 @@ binary_protocol_collection_end (int index, int generation)
 	protocol_entry (SGEN_PROTOCOL_COLLECTION_END, &entry, sizeof (SGenProtocolCollection));
 }
 
+void
+binary_protocol_concurrent_start (void)
+{
+	protocol_entry (SGEN_PROTOCOL_CONCURRENT_START, NULL, 0);
+}
+
+void
+binary_protocol_concurrent_update_finish (void)
+{
+	protocol_entry (SGEN_PROTOCOL_CONCURRENT_UPDATE_FINISH, NULL, 0);
+}
+
+void
+binary_protocol_world_stopping (long long timestamp)
+{
+	SGenProtocolWorldStop entry = { timestamp };
+	protocol_entry (SGEN_PROTOCOL_WORLD_STOPPING, &entry, sizeof (SGenProtocolWorldStop));
+}
+
+void
+binary_protocol_world_restarted (int generation, long long timestamp)
+{
+	SGenProtocolWorldRestart entry = { generation, timestamp };
+	protocol_entry (SGEN_PROTOCOL_WORLD_RESTARTED, &entry, sizeof (SGenProtocolWorldRestart));
+}
+
 void
 binary_protocol_thread_suspend (gpointer thread, gpointer stopped_ip)
 {

mono/metadata/sgen-protocol.h

@@ -26,6 +26,10 @@ enum {
 	SGEN_PROTOCOL_COLLECTION_FORCE,
 	SGEN_PROTOCOL_COLLECTION_BEGIN,
 	SGEN_PROTOCOL_COLLECTION_END,
+	SGEN_PROTOCOL_CONCURRENT_START,
+	SGEN_PROTOCOL_CONCURRENT_UPDATE_FINISH,
+	SGEN_PROTOCOL_WORLD_STOPPING,
+	SGEN_PROTOCOL_WORLD_RESTARTED,
 	SGEN_PROTOCOL_ALLOC,
 	SGEN_PROTOCOL_COPY,
 	SGEN_PROTOCOL_PIN,
@@ -62,6 +66,15 @@ typedef struct {
 	int index, generation;
 } SGenProtocolCollection;
 
+typedef struct {
+	long long timestamp;
+} SGenProtocolWorldStop;
+
+typedef struct {
+	int generation;
+	long long timestamp;
+} SGenProtocolWorldRestart;
+
 typedef struct {
 	gpointer obj;
 	gpointer vtable;
@@ -199,6 +212,10 @@ void binary_protocol_flush_buffers (gboolean force) MONO_INTERNAL;
 void binary_protocol_collection_force (int generation) MONO_INTERNAL;
 void binary_protocol_collection_begin (int index, int generation) MONO_INTERNAL;
 void binary_protocol_collection_end (int index, int generation) MONO_INTERNAL;
+void binary_protocol_concurrent_start (void) MONO_INTERNAL;
+void binary_protocol_concurrent_update_finish (void) MONO_INTERNAL;
+void binary_protocol_world_stopping (long long timestamp) MONO_INTERNAL;
+void binary_protocol_world_restarted (int generation, long long timestamp) MONO_INTERNAL;
 
 void binary_protocol_thread_suspend (gpointer thread, gpointer stopped_ip) MONO_INTERNAL;
 void binary_protocol_thread_restart (gpointer thread) MONO_INTERNAL;

mono/metadata/sgen-stw.c

@@ -202,6 +202,7 @@ sgen_stop_world (int generation)
 
 	mono_profiler_gc_event (MONO_GC_EVENT_PRE_STOP_WORLD, generation);
 	MONO_GC_WORLD_STOP_BEGIN ();
+	binary_protocol_world_stopping (sgen_timestamp ());
 	acquire_gc_locks ();
 
 	/* We start to scan after locks are taking, this ensures we won't be interrupted. */
@@ -260,6 +261,7 @@ sgen_restart_world (int generation, GGTimingInfo *timing)
 	SGEN_LOG (2, "restarted %d thread(s) (pause time: %d usec, max: %d)", count, (int)usec, (int)max_pause_usec);
 	mono_profiler_gc_event (MONO_GC_EVENT_POST_START_WORLD, generation);
 	MONO_GC_WORLD_RESTART_END (generation);
+	binary_protocol_world_restarted (generation, sgen_timestamp ());
 
 	/*
 	 * We must release the thread info suspend lock after doing

tools/sgen/sgen-grep-binprot.c

@@ -25,6 +25,10 @@ read_entry (FILE *in, void **data)
 	case SGEN_PROTOCOL_COLLECTION_FORCE: size = sizeof (SGenProtocolCollectionForce); break;
 	case SGEN_PROTOCOL_COLLECTION_BEGIN: size = sizeof (SGenProtocolCollection); break;
 	case SGEN_PROTOCOL_COLLECTION_END: size = sizeof (SGenProtocolCollection); break;
+	case SGEN_PROTOCOL_CONCURRENT_START: size = 0; break;
+	case SGEN_PROTOCOL_CONCURRENT_UPDATE_FINISH: size = 0; break;
+	case SGEN_PROTOCOL_WORLD_STOPPING: size = sizeof (SGenProtocolWorldStop); break;
+	case SGEN_PROTOCOL_WORLD_RESTARTED: size = sizeof (SGenProtocolWorldRestart); break;
 	case SGEN_PROTOCOL_ALLOC: size = sizeof (SGenProtocolAlloc); break;
 	case SGEN_PROTOCOL_ALLOC_PINNED: size = sizeof (SGenProtocolAlloc); break;
 	case SGEN_PROTOCOL_ALLOC_DEGRADED: size = sizeof (SGenProtocolAlloc); break;
@@ -86,6 +90,24 @@ print_entry (int type, void *data)
 		printf ("%s collection end %d generation %d\n", WORKER_PREFIX (type), entry->index, entry->generation);
 		break;
 	}
+	case SGEN_PROTOCOL_CONCURRENT_START: {
+		printf ("%s concurrent start\n", WORKER_PREFIX (type));
+		break;
+	}
+	case SGEN_PROTOCOL_CONCURRENT_UPDATE_FINISH: {
+		printf ("%s concurrent update or finish\n", WORKER_PREFIX (type));
+		break;
+	}
+	case SGEN_PROTOCOL_WORLD_STOPPING: {
+		SGenProtocolWorldStop *entry = data;
+		printf ("%s world stopping timestamp %lld\n", WORKER_PREFIX (type), entry->timestamp);
+		break;
+	}
+	case SGEN_PROTOCOL_WORLD_RESTARTED: {
+		SGenProtocolWorldRestart *entry = data;
+		printf ("%s world restarted generation %d timestamp %lld\n", WORKER_PREFIX (type), entry->generation, entry->timestamp);
+		break;
+	}
 	case SGEN_PROTOCOL_ALLOC: {
 		SGenProtocolAlloc *entry = data;
 		printf ("%s alloc obj %p vtable %p size %d\n", WORKER_PREFIX (type), entry->obj, entry->vtable, entry->size);
@@ -243,6 +265,10 @@ is_match (gpointer ptr, int type, void *data)
 	case SGEN_PROTOCOL_COLLECTION_FORCE:
 	case SGEN_PROTOCOL_COLLECTION_BEGIN:
 	case SGEN_PROTOCOL_COLLECTION_END:
+	case SGEN_PROTOCOL_CONCURRENT_START:
+	case SGEN_PROTOCOL_CONCURRENT_UPDATE_FINISH:
+	case SGEN_PROTOCOL_WORLD_STOPPING:
+	case SGEN_PROTOCOL_WORLD_RESTARTED:
 	case SGEN_PROTOCOL_THREAD_SUSPEND:
 	case SGEN_PROTOCOL_THREAD_RESTART:
 	case SGEN_PROTOCOL_THREAD_REGISTER:
@@ -379,8 +405,6 @@ is_vtable_match (gpointer ptr, int type, void *data)
 	}
 }
 
-static gboolean dump_all = FALSE;
-
 int
 main (int argc, char *argv[])
 {
@@ -392,12 +416,19 @@ main (int argc, char *argv[])
 	int i;
 	long nums [num_args];
 	long vtables [num_args];
+	gboolean dump_all = FALSE;
+	gboolean pause_times = FALSE;
+	gboolean pause_times_stopped = FALSE;
+	gboolean pause_times_concurrent = FALSE;
+	long long pause_times_ts = 0;
 
 	for (i = 0; i < num_args; ++i) {
 		char *arg = argv [i + 1];
 		char *next_arg = argv [i + 2];
 		if (!strcmp (arg, "--all")) {
 			dump_all = TRUE;
+		} else if (!strcmp (arg, "--pause-times")) {
+			pause_times = TRUE;
 		} else if (!strcmp (arg, "-v") || !strcmp (arg, "--vtable")) {
 			vtables [num_vtables++] = strtoul (next_arg, NULL, 16);
 			++i;
@@ -406,26 +437,59 @@ main (int argc, char *argv[])
 		}
 	}
 
+	if (dump_all)
+		assert (!pause_times);
+	if (pause_times)
+		assert (!dump_all);
+
 	while ((type = read_entry (stdin, &data)) != SGEN_PROTOCOL_EOF) {
-		gboolean match = FALSE;
-		for (i = 0; i < num_nums; ++i) {
-			if (is_match ((gpointer) nums [i], type, data)) {
-				match = TRUE;
+		if (pause_times) {
+			switch (type) {
+			case SGEN_PROTOCOL_WORLD_STOPPING: {
+				SGenProtocolWorldStop *entry = data;
+				assert (!pause_times_stopped);
+				pause_times_concurrent = FALSE;
+				pause_times_ts = entry->timestamp;
+				pause_times_stopped = TRUE;
 				break;
 			}
-		}
-		if (!match) {
-			for (i = 0; i < num_vtables; ++i) {
-				if (is_vtable_match ((gpointer) vtables [i], type, data)) {
+			case SGEN_PROTOCOL_CONCURRENT_START:
+			case SGEN_PROTOCOL_CONCURRENT_UPDATE_FINISH:
+				pause_times_concurrent = TRUE;
+				break;
+			case SGEN_PROTOCOL_WORLD_RESTARTED: {
+				SGenProtocolWorldRestart *entry = data;
+				assert (pause_times_stopped);
+				printf ("pause-time %d %d %lld %lld\n",
+						entry->generation,
+						pause_times_concurrent,
+						entry->timestamp - pause_times_ts,
+						pause_times_ts);
+				pause_times_stopped = FALSE;
+				break;
+			}
+			}
+		} else {
+			gboolean match = FALSE;
+			for (i = 0; i < num_nums; ++i) {
+				if (is_match ((gpointer) nums [i], type, data)) {
 					match = TRUE;
 					break;
 				}
 			}
+			if (!match) {
+				for (i = 0; i < num_vtables; ++i) {
+					if (is_vtable_match ((gpointer) vtables [i], type, data)) {
+						match = TRUE;
+						break;
+					}
+				}
+			}
+			if (dump_all)
+				printf (match ? "* " : "  ");
+			if (match || dump_all)
+				print_entry (type, data);
 		}
-		if (dump_all)
-			printf (match ? "* " : "  ");
-		if (match || dump_all)
-			print_entry (type, data);
 		free (data);
 	}