[Guile-commits] 396/423: Basic stats also record CPU time

[Andy Wingo]

wingo pushed a commit to branch wip-whippet
in repository guile.

commit 0cff6ffba484e7dd43acc0c5b5c0d1759b58275c
Author: Andy Wingo <wi...@igalia.com>
AuthorDate: Thu Mar 13 13:43:41 2025 +0100

    Basic stats also record CPU time
---
 api/gc-basic-stats.h | 31 ++++++++++++++++++++++++++++++-
 1 file changed, 30 insertions(+), 1 deletion(-)

diff --git a/api/gc-basic-stats.h b/api/gc-basic-stats.h
index 6b39a59c6..055340817 100644
--- a/api/gc-basic-stats.h
+++ b/api/gc-basic-stats.h
@@ -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);