Skip to content

Batch up GC metrics and log to JSON #34

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
ltratt merged 1 commit into from
Aug 6, 2025
Merged

Batch up GC metrics and log to JSON #34

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
49 changes: 28 additions & 21 deletions alloc.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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);
}
}
}
Expand Down Expand Up @@ -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",
Expand All @@ -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;
Expand All @@ -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;
Expand All @@ -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)
Expand Down
9 changes: 2 additions & 7 deletions finalize.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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. */
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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)
Expand All @@ -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 */

Expand Down
3 changes: 2 additions & 1 deletion include/gc/gc.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
Expand Down
100 changes: 71 additions & 29 deletions include/private/gc_priv.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 <time.h>
# if defined(FREEBSD) && !defined(CLOCKS_PER_SEC)
Expand Down Expand Up @@ -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 */
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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))

Expand Down Expand Up @@ -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 \
Expand Down
Loading