ruby-changes:69815
From: Koichi <ko1@a...>
Date: Fri, 19 Nov 2021 08:32:23 +0900 (JST)
Subject: [ruby-changes:69815] c347038d4e (master): GC measurement feature
https://git.ruby-lang.org/ruby.git/commit/?id=c347038d4e From c347038d4ea246d686fcd4ddc8761a91e4dd25ab Mon Sep 17 00:00:00 2001 From: Koichi Sasada <ko1@a...> Date: Wed, 10 Nov 2021 16:52:22 +0900 Subject: 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 | 1 + gc.c | 97 +++++++++++++++++++++++++++++++++++++++------------------------ gc.rb | 45 +++++++++++++++++++++++++++++ 3 files changed, 106 insertions(+), 37 deletions(-) diff --git a/common.mk b/common.mk index 714882a9b0d..ebf98993f64 100644 --- a/common.mk +++ b/common.mk @@ -5852,6 +5852,7 @@ gc.$(OBJEXT): {$(VPATH)}encoding.h https://github.com/ruby/ruby/blob/trunk/common.mk#L5852 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 diff --git a/gc.c b/gc.c index 1029306cfdb..0bb44d24ae2 100644 --- a/gc.c +++ b/gc.c @@ -732,6 +732,7 @@ typedef struct rb_objspace { https://github.com/ruby/ruby/blob/trunk/gc.c#L732 #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 { https://github.com/ruby/ruby/blob/trunk/gc.c#L808 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 * https://github.com/ruby/ruby/blob/trunk/gc.c#L1719 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) https://github.com/ruby/ruby/blob/trunk/gc.c#L9167 } } -#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,33 +9182,47 @@ gc_enter_event_measure_p(enum gc_enter_event event) https://github.com/ruby/ruby/blob/trunk/gc.c#L9182 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)) { - clock_gettime(CLOCK_MONOTONIC, &objspace->profile.start_time); + if (gc_enter_event_measure_p(objspace, event)) { + 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 (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; + if ((objspace->profile.start_time.tv_sec > 0 || + objspace->profile.start_time.tv_nsec > 0) && + current_process_time(&end_time)) { - objspace->profile.total_time_ns += ns; + if (end_time.tv_sec < objspace->profile.start_time.tv_sec) { + return; // ignore + } + 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; + } + } } } @@ -12411,16 +12429,14 @@ wmap_size(VALUE self) https://github.com/ruby/ruby/blob/trunk/gc.c#L12429 #define GC_PROFILE_RECORD_DEFAULT_SIZE 100 -/* return sec in user time */ -static double -getrusage_time(void) +static bool +current_process_time(struct timespec *ts) { #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) { - return ts.tv_sec + ts.tv_nsec * 1e-9; + if (try_clock_gettime && clock_gettime(CLOCK_PROCESS_CPUTIME_ID, ts) == 0) { + return true; } else { try_clock_gettime = 0; @@ -12434,7 +12450,9 @@ getrusage_time(void) https://github.com/ruby/ruby/blob/trunk/gc.c#L12450 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 @@ -12442,30 +12460,35 @@ getrusage_time(void) https://github.com/ruby/ruby/blob/trunk/gc.c#L12460 #ifdef _WIN32 { FILETIME creation_time, exit_time, kernel_time, user_time; - ULARGE_INTEGER ui; - LONG_LONG q; - double t; + ULARGE_INTEGER ui; - if (GetProcessTimes(GetCurrentProcess(), + if (GetProcessTimes(GetCurrentProcess(), &creation_time, &exit_time, &kernel_time, &user_time) != 0) { - memcpy(&ui, &user_time, sizeof(FILETIME)); - q = ui.QuadPart / 10L; - t = (DWORD)(q % 1000000L) * 1e-6; - q /= 1000000L; -#ifdef __GNUC__ - t += q; -#else - t += (double)(DWORD)(q >> 16) * (1 << 16); - t += (DWORD)q & ~(~0 << 16); -#endif - return t; + memcpy(&ui, &user_time, sizeof(FILETIME)); +#define PER100NSEC (uint64_t)(1000 * 1000 * 10) + ts->tv_nsec = (long)(ui.QuadPart % PER100NSEC); + ts->tv_sec = (time_t)(ui.QuadPart / PER100NSEC); + return true; } } #endif - return 0.0; + 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) { diff --git a/gc.rb b/gc.rb index e80d6635a78..d3f80dbaa8a 100644 --- a/gc.rb +++ b/gc.rb @@ -266,6 +266,51 @@ module GC https://github.com/ruby/ruby/blob/trunk/gc.rb#L266 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 -- cgit v1.2.1 -- ML: ruby-changes@q... Info: http://www.atdot.net/~ko1/quickml/