More accurate trace reporting duration of android gc bridge

There is some code that reports the length of a gc bridge operation in
sgen-stw. This is dead code dating from a period when gc bridges
occurred synchronously as part of a stop the world operation. The new
code globally tracks the end of the last stw and reports time since
then when the bridge thread completes.

diff --git a/mono/metadata/sgen-bridge.c b/mono/metadata/sgen-bridge.c
index 74630b2c973afd4027dae0aac1c84b2515fe747f..59d96de818c29ccb515c22697050cea6ac96101f 100644 (file)
--- a/mono/metadata/sgen-bridge.c
+++ b/mono/metadata/sgen-bridge.c
@@ -375,6 +375,8 @@ sgen_bridge_processing_finish (int generation)
        if (compare_bridge_processors ())
                compare_to_bridge_processor.processing_after_callback (generation);
 
+       mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_BRIDGE: Complete, was running for %.2fms", mono_time_since_last_stw () / 10000.0f);
+
        bridge_processing_in_progress = FALSE;
 }
 

diff --git a/mono/metadata/sgen-client-mono.h b/mono/metadata/sgen-client-mono.h
index 02cfce160ca364ad25a6c909523cbd2785408a42..d117d7fc288b04332a61ef76957eb4f0bded1779 100644 (file)
--- a/mono/metadata/sgen-client-mono.h
+++ b/mono/metadata/sgen-client-mono.h
@@ -727,6 +727,8 @@ extern MonoNativeTlsKey thread_info_key;
 #define SGEN_TV_GETTIME(tv) tv = mono_100ns_ticks ()
 #define SGEN_TV_ELAPSED(start,end) ((gint64)(end-start))
 
+guint64 mono_time_since_last_stw (void);
+
 typedef MonoSemType SgenSemaphore;
 
 #define SGEN_SEMAPHORE_INIT(sem,initial)       mono_os_sem_init ((sem), (initial))

diff --git a/mono/metadata/sgen-mono.c b/mono/metadata/sgen-mono.c
index 6510bfe0f1ffc69f965bc211cdecd5725531eb03..644c9ba93cd893c25d3c271d18d1a82bd69cf524 100644 (file)
--- a/mono/metadata/sgen-mono.c
+++ b/mono/metadata/sgen-mono.c
@@ -2726,7 +2726,7 @@ sgen_client_log_timing (GGTimingInfo *info, mword last_major_num_sections, mword
        full_timing_buff [0] = '\0';
 
        if (!info->is_overflow)
-               sprintf (full_timing_buff, "total %.2fms, bridge %.2fms", info->stw_time / 10000.0f, (int)info->bridge_time / 10000.0f);
+               sprintf (full_timing_buff, "total %.2fms", info->stw_time / 10000.0f);
        if (info->generation == GENERATION_OLD)
                mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MAJOR%s: (%s) pause %.2fms, %s los %dK/%dK",
                        info->is_overflow ? "_OVERFLOW" : "",

diff --git a/mono/metadata/sgen-stw.c b/mono/metadata/sgen-stw.c
index 6af2a6f45c99e53e51f1967f775d56fb1a25961a..cc154b0edeea58d22f13cb0c346950486f5b199e 100644 (file)
--- a/mono/metadata/sgen-stw.c
+++ b/mono/metadata/sgen-stw.c
@@ -33,6 +33,18 @@
 static void sgen_unified_suspend_restart_world (void);
 static void sgen_unified_suspend_stop_world (void);
 
+static TV_DECLARE (end_of_last_stw);
+
+guint64 mono_time_since_last_stw ()
+{
+       if (end_of_last_stw == 0)
+               return 0;
+
+       TV_DECLARE (current_time);
+       TV_GETTIME (current_time);
+       return TV_ELAPSED (end_of_last_stw, current_time);
+}
+
 unsigned int sgen_global_stop_count = 0;
 
 inline static void*
@@ -234,8 +246,7 @@ sgen_client_restart_world (int generation, GGTimingInfo *timing)
 {
        TV_DECLARE (end_sw);
        TV_DECLARE (start_handshake);
-       TV_DECLARE (end_bridge);
-       unsigned long usec, bridge_usec;
+       unsigned long usec;
 
        /* notify the profiler of the leftovers */
        /* FIXME this is the wrong spot at we can STW for non collection reasons. */
@@ -258,6 +269,7 @@ sgen_client_restart_world (int generation, GGTimingInfo *timing)
        time_restart_world += TV_ELAPSED (start_handshake, end_sw);
        usec = TV_ELAPSED (stop_world_time, end_sw);
        max_pause_usec = MAX (usec, max_pause_usec);
+       end_of_last_stw = end_sw;
 
        SGEN_LOG (2, "restarted (pause time: %d usec, max: %d)", (int)usec, (int)max_pause_usec);
 
@@ -273,12 +285,8 @@ sgen_client_restart_world (int generation, GGTimingInfo *timing)
         */
        release_gc_locks ();
 
-       TV_GETTIME (end_bridge);
-       bridge_usec = TV_ELAPSED (end_sw, end_bridge);
-
        if (timing) {
                timing [0].stw_time = usec;
-               timing [0].bridge_time = bridge_usec;
        }
 }
 

diff --git a/mono/sgen/sgen-gc.h b/mono/sgen/sgen-gc.h
index 565514568c5c2f688189efa417d00f133dc7b503..44092858c112a57d0f83b318d9889aaea745af38 100644 (file)
--- a/mono/sgen/sgen-gc.h
+++ b/mono/sgen/sgen-gc.h
@@ -817,7 +817,6 @@ typedef struct {
        gboolean is_overflow;
        gint64 total_time;
        gint64 stw_time;
-       gint64 bridge_time;
 } GGTimingInfo;
 
 void sgen_stop_world (int generation);