1
Fork 0
mirror of https://git.savannah.gnu.org/git/guile.git synced 2025-04-30 03:40:34 +02:00

Basic stats also record CPU time

This commit is contained in:
Andy Wingo 2025-03-13 13:43:41 +01:00
parent 3a86fedcde
commit 0cff6ffba4

View file

@ -9,6 +9,7 @@
#include <stdio.h>
#include <string.h>
#include <sys/time.h>
#include <time.h>
GC_DEFINE_HISTOGRAM(gc_latency, 25, 4);
@ -16,8 +17,11 @@ struct gc_basic_stats {
uint64_t major_collection_count;
uint64_t minor_collection_count;
uint64_t last_time_usec;
uint64_t last_cpu_time_usec;
uint64_t elapsed_mutator_usec;
uint64_t elapsed_collector_usec;
uint64_t cpu_mutator_usec;
uint64_t cpu_collector_usec;
size_t heap_size;
size_t max_heap_size;
size_t max_live_data_size;
@ -33,18 +37,31 @@ static inline uint64_t gc_basic_stats_now(void) {
return ret;
}
static inline uint64_t gc_basic_stats_cpu_time(void) {
struct timespec ts;
clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &ts);
uint64_t ret = ts.tv_sec;
ret *= 1000 * 1000;
ret += ts.tv_nsec / 1000;
return ret;
}
static inline void gc_basic_stats_init(void *data, size_t heap_size) {
struct gc_basic_stats *stats = data;
memset(stats, 0, sizeof(*stats));
stats->last_time_usec = gc_basic_stats_now();
stats->last_cpu_time_usec = gc_basic_stats_cpu_time();
stats->heap_size = stats->max_heap_size = heap_size;
}
static inline void gc_basic_stats_requesting_stop(void *data) {
struct gc_basic_stats *stats = data;
uint64_t now = gc_basic_stats_now();
uint64_t cpu_time = gc_basic_stats_cpu_time();
stats->elapsed_mutator_usec += now - stats->last_time_usec;
stats->cpu_mutator_usec += cpu_time - stats->last_cpu_time_usec;
stats->last_time_usec = now;
stats->last_cpu_time_usec = cpu_time;
}
static inline void gc_basic_stats_waiting_for_stop(void *data) {}
static inline void gc_basic_stats_mutators_stopped(void *data) {}
@ -66,10 +83,14 @@ static inline void gc_basic_stats_finalizers_traced(void *data) {}
static inline void gc_basic_stats_restarting_mutators(void *data) {
struct gc_basic_stats *stats = data;
uint64_t now = gc_basic_stats_now();
uint64_t cpu_time = gc_basic_stats_cpu_time();
uint64_t pause_time = now - stats->last_time_usec;
uint64_t pause_cpu_time = cpu_time - stats->last_cpu_time_usec;
stats->elapsed_collector_usec += pause_time;
stats->cpu_collector_usec += pause_cpu_time;
gc_latency_record(&stats->pause_times, pause_time);
stats->last_time_usec = now;
stats->last_cpu_time_usec = cpu_time;
}
static inline void* gc_basic_stats_mutator_added(void *data) {
@ -118,8 +139,11 @@ static inline void gc_basic_stats_live_data_size(void *data, size_t size) {
static inline void gc_basic_stats_finish(struct gc_basic_stats *stats) {
uint64_t now = gc_basic_stats_now();
uint64_t cpu_time = gc_basic_stats_cpu_time();
stats->elapsed_mutator_usec += now - stats->last_time_usec;
stats->cpu_mutator_usec += cpu_time - stats->last_cpu_time_usec;
stats->last_time_usec = now;
stats->last_cpu_time_usec = cpu_time;
}
static inline void gc_basic_stats_print(struct gc_basic_stats *stats, FILE *f) {
@ -127,10 +151,15 @@ static inline void gc_basic_stats_print(struct gc_basic_stats *stats, FILE *f) {
stats->major_collection_count, stats->minor_collection_count);
uint64_t stopped = stats->elapsed_collector_usec;
uint64_t elapsed = stats->elapsed_mutator_usec + stopped;
uint64_t cpu_stopped = stats->cpu_collector_usec;
uint64_t cpu_total = stats->cpu_mutator_usec + cpu_stopped;
uint64_t ms = 1000; // per usec
fprintf(f, "%" PRIu64 ".%.3" PRIu64 " ms total time "
"(%" PRIu64 ".%.3" PRIu64 " stopped); "
"%" PRIu64 ".%.3" PRIu64 " ms CPU time "
"(%" PRIu64 ".%.3" PRIu64 " stopped).\n",
elapsed / ms, elapsed % ms, stopped / ms, stopped % ms);
elapsed / ms, elapsed % ms, stopped / ms, stopped % ms,
cpu_total / ms, cpu_total % ms, cpu_stopped / ms, cpu_stopped % ms);
uint64_t pause_median = gc_latency_median(&stats->pause_times);
uint64_t pause_p95 = gc_latency_percentile(&stats->pause_times, 0.95);
uint64_t pause_max = gc_latency_max(&stats->pause_times);