From d99e63ecbe1b069193f5b9da7ca44f274d8cebde Mon Sep 17 00:00:00 2001 From: Ivan Maidanski Date: Mon, 14 Jan 2019 09:52:57 +0300 Subject: [PATCH] Report time with a nanosecond precision where available Issue #258 (bdwgc). * alloc.c [!NO_CLOCK] (GC_time_lim_nsec): Update comment. * alloc.c [!NO_CLOCK && !GC_DISABLE_INCREMENTAL] (GC_timeout_stop_func): Declare nsec_diff local variable; use GC_time_lim_nsec. * alloc.c [!NO_CLOCK && !GC_DISABLE_INCREMENTAL] (GC_timeout_stop_func): Use NS_FRAC_TIME_DIFF(); print "ns" value after "ms" one. * alloc.c [!NO_CLOCK] (GC_try_to_collect_inner, GC_stopped_mark, GC_finish_collection): Likewise. * reclaim.c [!NO_CLOCK] (GC_reclaim_all): Likewise. * include/private/gc_priv.h [!NO_CLOCK && BSD_TIME] (MS_TIME_DIFF): Always round the result of division toward minus infinity. * include/private/gc_priv.h [!NO_CLOCK] (NS_FRAC_TIME_DIFF): New macro. --- alloc.c | 35 +++++++++++++++++++++-------------- include/private/gc_priv.h | 19 ++++++++++++++++++- reclaim.c | 6 ++++-- 3 files changed, 43 insertions(+), 17 deletions(-) diff --git a/alloc.c b/alloc.c index 18a24016..5259cb87 100644 --- a/alloc.c +++ b/alloc.c @@ -177,8 +177,7 @@ GC_INNER int GC_CALLBACK GC_never_stop_func(void) /* The nanoseconds add-on to GC_time_limit */ /* value. Not updated by GC_set_time_limit(). */ /* Ignored if the value of GC_time_limit is */ - /* GC_TIME_UNLIMITED; ignored on some platforms */ - /* (depending on GET_TIME implementation). */ + /* GC_TIME_UNLIMITED. */ # define TV_NSEC_LIMIT (1000UL * 1000) /* amount of nanoseconds in 1 ms */ @@ -236,7 +235,7 @@ GC_API GC_stop_func GC_CALL GC_get_stop_func(void) { CLOCK_TYPE current_time; static unsigned count = 0; - unsigned long time_diff; + unsigned long time_diff, nsec_diff; if ((*GC_default_stop_func)()) return(1); @@ -244,11 +243,13 @@ GC_API GC_stop_func GC_CALL GC_get_stop_func(void) if ((count++ & 3) != 0) return(0); GET_TIME(current_time); time_diff = MS_TIME_DIFF(current_time,GC_start_time); - if (time_diff >= GC_time_limit) { - GC_COND_LOG_PRINTF( - "Abandoning stopped marking after %lu ms (attempt %d)\n", - time_diff, GC_n_attempts); - return(1); + nsec_diff = NS_FRAC_TIME_DIFF(current_time, GC_start_time); + if (time_diff >= GC_time_limit + && (time_diff > GC_time_limit || nsec_diff >= GC_time_lim_nsec)) { + GC_COND_LOG_PRINTF("Abandoning stopped marking after %lu ms %lu ns" + " (attempt %d)\n", + time_diff, nsec_diff, GC_n_attempts); + return 1; } return(0); } @@ -587,7 +588,8 @@ GC_INNER GC_bool GC_try_to_collect_inner(GC_stop_func stop_func) if (measure_performance) full_gc_total_time += time_diff; /* may wrap */ if (GC_print_stats) - GC_log_printf("Complete collection took %lu ms\n", time_diff); + GC_log_printf("Complete collection took %lu ms %lu ns\n", time_diff, + NS_FRAC_TIME_DIFF(current_time, start_time)); } # endif if (GC_on_collection_event) @@ -873,8 +875,10 @@ STATIC GC_bool GC_stopped_mark(GC_stop_func stop_func) world_stopped_total_divisor = ++divisor; GC_ASSERT(divisor != 0); - GC_log_printf("World-stopped marking took %lu ms (%u in average)\n", - time_diff, total_time / divisor); + GC_log_printf("World-stopped marking took %lu ms %lu ns" + " (%u ms in average)\n", + time_diff, NS_FRAC_TIME_DIFF(current_time, start_time), + total_time / divisor); } # endif return(TRUE); @@ -1150,9 +1154,12 @@ STATIC void GC_finish_collection(void) /* A convenient place to output finalization statistics. */ GC_print_finalization_stats(); # endif - GC_log_printf("Finalize plus initiate sweep took %lu + %lu ms\n", - MS_TIME_DIFF(finalize_time,start_time), - MS_TIME_DIFF(done_time,finalize_time)); + GC_log_printf("Finalize and initiate sweep took %lu ms %lu ns" + " + %lu ms %lu ns\n", + MS_TIME_DIFF(finalize_time, start_time), + NS_FRAC_TIME_DIFF(finalize_time, start_time), + MS_TIME_DIFF(done_time, finalize_time), + NS_FRAC_TIME_DIFF(done_time, finalize_time)); } # elif !defined(SMALL_CONFIG) && !defined(GC_NO_FINALIZATION) if (GC_print_stats) diff --git a/include/private/gc_priv.h b/include/private/gc_priv.h index 8b495d6a..dabc6808 100644 --- a/include/private/gc_priv.h +++ b/include/private/gc_priv.h @@ -436,9 +436,17 @@ EXTERN_C_END x = rusage.ru_utime; \ } while (0) # define MS_TIME_DIFF(a,b) ((unsigned long)((long)(a.tv_sec-b.tv_sec) * 1000 \ - + (long)(a.tv_usec-b.tv_usec) / 1000)) + + (long)(a.tv_usec - b.tv_usec) / 1000 \ + - (a.tv_usec < b.tv_usec \ + && (long)(a.tv_usec - b.tv_usec) % 1000 != 0 ? 1 : 0))) /* "a" time is expected to be not earlier than */ /* "b" one; the result has unsigned long type. */ +# define NS_FRAC_TIME_DIFF(a, b) ((unsigned long) \ + ((a.tv_usec < b.tv_usec \ + && (long)(a.tv_usec - b.tv_usec) % 1000 != 0 ? 1000L : 0) \ + + (long)(a.tv_usec - b.tv_usec) % 1000) * 1000) + /* The total time difference could be computed as */ + /* MS_TIME_DIFF(a,b)*1000000+NS_FRAC_TIME_DIFF(a,b).*/ #elif defined(MSWIN32) || defined(MSWINCE) # ifndef WIN32_LEAN_AND_MEAN # define WIN32_LEAN_AND_MEAN 1 @@ -453,6 +461,7 @@ EXTERN_C_END # define GET_TIME(x) (void)(x = GetTickCount()) # endif # define MS_TIME_DIFF(a,b) ((unsigned long)((a)-(b))) +# define NS_FRAC_TIME_DIFF(a, b) 0UL #elif defined(NN_PLATFORM_CTR) # define CLOCK_TYPE long long EXTERN_C_BEGIN @@ -461,6 +470,7 @@ EXTERN_C_END EXTERN_C_END # define GET_TIME(x) (void)(x = n3ds_get_system_tick()) # define MS_TIME_DIFF(a,b) ((unsigned long)n3ds_convert_tick_to_ms((a)-(b))) +# define NS_FRAC_TIME_DIFF(a, b) 0UL /* TODO: implement it */ #else /* !BSD_TIME && !NN_PLATFORM_CTR && !MSWIN32 && !MSWINCE */ # include # if defined(FREEBSD) && !defined(CLOCKS_PER_SEC) @@ -486,6 +496,13 @@ EXTERN_C_END : ((unsigned long)((a) - (b)) * 1000) / (unsigned long)CLOCKS_PER_SEC) /* Avoid using double type since some targets (like ARM) might */ /* require -lm option for double-to-long conversion. */ +# define NS_FRAC_TIME_DIFF(a, b) (CLOCKS_PER_SEC <= 1000 ? 0UL \ + : (unsigned long)(CLOCKS_PER_SEC <= (clock_t)1000000UL \ + ? (((a) - (b)) * ((clock_t)1000000UL / CLOCKS_PER_SEC) % 1000) * 1000 \ + : (CLOCKS_PER_SEC <= (clock_t)1000000UL * 1000 \ + ? ((a) - (b)) * ((clock_t)1000000UL * 1000 / CLOCKS_PER_SEC) \ + : (((a) - (b)) * (clock_t)1000000UL * 1000) / CLOCKS_PER_SEC) \ + % (clock_t)1000000UL)) #endif /* !BSD_TIME && !MSWIN32 */ # ifndef CLOCK_TYPE_INITIALIZER /* This is used to initialize CLOCK_TYPE variables (to some value) */ diff --git a/reclaim.c b/reclaim.c index 73292b4f..3a573832 100644 --- a/reclaim.c +++ b/reclaim.c @@ -755,8 +755,10 @@ GC_INNER GC_bool GC_reclaim_all(GC_stop_func stop_func, GC_bool ignore_old) CLOCK_TYPE done_time; GET_TIME(done_time); - GC_verbose_log_printf("Disposing of reclaim lists took %lu ms\n", - MS_TIME_DIFF(done_time,start_time)); + GC_verbose_log_printf( + "Disposing of reclaim lists took %lu ms %lu ns\n", + MS_TIME_DIFF(done_time, start_time), + NS_FRAC_TIME_DIFF(done_time, start_time)); } # endif return(TRUE); -- 2.50.1