GC measurement feature

* `GC.measure_total_time = true` enables total time measurement (default: true)
* `GC.measure_total_time` returns current flag.
* `GC.total_time` returns measured total time in nano seconds.
* `GC.stat(:time)` (and Hash) returns measured total time in milli seconds.

common.mk

@@ -5852,6 +5852,7 @@ gc.$(OBJEXT): {$(VPATH)}encoding.h
 gc.$(OBJEXT): {$(VPATH)}eval_intern.h
 gc.$(OBJEXT): {$(VPATH)}gc.c
 gc.$(OBJEXT): {$(VPATH)}gc.h
+gc.$(OBJEXT): {$(VPATH)}gc.rb
 gc.$(OBJEXT): {$(VPATH)}gc.rbinc
 gc.$(OBJEXT): {$(VPATH)}id.h
 gc.$(OBJEXT): {$(VPATH)}id_table.h

gc.c

@@ -732,6 +732,7 @@ typedef struct rb_objspace {
 #if GC_ENABLE_INCREMENTAL_MARK
 	unsigned int during_incremental_marking : 1;
 #endif
+        unsigned int measure_gc : 1;
     } flags;
 
     rb_event_flag_t hook_events;
@@ -807,7 +808,7 @@ typedef struct rb_objspace {
 	size_t total_freed_objects;
 	size_t total_allocated_pages;
 	size_t total_freed_pages;
-        size_t total_time_ns;
+        uint64_t total_time_ns;
         struct timespec start_time;
     } profile;
     struct gc_list *global_list;
@@ -1718,6 +1719,7 @@ rb_objspace_t *
 rb_objspace_alloc(void)
 {
     rb_objspace_t *objspace = calloc1(sizeof(rb_objspace_t));
+    objspace->flags.measure_gc = 1;
     malloc_limit = gc_params.malloc_limit_min;
 
     for (int i = 0; i < SIZE_POOL_COUNT; i++) {
@@ -9165,10 +9167,12 @@ gc_enter_count(enum gc_enter_event event)
     }
 }
 
-#define MEASURE_GC 1
+#ifndef MEASURE_GC
+#define MEASURE_GC (objspace->flags.measure_gc)
+#endif
 
 static bool
-gc_enter_event_measure_p(enum gc_enter_event event)
+gc_enter_event_measure_p(rb_objspace_t *objspace, enum gc_enter_event event)
 {
     if (!MEASURE_GC) return false;
 
@@ -9178,35 +9182,49 @@ gc_enter_event_measure_p(enum gc_enter_event event)
       case gc_enter_event_sweep_continue:
       case gc_enter_event_rest:
         return true;
-      case gc_enter_event_finalizer:
+
-      case gc_enter_event_rb_memerror:
+      default:
+        // case gc_enter_event_finalizer:
+        // case gc_enter_event_rb_memerror:
         return false;
     }
 }
 
+static bool current_process_time(struct timespec *ts);
+
 static void
 gc_enter_clock(rb_objspace_t *objspace, enum gc_enter_event event)
 {
-    if (gc_enter_event_measure_p(event)) {
+    if (gc_enter_event_measure_p(objspace, event)) {
-        clock_gettime(CLOCK_MONOTONIC, &objspace->profile.start_time);
+        if (!current_process_time(&objspace->profile.start_time)) {
+            objspace->profile.start_time.tv_sec = 0;
+            objspace->profile.start_time.tv_nsec = 0;
+        }
     }
 }
 
 static void
 gc_exit_clock(rb_objspace_t *objspace, enum gc_enter_event event)
 {
-    if (gc_enter_event_measure_p(event)) {
+    if (gc_enter_event_measure_p(objspace, event)) {
         struct timespec end_time;
 
-        clock_gettime(CLOCK_MONOTONIC, &end_time);
+        if ((objspace->profile.start_time.tv_sec > 0 ||
+             objspace->profile.start_time.tv_nsec > 0) &&
+            current_process_time(&end_time)) {
+
             if (end_time.tv_sec < objspace->profile.start_time.tv_sec) {
                 return; // ignore
             }
-        size_t ns = (end_time.tv_sec - objspace->profile.start_time.tv_sec) * 1000 * 1000 * 1000 + end_time.tv_nsec - objspace->profile.start_time.tv_nsec;
+            else {
-
+                uint64_t ns =
+                  (uint64_t)(end_time.tv_sec - objspace->profile.start_time.tv_sec) * (1000 * 1000 * 1000) +
+                            (end_time.tv_nsec - objspace->profile.start_time.tv_nsec);
                 objspace->profile.total_time_ns += ns;
             }
         }
+    }
+}
 
 static inline void
 gc_enter(rb_objspace_t *objspace, enum gc_enter_event event, unsigned int *lock_lev)
@@ -12411,16 +12429,14 @@ wmap_size(VALUE self)
 
 #define GC_PROFILE_RECORD_DEFAULT_SIZE 100
 
-/* return sec in user time */
+static bool
-static double
+current_process_time(struct timespec *ts)
-getrusage_time(void)
 {
 #if defined(HAVE_CLOCK_GETTIME) && defined(CLOCK_PROCESS_CPUTIME_ID)
     {
         static int try_clock_gettime = 1;
-        struct timespec ts;
+        if (try_clock_gettime && clock_gettime(CLOCK_PROCESS_CPUTIME_ID, ts) == 0) {
-        if (try_clock_gettime && clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts) == 0) {
+            return true;
-            return ts.tv_sec + ts.tv_nsec * 1e-9;
         }
         else {
             try_clock_gettime = 0;
@@ -12434,7 +12450,9 @@ getrusage_time(void)
         struct timeval time;
         if (getrusage(RUSAGE_SELF, &usage) == 0) {
             time = usage.ru_utime;
-            return time.tv_sec + time.tv_usec * 1e-6;
+            ts->tv_sec = time.tv_sec;
+            ts->tv_nsec = time.tv_usec * 1000;
+            return true;
         }
     }
 #endif
@@ -12443,28 +12461,33 @@ getrusage_time(void)
     {
 	FILETIME creation_time, exit_time, kernel_time, user_time;
         ULARGE_INTEGER ui;
-	LONG_LONG q;
-	double t;
 
         if (GetProcessTimes(GetCurrentProcess(),
 			    &creation_time, &exit_time, &kernel_time, &user_time) != 0) {
             memcpy(&ui, &user_time, sizeof(FILETIME));
-	    q = ui.QuadPart / 10L;
+#define PER100NSEC (uint64_t)(1000 * 1000 * 10)
-	    t = (DWORD)(q % 1000000L) * 1e-6;
+            ts->tv_nsec = (long)(ui.QuadPart % PER100NSEC);
-	    q /= 1000000L;
+            ts->tv_sec  = (time_t)(ui.QuadPart / PER100NSEC);
-#ifdef __GNUC__
+            return true;
-	    t += q;
-#else
-	    t += (double)(DWORD)(q >> 16) * (1 << 16);
-	    t += (DWORD)q & ~(~0 << 16);
-#endif
-	    return t;
 	}
     }
 #endif
 
+    return false;
+}
+
+static double
+getrusage_time(void)
+{
+    struct timespec ts;
+    if (current_process_time(&ts)) {
+        return ts.tv_sec + ts.tv_nsec * 1e-9;
+    }
+    else {
         return 0.0;
     }
+}
+
 
 static inline void
 gc_prof_setup_new_record(rb_objspace_t *objspace, unsigned int reason)

gc.rb

@@ -266,6 +266,51 @@ module GC
   def self.using_rvargc?
     GC::INTERNAL_CONSTANTS[:SIZE_POOL_COUNT] > 1
   end
+
+
+  # call-seq:
+  #    GC.measure_total_time = true/false
+  #
+  # Enable to measure GC time.
+  # You can get the result with `GC.stat(:time)`.
+  # Note that the GC time measurement can introduce the performance regression.
+  def self.measure_total_time=(flag)
+    Primitive.cstmt! %{
+      rb_objspace.flags.measure_gc = RTEST(flag) ? TRUE : FALSE;
+      return flag;
+    }
+  end
+
+  # call-seq:
+  #    GC.measure_total_time -> true/false
+  #
+  # Return measure_total_time flag (default: true).
+  # Note that measurement can affect the application performance.
+  def self.measure_total_time
+    Primitive.cexpr! %{
+      RBOOL(rb_objspace.flags.measure_gc)
+    }
+  end
+
+  Primitive.cinit! %{
+    #if SIZEOF_LONG == 8
+      #define UINT64_2NUM RB_ULONG2NUM
+    #elif SIZEOF_LONG_LONG == 8
+      #define UINT64_2NUM RB_ULL2NUM
+    #else
+      #error Can not make UINT64_2NUM
+    #endif
+  }
+
+  # call-seq:
+  #    GC.total_time -> int
+  #
+  # Return measured GC total time in nano seconds.
+  def self.total_time
+    Primitive.cexpr! %{
+      UINT64_2NUM(rb_objspace.profile.total_time_ns)
+    }
+  end
 end
 
 module ObjectSpace