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.

diff --git a/alloc.c b/alloc.c
index 18a240161b690b73d8ac137b0714e9db15dceb06..5259cb872a9df86621f389aa873ef244af27203c 100644 (file)
--- 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 8b495d6aa66ff6bfed3da88f758448a252965a7c..dabc680867637f85565ba12f08f12cd49e683de9 100644 (file)
--- 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 <time.h>
 # 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 73292b4f3e9f41530941b1c0941376f71d0ead3c..3a573832b9253f21df8b602510ba904a51dcfad1 100644 (file)
--- 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);