From: authorNari <authornari@...>
Date: 2008-07-13T23:25:58+09:00
Subject: [ruby-dev:35469] Re: make profiler for gc

nariです。

動的に変更できるパッチも併せて作成しました。

「GC.profile=true」でプロファイルし始めて、
「GC.profile_report」で結果を返してくれます。

また、通常はGC全体の時間のみ返しますが、コンパイル時に
#define GC_PROFILE_MORE_DETAIL 1
にする事でmark/sweepにかかった時間等の詳細なデータ
を返すようにしました。

速度的にもそれ程重くないようですし、私としてはこちらの方が
良いように思うのですがいかがでしょうか？

ベンチマーク
               normal       profile
vm3_gc	2.359　　	2.375


=============
nari@nari-laptop ~/s/r/ruby-trunk> make benchmark OPTS="-r 10"
ruby ./benchmark/driver.rb -v \
	            --executables="ruby; ./miniruby -I./lib -I.ext/common
-I./- -r./ext/purelib.rb  ./runruby.rb --extout=.ext  --" \
	            --pattern='bm_' --directory=./benchmark -r 10
"1.9.0"
2008-07-13 22:42:41 +0900
target 0: ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]
target 1: ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]

-----------------------------------------------------------
vm3_gc

#! /usr/bin/ruby
5000.times do
  100.times do
    {"xxxx"=>"yyyy"}
  end
  GC.start
end

ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	2.35910558700562
ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	2.51446843147278
ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	2.90153551101685
ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	2.67432570457458
ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	2.74260926246643
ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	3.18074822425842
ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	2.78490710258484
ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	2.73308610916138
ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	2.76204562187195
ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	2.78759121894836
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.6268355846405
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.49695825576782
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.47115182876587
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.37481427192688
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.85433769226074
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.76230645179749
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.74803757667542
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.48261618614197
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.42063546180725
ruby 1.9.0 (2008-07-13 revision 17780) [i686-linux]	2.67150807380676

-----------------------------------------------------------
raw data:

[["vm3_gc",
  [[2.35910558700562,
    2.51446843147278,
    2.90153551101685,
    2.67432570457458,
    2.74260926246643,
    3.18074822425842,
    2.78490710258484,
    2.73308610916138,
    2.76204562187195,
    2.78759121894836],
   [2.6268355846405,
    2.49695825576782,
    2.47115182876587,
    2.37481427192688,
    2.85433769226074,
    2.76230645179749,
    2.74803757667542,
    2.48261618614197,
    2.42063546180725,
    2.67150807380676]]]]

Elapesed time: 53.357572675 (sec)
-----------------------------------------------------------
benchmark results:
minimum results in each 10 measurements.
name	ruby 1.9.0 (2008-07-11 revision 17780) [i686-linux]	ruby 1.9.0
(2008-07-13 revision 17780) [i686-linux]
vm3_gc	2.359	2.375


Index: gc.c
===================================================================
--- gc.c	(リビジョン 18054)
+++ gc.c	(作業コピー)
@@ -92,6 +92,117 @@

 #undef GC_DEBUG

+/* for GC profile */
+#define GC_PROFILE_MORE_DETAIL 0
+typedef struct gc_profile_data {
+    double gc_time;
+    double gc_mark_time;
+    double gc_sweep_time;
+    size_t heaps_use_count;
+    size_t heaps_live;
+    size_t heaps_free;
+    size_t heaps_all_objects;
+    int is_exist_finalize;
+    size_t allocate_increase;
+    size_t allocate_limit;
+} gc_profile_data;
+
+/* referenced document http://kzk9.net/column/time.html */
+static double
+getrusage_time(void)
+{
+    struct rusage usage;
+    struct timeval time;
+    getrusage(RUSAGE_SELF, &usage);
+    time = usage.ru_utime;
+    return time.tv_sec + (double)time.tv_usec*1e-6;
+}
+
+#define GC_PROF_TIMER_START do {					\
+	if (ruby_gc_profile) {						\
+	    if (!objspace->profile.data) {				\
+		objspace->profile.size = 1000;				\
+		objspace->profile.data = malloc(sizeof(gc_profile_data) *
objspace->profile.size); \
+	    }								\
+	    if (count >= objspace->profile.size) {			\
+		objspace->profile.size += 1000;				\
+		objspace->profile.data = realloc(objspace->profile.data,
sizeof(gc_profile_data) * objspace->profile.size); \
+	    }								\
+	    if (!objspace->profile.data) {				\
+		rb_bug("gc_profile malloc or realloc miss");		\
+	    }								\
+	    MEMZERO(&objspace->profile.data[count], gc_profile_data, 1); \
+	    gc_time = getrusage_time();					\
+	}								\
+    } while(0)
+
+#define GC_PROF_TIMER_STOP do {					\
+	if (ruby_gc_profile) {					\
+	    gc_time = getrusage_time() - gc_time;		\
+	    objspace->profile.data[count].gc_time = gc_time;	\
+	    objspace->profile.count++;				\
+	}							\
+    } while(0)
+
+#if GC_PROFILE_MORE_DETAIL
+#define INIT_GC_PROF_PARAMS double gc_time = 0, mark_time = 0,
sweep_time = 0;	\
+    size_t count = objspace->profile.count
+
+#define GC_PROF_MARK_TIMER_START do {		\
+	if (ruby_gc_profile) {			\
+	    mark_time = getrusage_time();	\
+	}					\
+    } while(0)
+
+#define GC_PROF_MARK_TIMER_STOP do {					\
+	if (ruby_gc_profile) {						\
+	    mark_time = getrusage_time() - mark_time;			\
+	    objspace->profile.data[count].gc_mark_time = mark_time;	\
+	}								\
+    } while(0)
+
+#define GC_PROF_SWEEP_TIMER_START do {		\
+	if (ruby_gc_profile) {			\
+	    sweep_time = getrusage_time();	\
+	}					\
+    } while(0)
+
+#define GC_PROF_SWEEP_TIMER_STOP do {					\
+	if (ruby_gc_profile) {						\
+	    sweep_time = getrusage_time() - sweep_time;			\
+	    objspace->profile.data[count].gc_sweep_time = sweep_time;	\
+	}								\
+    } while(0)
+#define GC_PROF_SET_MALLOC_INFO do {					\
+	if (ruby_gc_profile) {						\
+	    size_t count = objspace->profile.count;			\
+	    objspace->profile.data[count].allocate_increase = malloc_increase; \
+	    objspace->profile.data[count].allocate_limit = malloc_limit; \
+	}								\
+    } while(0)
+#define GC_PROF_SET_HEAP_INFO do {					\
+	if (ruby_gc_profile) {						\
+	    size_t count = objspace->profile.count;			\
+	    objspace->profile.data[count].heaps_use_count = heaps_used;	\
+	    objspace->profile.data[count].heaps_live = live;		\
+	    objspace->profile.data[count].heaps_free = freed;		\
+	    objspace->profile.data[count].heaps_all_objects = heaps_used *
HEAP_OBJ_LIMIT; \
+	    objspace->profile.data[count].is_exist_finalize = final_list ?
Qtrue : Qfalse; \
+	}								\
+    } while(0)
+
+#else
+#define INIT_GC_PROF_PARAMS double gc_time = 0;\
+    size_t count = objspace->profile.count
+#define GC_PROF_MARK_TIMER_START
+#define GC_PROF_MARK_TIMER_STOP
+#define GC_PROF_SWEEP_TIMER_START
+#define GC_PROF_SWEEP_TIMER_STOP
+#define GC_PROF_SET_MALLOC_INFO
+#define GC_PROF_SET_HEAP_INFO
+#endif
+
+
 #if defined(_MSC_VER) || defined(__BORLANDC__) || defined(__CYGWIN__)
 #pragma pack(push, 1) /* magic for reducing sizeof(RVALUE): 24 -> 20 */
 #endif
@@ -176,6 +287,12 @@
 	VALUE *ptr;
 	int overflow;
     } markstack;
+    struct {
+	int run;
+	gc_profile_data *data;
+	size_t count;
+	size_t size;
+    } profile;
     struct gc_list *global_list;
     unsigned int count;
     int gc_stress;
@@ -209,6 +326,7 @@
 #define mark_stack_overflow	objspace->markstack.overflow
 #define global_List		objspace->global_list
 #define ruby_gc_stress		objspace->gc_stress
+#define ruby_gc_profile		objspace->profile.run

 #define need_call_final 	(finalizer_table && finalizer_table->num_entries)

@@ -309,6 +427,46 @@
     return bool;
 }

+/*
+ *  call-seq:
+ *    GC.profile                 => true or false
+ *
+ *  returns current status of GC profile mode.
+ */
+
+static VALUE
+gc_profile_get(VALUE self)
+{
+    rb_objspace_t *objspace = &rb_objspace;
+    return ruby_gc_profile ? Qtrue : Qfalse;
+}
+
+/*
+ *  call-seq:
+ *    GC.profile = bool          => bool
+ *
+ *  updates GC profile mode.
+ *
+ *  When GC.profile = true, run profiler for GC.
+ *
+ *  When GC.profile = false, delete before profiler data.
+ *
+ *  if want more detail info. please use GC_PROFILE_MORE_DETAIL.
+ */
+
+static VALUE
+gc_profile_set(VALUE self, VALUE bool)
+{
+    rb_objspace_t *objspace = &rb_objspace;
+    rb_secure(2);
+    ruby_gc_profile = RTEST(bool);
+    if (!ruby_gc_profile) {
+	MEMZERO(objspace->profile.data, gc_profile_data, objspace->profile.size);
+	objspace->profile.count = 0;
+    }
+    return bool;
+}
+
 static void *
 vm_xmalloc(rb_objspace_t *objspace, size_t size)
 {
@@ -1440,6 +1598,7 @@
 	    freed += n;
 	}
     }
+    GC_PROF_SET_MALLOC_INFO;
     if (malloc_increase > malloc_limit) {
 	malloc_limit += (malloc_increase - malloc_limit) * (double)live /
(live + freed);
 	if (malloc_limit < GC_MALLOC_LIMIT) malloc_limit = GC_MALLOC_LIMIT;
@@ -1453,10 +1612,12 @@

     /* clear finalization list */
     if (final_list) {
+	GC_PROF_SET_HEAP_INFO;
 	deferred_final_list = final_list;
 	return;
     }
     free_unused_heaps(objspace);
+    GC_PROF_SET_HEAP_INFO;
 }

 void
@@ -1672,6 +1833,7 @@
 {
     struct gc_list *list;
     rb_thread_t *th = GET_THREAD();
+    INIT_GC_PROF_PARAMS;

     if (GC_NOTIFY) printf("start garbage_collect()\n");

@@ -1691,6 +1853,8 @@
     during_gc++;
     objspace->count++;

+    GC_PROF_TIMER_START;
+    GC_PROF_MARK_TIMER_START;
     SET_STACK_END;

     init_mark_stack(objspace);
@@ -1731,9 +1895,13 @@
 	    gc_mark_rest(objspace);
 	}
     }
+    GC_PROF_MARK_TIMER_STOP;

+    GC_PROF_SWEEP_TIMER_START;
     gc_sweep(objspace);
+    GC_PROF_SWEEP_TIMER_STOP;

+    GC_PROF_TIMER_STOP;
     if (GC_NOTIFY) printf("end garbage_collect()\n");
     return Qtrue;
 }
@@ -2387,6 +2555,53 @@
 #endif

 /*
+ *  call-seq:
+ *     GC.profile_report -> hash
+ *
+ *  Report profile data to wrap hash.
+ *
+ *  It returns a hash as:
+ *  {:gc_count => 20 :report => [{:gc_time => 0.001}, {:gc_time => 0.002}]}
+ *
+ *  if GC_PROFILE_MORE_DETAIL is 1:
+ *  {:gc_count => 20 :report => [{:gc_time => 0.001, :gc_mark_time =>
0.00004, :gc_sweep_time => 0.00006 }, ... }]}
+ */
+
+VALUE
+gc_profile_report(void)
+{
+    VALUE prof = 0;
+    VALUE res = rb_hash_new();
+    VALUE datas = rb_ary_new();
+    size_t i;
+    rb_objspace_t *objspace = (&rb_objspace);
+
+    if (!ruby_gc_profile) {
+	return Qnil;
+    }
+
+    for (i =0; i < objspace->profile.count; i++) {
+	prof = rb_hash_new();
+        rb_hash_aset(prof, ID2SYM(rb_intern("gc_time")),
DOUBLE2NUM(objspace->profile.data[i].gc_time));
+#if GC_PROFILE_MORE_DETAIL
+        rb_hash_aset(prof, ID2SYM(rb_intern("gc_mark_time")),
DOUBLE2NUM(objspace->profile.data[i].gc_mark_time));
+	rb_hash_aset(prof, ID2SYM(rb_intern("gc_sweep_time")),
DOUBLE2NUM(objspace->profile.data[i].gc_sweep_time));
+        rb_hash_aset(prof, ID2SYM(rb_intern("allocate_increase")),
rb_uint2inum(objspace->profile.data[i].allocate_increase));
+        rb_hash_aset(prof, ID2SYM(rb_intern("allocate_limit")),
rb_uint2inum(objspace->profile.data[i].allocate_limit));
+        rb_hash_aset(prof, ID2SYM(rb_intern("heaps_use_count")),
rb_uint2inum(objspace->profile.data[i].heaps_use_count));
+        rb_hash_aset(prof, ID2SYM(rb_intern("heaps_live")),
rb_uint2inum(objspace->profile.data[i].heaps_live));
+        rb_hash_aset(prof, ID2SYM(rb_intern("heaps_free")),
rb_uint2inum(objspace->profile.data[i].heaps_free));
+        rb_hash_aset(prof, ID2SYM(rb_intern("heaps_all_objects")),
rb_uint2inum(objspace->profile.data[i].heaps_all_objects));
+        rb_hash_aset(prof, ID2SYM(rb_intern("is_exist_finalize")),
objspace->profile.data[i].is_exist_finalize);
+#endif
+	rb_ary_push(datas, prof);
+    }
+    rb_hash_aset(res, ID2SYM(rb_intern("gc_count")),
rb_uint2inum(objspace->count));
+    rb_hash_aset(res, ID2SYM(rb_intern("report")), datas);
+    return res;
+}
+
+/*
  *  The <code>GC</code> module provides an interface to Ruby's mark and
  *  sweep garbage collection mechanism. Some of the underlying methods
  *  are also available via the <code>ObjectSpace</code> module.
@@ -2404,6 +2619,9 @@
     rb_define_singleton_method(rb_mGC, "stress", gc_stress_get, 0);
     rb_define_singleton_method(rb_mGC, "stress=", gc_stress_set, 1);
     rb_define_singleton_method(rb_mGC, "count", gc_count, 0);
+    rb_define_singleton_method(rb_mGC, "profile", gc_profile_get, 0);
+    rb_define_singleton_method(rb_mGC, "profile=", gc_profile_set, 1);
+    rb_define_singleton_method(rb_mGC, "profile_report", gc_profile_report, 0);
     rb_define_method(rb_mGC, "garbage_collect", rb_gc_start, 0);

     rb_mObSpace = rb_define_module("ObjectSpace");