diff --git a/alloc.c b/alloc.c index 99cafb794..abdcd8ab8 100644 --- a/alloc.c +++ b/alloc.c @@ -506,8 +506,12 @@ STATIC void GC_maybe_gc(void) GC_COND_LOG_PRINTF( "***>Full mark for collection #%lu after %lu allocd bytes\n", (unsigned long)GC_gc_no + 1, (unsigned long)GC_bytes_allocd); - GC_BENCHMARK_LOG_MAYBE_HEADER(); - GC_BENCHMARK_LOG_PRINTF("%lu,major,%lu,",(unsigned long)GC_gc_no + 1,(unsigned long)GC_bytes_allocd); + if (GC_benchmark) { + GC_metrics.collection_number = GC_gc_no + 1; + GC_metrics.kind = 2; + GC_metrics.mem_allocd_entry = GC_bytes_allocd; + GC_metrics.mem_hsize_entry = GC_get_heap_size(); + } GC_promote_black_lists(); (void)GC_reclaim_all((GC_stop_func)0, TRUE); GC_notify_full_gc(); @@ -647,8 +651,8 @@ GC_INNER GC_bool GC_try_to_collect_inner(GC_stop_func stop_func) if (GC_print_stats) GC_log_printf("Complete collection took %lu ms %lu ns\n", time_diff, ns_frac_diff); - if (GC_benchmark) - GC_log_printf("%lu,%lu,",time_diff, ns_frac_diff); + + GC_metrics.time_total = NS_TO_MS(time_diff, ns_frac_diff); } # endif if (GC_on_collection_event) @@ -860,9 +864,12 @@ STATIC GC_bool GC_stopped_mark(GC_stop_func stop_func) GC_COND_LOG_PRINTF( "\n--> Marking for collection #%lu after %lu allocated bytes\n", (unsigned long)GC_gc_no + 1, (unsigned long)GC_bytes_allocd); - GC_BENCHMARK_LOG_MAYBE_HEADER(); - GC_BENCHMARK_LOG_PRINTF("%lu,minor,%lu,",(unsigned long)GC_gc_no + 1,(unsigned long)GC_bytes_allocd); - + if (GC_benchmark) { + GC_metrics.collection_number = GC_gc_no + 1; + GC_metrics.kind = 1; + GC_metrics.mem_allocd_entry = GC_bytes_allocd; + GC_metrics.mem_hsize_entry = GC_get_heap_size(); + } # ifndef NO_CLOCK if (GC_PRINT_STATS_FLAG || measure_performance || GC_benchmark) { GET_TIME(start_time); @@ -987,7 +994,7 @@ STATIC GC_bool GC_stopped_mark(GC_stop_func stop_func) " (%u ms in average)\n", time_diff, ns_frac_diff, total_time / divisor); if (GC_benchmark) - GC_log_printf("%lu,%lu,", time_diff, ns_frac_diff); + GC_metrics.time_marking = NS_TO_MS(time_diff, ns_frac_diff); } } } @@ -1283,7 +1290,6 @@ STATIC void GC_finish_collection(void) GC_ASSERT(GC_heapsize >= GC_unmapped_bytes); # endif GC_ASSERT(GC_our_mem_bytes >= GC_heapsize); - GC_BENCHMARK_LOG_PRINTF("%ld,", (long)GC_bytes_found); GC_DBGLOG_PRINTF("GC #%lu freed %ld bytes, heap %lu KiB (" IF_USE_MUNMAP("+ %lu KiB unmapped ") "+ %lu KiB internal)\n", @@ -1301,6 +1307,9 @@ STATIC void GC_finish_collection(void) > min_bytes_allocd() + GC_large_free_bytes; } + if (GC_on_collection_event) + GC_on_collection_event(GC_EVENT_RECLAIM_END); + /* Reset or increment counters for next cycle. */ GC_n_attempts = 0; GC_is_full_gc = FALSE; @@ -1311,8 +1320,6 @@ STATIC void GC_finish_collection(void) GC_bytes_freed = 0; GC_finalizer_bytes_freed = 0; - if (GC_on_collection_event) - GC_on_collection_event(GC_EVENT_RECLAIM_END); # ifndef NO_CLOCK if (GC_print_stats || GC_benchmark) { CLOCK_TYPE done_time; @@ -1322,20 +1329,20 @@ STATIC void GC_finish_collection(void) /* A convenient place to output finalization statistics. */ GC_print_finalization_stats(); # endif + word flz_ms = MS_TIME_DIFF(finalize_time, start_time); + word flz_ns = NS_FRAC_TIME_DIFF(finalize_time, start_time); + word sweep_ms = MS_TIME_DIFF(done_time, finalize_time); + word sweep_ns = NS_FRAC_TIME_DIFF(done_time, finalize_time); if (GC_print_stats) GC_log_printf("Finalize and initiate sweep took %lu ms %lu ns" " + %lu ms %lu ns\n", - MS_TIME_DIFF(finalize_time, start_time), - NS_FRAC_TIME_DIFF(finalize_time, start_time), - MS_TIME_DIFF(done_time, finalize_time), - NS_FRAC_TIME_DIFF(done_time, finalize_time)); + flz_ms, + flz_ns, + sweep_ms, + sweep_ns); if (GC_benchmark) { - GC_log_printf("%lu,%lu," - "%lu,%lu,", - MS_TIME_DIFF(finalize_time, start_time), - NS_FRAC_TIME_DIFF(finalize_time, start_time), - MS_TIME_DIFF(done_time, finalize_time), - NS_FRAC_TIME_DIFF(done_time, finalize_time)); + GC_metrics.time_fin_q = NS_TO_MS(flz_ms, flz_ns); + GC_metrics.time_sweeping = NS_TO_MS(sweep_ms, sweep_ns); } } # elif !defined(SMALL_CONFIG) && !defined(GC_NO_FINALIZATION) diff --git a/finalize.c b/finalize.c index 00a606dc1..800df8b18 100644 --- a/finalize.c +++ b/finalize.c @@ -741,6 +741,7 @@ STATIC void GC_register_finalizer_inner(void * obj, } if (fn == 0) { GC_fo_entries--; + GC_fin_q--; /* May not happen if we get a signal. But a high */ /* estimate will only make the table larger than */ /* necessary. */ @@ -823,6 +824,7 @@ STATIC void GC_register_finalizer_inner(void * obj, fo_set_next(new_fo, GC_fnlz_roots.fo_head[index]); GC_dirty(new_fo); GC_fo_entries++; + GC_fin_q++; GC_fnlz_roots.fo_head[index] = new_fo; GC_dirty(GC_fnlz_roots.fo_head + index); UNLOCK(); @@ -1461,10 +1463,6 @@ GC_INNER void GC_notify_or_invoke_finalizers(void) (unsigned long)IF_LONG_REFS_PRESENT_ELSE( GC_ll_hashtbl.entries, 0)); - if (GC_benchmark) - GC_log_printf("%lu,", - (unsigned long)GC_fo_entries); - for (fo = GC_fnlz_roots.finalize_now; fo != NULL; fo = fo_next(fo)) ++ready; if (GC_print_stats) @@ -1474,9 +1472,6 @@ GC_INNER void GC_notify_or_invoke_finalizers(void) (long)GC_old_dl_entries - (long)GC_dl_hashtbl.entries, (long)IF_LONG_REFS_PRESENT_ELSE( GC_old_ll_entries - GC_ll_hashtbl.entries, 0)); - if (GC_benchmark) - GC_log_printf("%lu,", - (unsigned long)ready); } #endif /* !SMALL_CONFIG */ diff --git a/include/gc/gc.h b/include/gc/gc.h index 87ce9866c..7249f23af 100644 --- a/include/gc/gc.h +++ b/include/gc/gc.h @@ -428,12 +428,13 @@ GC_API void GC_CALL GC_start_performance_measurement(void); GC_API void GC_CALL GC_enable_benchmark_stats(void); GC_API void GC_CALL GC_log_metrics(GC_word finalizers_run, + GC_word finalizers_elided, GC_word finalizers_registered, GC_word allocated_gc, GC_word allocated_arc, GC_word allocated_rc, GC_word allocated_boxed, - int final); + GC_word explicit_frees); /* Get the total time of all full collections since the start of the */ /* performance measurements. Includes time spent in the supplementary */ diff --git a/include/private/gc_priv.h b/include/private/gc_priv.h index 7cf162361..aa1653d50 100644 --- a/include/private/gc_priv.h +++ b/include/private/gc_priv.h @@ -553,6 +553,9 @@ EXTERN_C_END # define NS_FRAC_TIME_DIFF(a, b) \ ((unsigned long)((a).tv_nsec + (1000000L*1000 - (b).tv_nsec)) % 1000000UL) +# define NS_TO_MS(ms, ns) \ + ((double) ms + ((double) ns / 1000000UL)) + #else /* !BSD_TIME && !LINUX && !NN_PLATFORM_CTR && !MSWIN32 */ # include # if defined(FREEBSD) && !defined(CLOCKS_PER_SEC) @@ -1309,6 +1312,47 @@ struct HeapSect { size_t hs_bytes; }; +#define ABS_SIGNED_WORD(x) ((x) < 0 ? -(x) : (x)) + +#define GC_METRICS_FIELDS \ + X(signed_word, "%ld", collection_number, -1) \ + X(signed_word, "%ld", kind, -1) \ + X(word, "%lu", mem_hsize_entry, 0) \ + X(word, "%lu", mem_hsize_exit, 0) \ + X(word, "%lu", mem_allocd_entry, 0) \ + X(word, "%lu", mem_allocd_exit, 0) \ + X(word, "%lu", mem_allocd_flzq, 0) \ + X(word, "%lu", mem_freed_explicit_entry, 0) \ + X(word, "%lu", mem_freed_explicit_exit, 0) \ + X(word, "%lu", mem_freed_swept, 0) \ + X(word, "%lu", mem_freed_flz, 0) \ + X(double, "%.17g",time_marking, 0) \ + X(double, "%.17g",time_fin_q, 0) \ + X(double, "%.17g",time_sweeping, 0) \ + X(double, "%.17g",time_total, 0) \ + X(word, "%lu", flz_registered, 0) \ + X(word, "%lu", flz_elided, 0) \ + X(word, "%lu", flz_run, 0) \ + X(word, "%lu", obj_allocd_arc, 0) \ + X(word, "%lu", obj_allocd_box, 0) \ + X(word, "%lu", obj_allocd_flzq, 0) \ + X(word, "%lu", obj_allocd_gc, 0) \ + X(word, "%lu", obj_allocd_rc, 0) \ + X(word, "%lu", obj_freed_swept, 0) \ + X(word, "%lu", obj_freed_explicit, 0) + +typedef struct { +#define X(type, fmt, name, init) type name; + GC_METRICS_FIELDS +#undef X +} _GC_metrics; + +GC_INLINE void reset_metrics(_GC_metrics *metrics) { +#define X(type, fmt, name, init) metrics->name = init; + GC_METRICS_FIELDS +#undef X +} + /* Lists of all heap blocks and free lists as well as other random data */ /* structures that should not be scanned by the collector. These are */ /* grouped together in a struct so that they can be easily skipped by */ @@ -1379,6 +1423,8 @@ struct _GC_arrays { /* allocator lock is held. */ bottom_index *_all_bottom_indices_end; + _GC_metrics _metrics; + ptr_t _scratch_free_ptr; hdr *_hdr_free_list; # define GC_scratch_end_addr GC_arrays._scratch_end_addr @@ -1514,6 +1560,8 @@ struct _GC_arrays { # endif # define GC_fo_entries GC_arrays._fo_entries size_t _fo_entries; +# define GC_fin_q GC_arrays._fin_q + size_t _fin_q; # ifndef GC_NO_FINALIZATION # define GC_dl_hashtbl GC_arrays._dl_hashtbl # define GC_fnlz_roots GC_arrays._fnlz_roots @@ -1675,10 +1723,10 @@ GC_API_PRIV GC_FAR struct _GC_arrays GC_arrays; #define GC_bytes_dropped GC_arrays._bytes_dropped #define GC_bytes_finalized GC_arrays._bytes_finalized #define GC_bytes_freed GC_arrays._bytes_freed +#define GC_bytes_swept GC_arrays._bytes_swept #define GC_composite_in_use GC_arrays._composite_in_use #define GC_excl_table GC_arrays._excl_table #define GC_finalizer_bytes_freed GC_arrays._finalizer_bytes_freed -#define GC_finalizers_run GC_arrays._finalizers_run #define GC_total_objects_reclaimed GC_arrays._total_objects_reclaimed #define GC_heapsize GC_arrays._heapsize #define GC_large_allocd_bytes GC_arrays._large_allocd_bytes @@ -1701,6 +1749,8 @@ GC_API_PRIV GC_FAR struct _GC_arrays GC_arrays; #define GC_uobjfreelist GC_arrays._uobjfreelist #define GC_valid_offsets GC_arrays._valid_offsets +#define GC_metrics GC_arrays._metrics + #define beginGC_arrays ((ptr_t)(&GC_arrays)) #define endGC_arrays (beginGC_arrays + sizeof(GC_arrays)) @@ -2753,37 +2803,29 @@ GC_API_PRIV void GC_log_printf(const char * format, ...) # define GC_ERRINFO_PRINTF GC_log_printf #endif -#define GC_BENCHMARK_LOG_MAYBE_HEADER() \ + +GC_INLINE void GC_write_metrics() { + GC_log_printf("{"); + + int first = 1; + +#define X(type, fmt, name, init) \ + if (!first) GC_log_printf(","); \ + GC_log_printf("\"" #name "\":" fmt, GC_metrics.name); \ + first = 0; + + GC_METRICS_FIELDS + +#undef X + GC_log_printf("}\n"); +} + +#define GC_LOG_METRICS() \ do { \ - if (GC_benchmark && GC_get_gc_no() == 0) { \ - GC_BENCHMARK_LOG_PRINTF( \ - "collection_number," \ - "kind," \ - "heap_size_on_entry," \ - "time_marking_ms," \ - "time_marking_ns," \ - "bytes_freed," \ - "live_objects_with_finalizers," \ - "objects_in_finalizer_queue," \ - "time_fin_q_ms," \ - "time_fin_q_ns," \ - "time_sweeping_ms," \ - "time_sweeping_ns," \ - "time_total_ms," \ - "time_total_ns," \ - "finalizers_run," \ - "finalizers_registered," \ - "allocated_gc," \ - "allocated_arc," \ - "allocated_rc," \ - "allocated_boxed\n" \ - ); \ - } \ + if (GC_benchmark) GC_write_metrics(); \ } while (0) -/* Convenient macros for GC_[verbose_]log_printf invocation. */ -#define GC_BENCHMARK_LOG_PRINTF \ - if (EXPECT(!GC_benchmark, TRUE)) {} else GC_log_printf + #define GC_COND_LOG_PRINTF \ if (EXPECT(!GC_print_stats, TRUE)) {} else GC_log_printf #define GC_VERBOSE_LOG_PRINTF \ diff --git a/misc.c b/misc.c index 8ec8428a7..b331e4fca 100644 --- a/misc.c +++ b/misc.c @@ -16,6 +16,7 @@ #include "include/gc/gc.h" #include "private/gc_pmark.h" +#include "private/gc_priv.h" #include #include @@ -1522,6 +1523,9 @@ GC_API void GC_CALL GC_init(void) # if defined(GWW_VDB) && !defined(KEEP_BACK_PTRS) GC_ASSERT(GC_bytes_allocd + GC_bytes_allocd_before_gc == 0); # endif + + GC_fin_q = 0; + reset_metrics(&GC_metrics); } GC_API void GC_CALL GC_enable_incremental(void) @@ -2810,41 +2814,36 @@ GC_API size_t GC_CALL GC_get_hblk_size(void) } GC_API void GC_CALL GC_log_metrics(GC_word finalizers_run, + GC_word finalizers_elided, GC_word finalizers_registered, GC_word allocated_gc, GC_word allocated_arc, GC_word allocated_rc, GC_word allocated_boxed, - int final) -{ - if (final == 1) { - GC_BENCHMARK_LOG_MAYBE_HEADER(); - GC_BENCHMARK_LOG_PRINTF("-1," // Sentinel collection number - "final," // Kind - "%lu," - "0," // Time marking ms (n/a) - "0," // Time marking ns (n/a) - "0," // Bytes freed (n/a) - "%lu,%lu," - "0," // Time in fin q ms (n/a) - "0," // Time in fin q ns (n/a) - "0," // Time sweeping ms (n/a) - "0," // Time sweeping ns (n/a) - "%lu,%u,", - (unsigned long) GC_bytes_allocd, - (unsigned long) GC_fo_entries, - GC_get_total_finalization_ready_objects(), - GC_get_full_gc_total_time(), - GC_get_full_gc_total_ns_frac()); - - + GC_word explicit_frees) +{ + GC_metrics.flz_registered = finalizers_registered; + GC_metrics.flz_elided = finalizers_elided; + GC_metrics.flz_run = finalizers_run; + GC_metrics.obj_allocd_gc = allocated_gc; + GC_metrics.obj_allocd_arc = allocated_arc; + GC_metrics.obj_allocd_rc = allocated_rc; + GC_metrics.obj_allocd_box = allocated_boxed; + GC_metrics.obj_freed_explicit = explicit_frees; + GC_metrics.obj_allocd_flzq = GC_fin_q; + if (GC_bytes_found < 0) { + /* This GC grew the heap */ + GC_metrics.mem_allocd_exit = ABS_SIGNED_WORD(GC_bytes_found); + GC_metrics.mem_freed_swept = 0; + } else { + GC_metrics.mem_freed_swept = GC_bytes_found; + GC_metrics.mem_allocd_exit = 0; } - GC_BENCHMARK_LOG_PRINTF("%lu,%lu,%lu,%lu,%lu,%lu\n", - (unsigned long) finalizers_run, - (unsigned long) finalizers_registered, - (unsigned long) allocated_gc, - (unsigned long) allocated_arc, - (unsigned long) allocated_rc, - (unsigned long) allocated_boxed); + GC_metrics.mem_freed_flz = GC_finalizer_bytes_freed; + GC_metrics.mem_allocd_flzq = GC_bytes_finalized; + GC_metrics.mem_hsize_entry = GC_get_total_bytes(); + GC_metrics.mem_hsize_exit = GC_metrics.mem_hsize_entry - GC_bytes_found; + GC_LOG_METRICS(); + reset_metrics(&GC_metrics); }