From: Robert Feldt <feldt@...>
Date: 2001-07-02T22:11:18+09:00
Subject: [ruby-talk:17144] Timing GC

Hi,

Sometimes when profiling I find myself wanting to know how much time is
spent in GC. I couldn't find a way to do it in pure Ruby so below you'll
find a patch for adding a GC.time_spent method. It returns the amount of
user time the process has spent in GC. This script shows the method in
(artificial) use:

start_gc, start = GC.time_spent, Process.times.utime
a = Array.new, i = 0
100000.times {a.push (1<<i); i+=1 if rand(10)==0}
a = nil
GC.start
time_in_gc, time = GC.time_spent-start_gc, Process.times.utime-start
puts "Elapsed: #{time} seconds of which #{time_in_gc} was spent in GC
(#{time_in_gc*100.0/time}%)"

with the output:

$ ruby test_gc_time_spent.rb
Elapsed: 2.383 seconds of which 0.642 was spent in GC (26.94083089%)

RCR? Correct? Comments? Effect on performance?

Here are some alternative solutions I've contemplated to get the same
info:

1. Add two events to trace funcs: "gc-start" "gc-finish"
    Pro: * "Easy" and using existing framework
         * Can subtract time when profiling
    Con: * Trace funcs adds large overhead. Not good for profiling (since
             you have some performance problem and want to use realistic
             input).

2. set_gc_trace_func
    Pro: * Faster than above
         * Can subtract time when profiling
    Con: * Can't add separate trace funcs for each new event

3. Hard-coded timer (this is the one in the diff below)
    Pro: Simple and fast
    Con: Feature bloat

Other ways/ideas?

Somthing like a "polished" 2 (ie. part of a new event trapping "system") 
is probably what I'd like to see in the long term. Comments?

Regards,

Robert

--- gc.c.old	Mon Jul  2 14:21:36 2001
+++ gc.c	Mon Jul  2 14:59:54 2001
@@ -48,6 +48,35 @@
 
 static void run_final();
 
+#ifdef HAVE_SYS_TIMES_H
+#include <sys/times.h>
+#endif
+double gc_timer_start, gc_timer_total;
+
+double process_user_time()
+{
+  struct tms buffer;
+  times(&buffer);
+  return (double)buffer.tms_utime;
+}
+
+static VALUE
+rb_gc_time_spent()
+{
+#if defined(HAVE_TIMES) && !defined(__CHECKER__)
+#ifndef HZ
+# ifdef CLK_TCK
+#   define HZ CLK_TCK
+# else
+#   define HZ 60
+# endif
+#endif /* HZ */
+  return rb_float_new(gc_timer_total / HZ);
+#else
+  rb_notimplement();
+#endif
+}
+
 #ifndef GC_MALLOC_LIMIT
 #if defined(MSDOS) || defined(__human68k__)
 #define GC_MALLOC_LIMIT 200000
@@ -742,6 +771,7 @@
     if (freed < FREE_MIN) {
 	add_heap();
     }
+    gc_timer_total += (process_user_time() - gc_timer_start);
     during_gc = 0;
 
     /* clear finalization list */
@@ -978,6 +1008,7 @@
 
     if (during_gc) return;
     during_gc++;
+    gc_timer_start = process_user_time();
 
     /* mark frame stack */
     for (frame = ruby_frame; frame; frame = frame->prev) {
@@ -1329,6 +1360,7 @@
     rb_define_singleton_method(rb_mGC, "enable", rb_gc_enable, 0);
     rb_define_singleton_method(rb_mGC, "disable", rb_gc_disable, 0);
     rb_define_method(rb_mGC, "garbage_collect", rb_gc_start, 0);
+    rb_define_singleton_method(rb_mGC, "time_spent", rb_gc_time_spent,
0);
 
     rb_mObSpace = rb_define_module("ObjectSpace");
     rb_define_module_function(rb_mObSpace, "each_object", os_each_obj,
-1);