ruby-changes:6975
From: nari <ko1@a...>
Date: Mon, 11 Aug 2008 18:37:12 +0900 (JST)
Subject: [ruby-changes:6975] Ruby:r18493 (trunk):
nari 2008-08-11 18:36:57 +0900 (Mon, 11 Aug 2008) New Revision: 18493 http://svn.ruby-lang.org/cgi-bin/viewvc.cgi?view=rev&revision=18493 Log: * gc.c: added GC::Profiler. Modified files: trunk/ChangeLog trunk/gc.c Index: ChangeLog =================================================================== --- ChangeLog (revision 18492) +++ ChangeLog (revision 18493) @@ -1,3 +1,7 @@ +Mon Aug 11 18:28:02 2008 Narihiro Nakamura <authorNari@g...> + + * gc.c: added GC::Profiler. + Mon Aug 11 17:26:16 2008 TAKAO Kouji <kouji@t...> * ext/readline/README.ja: added API document for Index: gc.c =================================================================== --- gc.c (revision 18492) +++ gc.c (revision 18493) @@ -92,6 +92,132 @@ #undef GC_DEBUG +/* for GC profile */ +#define GC_PROFILE_MORE_DETAIL 0 +typedef struct gc_profile_record { + double gc_time; + double gc_mark_time; + double gc_sweep_time; + double gc_invoke_time; + size_t heap_use_slots; + size_t heap_live_objects; + size_t heap_free_objects; + size_t heap_total_objects; + size_t heap_use_size; + size_t heap_total_size; + int have_finalize; + size_t allocate_increase; + size_t allocate_limit; +} gc_profile_record; + +static double +getrusage_time(void) +{ + struct rusage usage; + struct timeval time; + getrusage(RUSAGE_SELF, &usage); + time = usage.ru_utime; + return time.tv_sec + time.tv_usec * 1e-6; +} + +#define GC_PROF_TIMER_START do {\ + if (objspace->profile.run) {\ + if (!objspace->profile.record) {\ + objspace->profile.size = 1000;\ + objspace->profile.record = malloc(sizeof(gc_profile_record) * objspace->profile.size);\ + }\ + if (count >= objspace->profile.size) {\ + objspace->profile.size += 1000;\ + objspace->profile.record = realloc(objspace->profile.record, sizeof(gc_profile_record) * objspace->profile.size);\ + }\ + if (!objspace->profile.record) {\ + rb_bug("gc_profile malloc or realloc miss");\ + }\ + MEMZERO(&objspace->profile.record[count], gc_profile_record, 1);\ + gc_time = getrusage_time();\ + objspace->profile.record[count].gc_invoke_time = gc_time - objspace->profile.invoke_time;\ + }\ + } while(0) + +#define GC_PROF_TIMER_STOP do {\ + if (objspace->profile.run) {\ + gc_time = getrusage_time() - gc_time;\ + if(gc_time < 0) gc_time = 0;\ + objspace->profile.record[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 (objspace->profile.run) {\ + mark_time = getrusage_time();\ + }\ + } while(0) + +#define GC_PROF_MARK_TIMER_STOP do {\ + if (objspace->profile.run) {\ + mark_time = getrusage_time() - mark_time;\ + if (mark_time < 0) mark_time = 0;\ + objspace->profile.record[count].gc_mark_time = mark_time;\ + }\ + } while(0) + +#define GC_PROF_SWEEP_TIMER_START do {\ + if (objspace->profile.run) {\ + sweep_time = getrusage_time();\ + }\ + } while(0) + +#define GC_PROF_SWEEP_TIMER_STOP do {\ + if (objspace->profile.run) {\ + sweep_time = getrusage_time() - sweep_time;\ + if (sweep_time < 0) sweep_time = 0;\ + objspace->profile.record[count].gc_sweep_time = sweep_time;\ + }\ + } while(0) +#define GC_PROF_SET_MALLOC_INFO do {\ + if (objspace->profile.run) {\ + size_t count = objspace->profile.count;\ + objspace->profile.record[count].allocate_increase = malloc_increase;\ + objspace->profile.record[count].allocate_limit = malloc_limit; \ + }\ + } while(0) +#define GC_PROF_SET_HEAP_INFO do {\ + if (objspace->profile.run) {\ + size_t count = objspace->profile.count;\ + objspace->profile.record[count].heap_use_slots = heaps_used;\ + objspace->profile.record[count].heap_live_objects = live;\ + objspace->profile.record[count].heap_free_objects = freed;\ + objspace->profile.record[count].heap_total_objects = heaps_used * HEAP_OBJ_LIMIT;\ + objspace->profile.record[count].have_finalize = final_list ? Qtrue : Qfalse;\ + objspace->profile.record[count].heap_use_size = live * sizeof(RVALUE);\ + objspace->profile.record[count].heap_total_size = heaps_used * (HEAP_OBJ_LIMIT * sizeof(RVALUE));\ + }\ + } 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 do {\ + if (objspace->profile.run) {\ + size_t count = objspace->profile.count;\ + objspace->profile.record[count].heap_total_objects = heaps_used * HEAP_OBJ_LIMIT;\ + objspace->profile.record[count].heap_use_size = live * sizeof(RVALUE);\ + objspace->profile.record[count].heap_total_size = heaps_used * HEAP_SIZE;\ + }\ + } while(0) +#endif + + #if defined(_MSC_VER) || defined(__BORLANDC__) || defined(__CYGWIN__) #pragma pack(push, 1) /* magic for reducing sizeof(RVALUE): 24 -> 20 */ #endif @@ -176,6 +302,13 @@ VALUE *ptr; int overflow; } markstack; + struct { + int run; + gc_profile_record *record; + size_t count; + size_t size; + double invoke_time; + } profile; struct gc_list *global_list; unsigned int count; int gc_stress; @@ -309,6 +442,73 @@ return bool; } +/* + * call-seq: + * GC::Profiler.enable? => true or false + * + * returns current status of GC profile mode. + */ + +static VALUE +gc_profile_enable_get(VALUE self) +{ + rb_objspace_t *objspace = &rb_objspace; + return objspace->profile.run; +} + +/* + * call-seq: + * GC::Profiler.enable => nil + * + * updates GC profile mode. + * start profiler for GC. + * + */ + +static VALUE +gc_profile_enable(void) +{ + rb_objspace_t *objspace = &rb_objspace; + + objspace->profile.run = Qtrue; + return Qnil; +} + +/* + * call-seq: + * GC::Profiler.disable => nil + * + * updates GC profile mode. + * stop profiler for GC. + * + */ + +static VALUE +gc_profile_disable(void) +{ + rb_objspace_t *objspace = &rb_objspace; + + objspace->profile.run = Qfalse; + return Qnil; +} + +/* + * call-seq: + * GC::Profiler.clear => nil + * + * clear before profile data. + * + */ + +static VALUE +gc_profile_clear(void) +{ + rb_objspace_t *objspace = &rb_objspace; + MEMZERO(objspace->profile.record, gc_profile_record, objspace->profile.size); + objspace->profile.count = 0; + return Qnil; +} + static void * vm_xmalloc(rb_objspace_t *objspace, size_t size) { @@ -634,6 +834,7 @@ assign_heap_slot(objspace); } heaps_inc = 0; + objspace->profile.invoke_time = getrusage_time(); } @@ -1461,6 +1662,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; @@ -1474,11 +1676,13 @@ /* clear finalization list */ if (final_list) { + GC_PROF_SET_HEAP_INFO; deferred_final_list = final_list; RUBY_VM_SET_FINALIZER_INTERRUPT(GET_THREAD()); } else{ free_unused_heaps(objspace); + GC_PROF_SET_HEAP_INFO; } } @@ -1706,6 +1910,7 @@ { struct gc_list *list; rb_thread_t *th = GET_THREAD(); + INIT_GC_PROF_PARAMS; if (GC_NOTIFY) printf("start garbage_collect()\n"); @@ -1725,6 +1930,8 @@ during_gc++; objspace->count++; + GC_PROF_TIMER_START; + GC_PROF_MARK_TIMER_START; SET_STACK_END; init_mark_stack(objspace); @@ -1765,9 +1972,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; } @@ -2354,6 +2565,7 @@ } rb_hash_aset(hash, ID2SYM(rb_intern("TOTAL")), SIZET2NUM(total)); rb_hash_aset(hash, ID2SYM(rb_intern("FREE")), SIZET2NUM(freed)); + for (i = 0; i <= T_MASK; i++) { VALUE type; switch (i) { @@ -2441,7 +2653,125 @@ } #endif +VALUE +gc_profile_record_get(void) +{ + VALUE prof; + VALUE gc_profile = rb_ary_new(); + size_t i; + rb_objspace_t *objspace = (&rb_objspace); + + if (!objspace->profile.run) { + 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.record[i].gc_time)); + rb_hash_aset(prof, ID2SYM(rb_intern("GC_INVOKE_TIME")), DOUBLE2NUM(objspace->profile.record[i].gc_invoke_time)); + rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_USE_SIZE")), rb_uint2inum(objspace->profile.record[i].heap_use_size)); + rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_TOTAL_SIZE")), rb_uint2inum(objspace->profile.record[i].heap_total_size)); + rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_TOTAL_OBJECTS")), rb_uint2inum(objspace->profile.record[i].heap_total_objects)); +#if GC_PROFILE_MORE_DETAIL + rb_hash_aset(prof, ID2SYM(rb_intern("GC_MARK_TIME")), DOUBLE2NUM(objspace->profile.record[i].gc_mark_time)); + rb_hash_aset(prof, ID2SYM(rb_intern("GC_SWEEP_TIME")), DOUBLE2NUM(objspace->profile.record[i].gc_sweep_time)); + rb_hash_aset(prof, ID2SYM(rb_intern("ALLOCATE_INCREASE")), rb_uint2inum(objspace->profile.record[i].allocate_increase)); + rb_hash_aset(prof, ID2SYM(rb_intern("ALLOCATE_LIMIT")), rb_uint2inum(objspace->profile.record[i].allocate_limit)); + rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_USE_SLOTS")), rb_uint2inum(objspace->profile.record[i].heap_use_slots)); + rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_LIVE_OBJECTS")), rb_uint2inum(objspace->profile.record[i].heap_live_objects)); + rb_hash_aset(prof, ID2SYM(rb_intern("HEAP_FREE_OBJECTS")), rb_uint2inum(objspace->profile.record[i].heap_free_objects)); + rb_hash_aset(prof, ID2SYM(rb_intern("HAVE_FINALIZE")), objspace->profile.record[i].have_finalize); +#endif + rb_ary_push(gc_profile, prof); + } + + return gc_profile; +} + /* + * call-seq: + * GC::Profiler.result -> string + * + * Report profile data to string. + * + * It returns a string as: + * GC 1 invokes. + * Index Invoke Time(sec) Use Size(byte) Total Size(byte) Total Object GC time(ms) + * 1 0.012 159240 212940 10647 0.00000000000001530000 + */ + +VALUE +gc_profile_result(void) +{ + rb_objspace_t *objspace = &rb_objspace; + VALUE record = gc_profile_record_get(); + VALUE result = rb_str_new2(""); + int i; + char buf[1024]; + + if(objspace->profile.run && objspace->profile.count) { + sprintf(buf, "GC %1$d invokes.\n", NUM2INT(gc_count(0))); + rb_str_concat(result, rb_str_new2(buf)); + rb_str_concat(result, rb_str_new2("Index Invoke Time(sec) Use Size(byte) Total Size(byte) Total Object GC Time(ms)\n")); + for(i = 0; i < (int)RARRAY_LEN(record); i++) { + memset(buf, 0, 1024); + VALUE r = RARRAY_PTR(record)[i]; + sprintf(buf, "%1$5d %2$19.3f %3$20d %4$20d %5$20d %6$30.20f\n", + i+1, NUM2DBL(rb_hash_aref(r, ID2SYM(rb_intern("GC_INVOKE_TIME")))), + NUM2INT(rb_hash_aref(r, ID2SYM(rb_intern("HEAP_USE_SIZE")))), + NUM2INT(rb_hash_aref(r, ID2SYM(rb_intern("HEAP_TOTAL_SIZE")))), + NUM2INT(rb_hash_aref(r, ID2SYM(rb_intern("HEAP_TOTAL_OBJECTS")))), + NUM2DBL(rb_hash_aref(r, ID2SYM(rb_intern("GC_TIME"))))*100); + rb_str_concat(result, rb_str_new2(buf)); + } +#if GC_PROFILE_MORE_DETAIL + rb_str_concat(result, rb_str_new2("\n\n")); + rb_str_concat(result, rb_str_new2("More detail.\n")); + rb_str_concat(result, rb_str_new2("Index Allocate Increase Allocate Limit Use Slot Have Finalize Mark Time(ms) Sweep Time(ms)\n")); + for(i = 0; i < (int)RARRAY_LEN(record); i++) { + memset(buf, 0, 1024); + VALUE r = RARRAY_PTR(record)[i]; + sprintf(buf, "%1$5d %2$17d %3$17d %4$9d %5$14s %6$25.20f %7$25.20f\n", + i+1, NUM2INT(rb_hash_aref(r, ID2SYM(rb_intern("ALLOCATE_INCREASE")))), + NUM2INT(rb_hash_aref(r, ID2SYM(rb_intern("ALLOCATE_LIMIT")))), + NUM2INT(rb_hash_aref(r, ID2SYM(rb_intern("HEAP_USE_SLOTS")))), + rb_hash_aref(r, ID2SYM(rb_intern("HAVE_FINALIZE")))? "true" : "false", + NUM2DBL(rb_hash_aref(r, ID2SYM(rb_intern("GC_MARK_TIME"))))*100, + NUM2DBL(rb_hash_aref(r, ID2SYM(rb_intern("GC_SWEEP_TIME"))))*100); + rb_str_concat(result, rb_str_new2(buf)); + } +#endif + } + return result; +} + + +/* + * call-seq: + * GC::Profiler.report + * + * GC::Profiler.result display + * + */ + +VALUE +gc_profile_report(int argc, VALUE *argv, VALUE self) +{ + VALUE out; + + if (argc == 0) { + out = rb_stdout; + } + else { + rb_scan_args(argc, argv, "01", &out); + } + rb_io_write(out, gc_profile_result()); + + return Qnil; +} + + +/* * 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. @@ -2451,6 +2781,7 @@ Init_GC(void) { VALUE rb_mObSpace; + VALUE rb_mProfiler; rb_mGC = rb_define_module("GC"); rb_define_singleton_method(rb_mGC, "start", rb_gc_start, 0); @@ -2461,6 +2792,14 @@ rb_define_singleton_method(rb_mGC, "count", gc_count, 0); rb_define_method(rb_mGC, "garbage_collect", rb_gc_start, 0); + rb_mProfiler = rb_define_module_under(rb_mGC, "Profiler"); + rb_define_singleton_method(rb_mProfiler, "enabled?", gc_profile_enable_get, 0); + rb_define_singleton_method(rb_mProfiler, "enable", gc_profile_enable, 0); + rb_define_singleton_method(rb_mProfiler, "disable", gc_profile_disable, 0); + rb_define_singleton_method(rb_mProfiler, "clear", gc_profile_clear, 0); + rb_define_singleton_method(rb_mProfiler, "result", gc_profile_result, 0); + rb_define_singleton_method(rb_mProfiler, "report", gc_profile_report, -1); + rb_mObSpace = rb_define_module("ObjectSpace"); rb_define_module_function(rb_mObSpace, "each_object", os_each_obj, -1); rb_define_module_function(rb_mObSpace, "garbage_collect", rb_gc_start, 0); -- ML: ruby-changes@q... Info: http://www.atdot.net/~ko1/quickml/