diff --git a/gc.c b/gc.c index 4e3c2282de..c4c245ee0b 100644 --- a/gc.c +++ b/gc.c @@ -826,8 +826,10 @@ typedef struct rb_objspace { /* basic statistics */ size_t count; size_t total_freed_objects; - uint64_t total_time_ns; - struct timespec start_time; + uint64_t marking_time_ns; + struct timespec marking_start_time; + uint64_t sweeping_time_ns; + struct timespec sweeping_start_time; } profile; struct gc_list *global_list; @@ -1242,6 +1244,10 @@ enum gc_enter_event { static inline void gc_enter(rb_objspace_t *objspace, enum gc_enter_event event, unsigned int *lock_lev); static inline void gc_exit(rb_objspace_t *objspace, enum gc_enter_event event, unsigned int *lock_lev); +static void gc_marking_enter(rb_objspace_t *objspace); +static void gc_marking_exit(rb_objspace_t *objspace); +static void gc_sweeping_enter(rb_objspace_t *objspace); +static void gc_sweeping_exit(rb_objspace_t *objspace); static void gc_marks_start(rb_objspace_t *objspace, int full); static void gc_marks_finish(rb_objspace_t *objspace); @@ -4572,7 +4578,7 @@ rb_objspace_call_finalizer(rb_objspace_t *objspace) } } - gc_exit(objspace, false, &lock_lev); + gc_exit(objspace, gc_enter_event_finalizer, &lock_lev); finalize_deferred_heap_pages(objspace); @@ -6058,6 +6064,8 @@ gc_sweep_continue(rb_objspace_t *objspace, rb_size_pool_t *sweep_size_pool, rb_h GC_ASSERT(dont_gc_val() == FALSE); if (!GC_ENABLE_LAZY_SWEEP) return; + gc_sweeping_enter(objspace); + for (int i = 0; i < SIZE_POOL_COUNT; i++) { rb_size_pool_t *size_pool = &size_pools[i]; if (!gc_sweep_step(objspace, size_pool, SIZE_POOL_EDEN_HEAP(size_pool))) { @@ -6076,6 +6084,8 @@ gc_sweep_continue(rb_objspace_t *objspace, rb_size_pool_t *sweep_size_pool, rb_h #endif } } + + gc_sweeping_exit(objspace); } static void @@ -6186,6 +6196,8 @@ static void gc_sweep_compact(rb_objspace_t *objspace); static void gc_sweep(rb_objspace_t *objspace) { + gc_sweeping_enter(objspace); + const unsigned int immediate_sweep = objspace->flags.immediate_sweep; gc_report(1, objspace, "gc_sweep: immediate: %d\n", immediate_sweep); @@ -6217,6 +6229,8 @@ gc_sweep(rb_objspace_t *objspace) rb_size_pool_t *size_pool = &size_pools[0]; gc_heap_prepare_minimum_pages(objspace, size_pool, SIZE_POOL_EDEN_HEAP(size_pool)); #endif + + gc_sweeping_exit(objspace); } /* Marking - Marking stack */ @@ -8709,6 +8723,8 @@ gc_marks_continue(rb_objspace_t *objspace, rb_size_pool_t *size_pool, rb_heap_t GC_ASSERT(dont_gc_val() == FALSE); bool marking_finished = true; + gc_marking_enter(objspace); + #if GC_ENABLE_INCREMENTAL_MARK if (heap->free_pages) { gc_report(2, objspace, "gc_marks_continue: has pooled pages"); @@ -8722,6 +8738,8 @@ gc_marks_continue(rb_objspace_t *objspace, rb_size_pool_t *size_pool, rb_heap_t } #endif + gc_marking_exit(objspace); + return marking_finished; } @@ -8729,6 +8747,8 @@ static bool gc_marks(rb_objspace_t *objspace, int full_mark) { gc_prof_mark_timer_start(objspace); + gc_marking_enter(objspace); + bool marking_finished = false; /* setup marking */ @@ -8745,6 +8765,8 @@ gc_marks(rb_objspace_t *objspace, int full_mark) record->old_objects = objspace->rgengc.old_objects; } #endif + + gc_marking_exit(objspace); gc_prof_mark_timer_stop(objspace); return marking_finished; @@ -9549,12 +9571,19 @@ gc_rest(rb_objspace_t *objspace) if (RGENGC_CHECK_MODE >= 2) gc_verify_internal_consistency(objspace); if (is_incremental_marking(objspace)) { + gc_marking_enter(objspace); gc_marks_rest(objspace); + gc_marking_exit(objspace); + gc_sweep(objspace); } + if (is_lazy_sweeping(objspace)) { + gc_sweeping_enter(objspace); gc_sweep_rest(objspace); + gc_sweeping_exit(objspace); } + gc_exit(objspace, gc_enter_event_rest, &lock_lev); } } @@ -9669,58 +9698,30 @@ gc_enter_count(enum gc_enter_event event) #define MEASURE_GC (objspace->flags.measure_gc) #endif -static bool -gc_enter_event_measure_p(rb_objspace_t *objspace, enum gc_enter_event event) -{ - if (!MEASURE_GC) return false; - - switch (event) { - case gc_enter_event_start: - case gc_enter_event_continue: - case gc_enter_event_rest: - return true; - - 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) +gc_clock_start(struct timespec *ts) { - 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; - } + if (!current_process_time(ts)) { + ts->tv_sec = 0; + ts->tv_nsec = 0; } } -static void -gc_exit_clock(rb_objspace_t *objspace, enum gc_enter_event event) +static uint64_t +gc_clock_end(struct timespec *ts) { - if (gc_enter_event_measure_p(objspace, event)) { - struct timespec end_time; + struct timespec 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 - } - 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; - } - } + if ((ts->tv_sec > 0 || ts->tv_nsec > 0) && + current_process_time(&end_time) && + end_time.tv_sec >= ts->tv_sec) { + return (uint64_t)(end_time.tv_sec - ts->tv_sec) * (1000 * 1000 * 1000) + + (end_time.tv_nsec - ts->tv_nsec); } + + return 0; } static inline void @@ -9728,8 +9729,6 @@ gc_enter(rb_objspace_t *objspace, enum gc_enter_event event, unsigned int *lock_ { RB_VM_LOCK_ENTER_LEV(lock_lev); - gc_enter_clock(objspace, event); - switch (event) { case gc_enter_event_rest: if (!is_marking(objspace)) break; @@ -9765,7 +9764,6 @@ gc_exit(rb_objspace_t *objspace, enum gc_enter_event event, unsigned int *lock_l gc_report(1, objspace, "gc_exit: %s [%s]\n", gc_enter_event_cstr(event), gc_current_status(objspace)); during_gc = FALSE; - gc_exit_clock(objspace, event); RB_VM_LOCK_LEAVE_LEV(lock_lev); #if RGENGC_CHECK_MODE >= 2 @@ -9777,6 +9775,38 @@ gc_exit(rb_objspace_t *objspace, enum gc_enter_event event, unsigned int *lock_l #endif } +static void +gc_marking_enter(rb_objspace_t *objspace) +{ + GC_ASSERT(during_gc != 0); + + gc_clock_start(&objspace->profile.marking_start_time); +} + +static void +gc_marking_exit(rb_objspace_t *objspace) +{ + GC_ASSERT(during_gc != 0); + + objspace->profile.marking_time_ns += gc_clock_end(&objspace->profile.marking_start_time); +} + +static void +gc_sweeping_enter(rb_objspace_t *objspace) +{ + GC_ASSERT(during_gc != 0); + + gc_clock_start(&objspace->profile.sweeping_start_time); +} + +static void +gc_sweeping_exit(rb_objspace_t *objspace) +{ + GC_ASSERT(during_gc != 0); + + objspace->profile.sweeping_time_ns += gc_clock_end(&objspace->profile.sweeping_start_time); +} + static void * gc_with_gvl(void *ptr) { @@ -11152,6 +11182,8 @@ gc_latest_gc_info(rb_execution_context_t *ec, VALUE self, VALUE arg) enum gc_stat_sym { gc_stat_sym_count, gc_stat_sym_time, + gc_stat_sym_marking_time, + gc_stat_sym_sweeping_time, gc_stat_sym_heap_allocated_pages, gc_stat_sym_heap_sorted_length, gc_stat_sym_heap_allocatable_pages, @@ -11201,6 +11233,8 @@ setup_gc_stat_symbols(void) #define S(s) gc_stat_symbols[gc_stat_sym_##s] = ID2SYM(rb_intern_const(#s)) S(count); S(time); + S(marking_time), + S(sweeping_time), S(heap_allocated_pages); S(heap_sorted_length); S(heap_allocatable_pages); @@ -11242,6 +11276,12 @@ setup_gc_stat_symbols(void) } } +static uint64_t +ns_to_ms(uint64_t ns) +{ + return ns / (1000 * 1000); +} + static size_t gc_stat_internal(VALUE hash_or_sym) { @@ -11267,7 +11307,9 @@ gc_stat_internal(VALUE hash_or_sym) rb_hash_aset(hash, gc_stat_symbols[gc_stat_sym_##name], SIZET2NUM(attr)); SET(count, objspace->profile.count); - SET(time, (size_t) (objspace->profile.total_time_ns / (1000 * 1000) /* ns -> ms */)); // TODO: UINT64T2NUM + SET(time, (size_t)ns_to_ms(objspace->profile.marking_time_ns + objspace->profile.sweeping_time_ns)); // TODO: UINT64T2NUM + SET(marking_time, (size_t)ns_to_ms(objspace->profile.marking_time_ns)); + SET(sweeping_time, (size_t)ns_to_ms(objspace->profile.sweeping_time_ns)); /* implementation dependent counters */ SET(heap_allocated_pages, heap_allocated_pages); diff --git a/gc.rb b/gc.rb index 495f203487..dd4fb6c274 100644 --- a/gc.rb +++ b/gc.rb @@ -282,7 +282,7 @@ module GC # Return measured \GC total time in nano seconds. def self.total_time Primitive.cexpr! %{ - ULL2NUM(rb_objspace.profile.total_time_ns) + ULL2NUM(rb_objspace.profile.marking_time_ns + rb_objspace.profile.sweeping_time_ns) } end end diff --git a/test/ruby/test_gc.rb b/test/ruby/test_gc.rb index 0e3a3b4e1c..4f1d32580a 100644 --- a/test/ruby/test_gc.rb +++ b/test/ruby/test_gc.rb @@ -128,6 +128,8 @@ class TestGc < Test::Unit::TestCase omit 'stress' if GC.stress stat = GC.stat + # marking_time + sweeping_time could differ from time by 1 because they're stored in nanoseconds + assert_in_delta stat[:time], stat[:marking_time] + stat[:sweeping_time], 1 assert_equal stat[:total_allocated_pages], stat[:heap_allocated_pages] + stat[:total_freed_pages] assert_operator stat[:heap_sorted_length], :>=, stat[:heap_eden_pages] + stat[:heap_allocatable_pages], "stat is: " + stat.inspect assert_equal stat[:heap_available_slots], stat[:heap_live_slots] + stat[:heap_free_slots] + stat[:heap_final_slots]