From f8bd1a342bed72fdcb33ead9722c589eb7d441aa Mon Sep 17 00:00:00 2001 From: KC Sivaramakrishnan Date: Thu, 25 Jul 2024 18:07:53 +0530 Subject: [PATCH] Fix GC stats. Use wall clock time for per-domain time calculation. --- CHANGES.md | 1 - dune-project | 2 +- lib/olly_gc_stats/olly_gc_stats.ml | 54 ++++++++++++++++++++---------- runtime_events_tools.opam | 2 +- runtime_events_tools_bare.opam | 2 +- 5 files changed, 39 insertions(+), 22 deletions(-) diff --git a/CHANGES.md b/CHANGES.md index 7c4421c..e629d9e 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -1,4 +1,3 @@ - ### 0.5.1 * Fix support on ARM64 platforms (Linux and MacOS) (#34, @tmcgilchrist) diff --git a/dune-project b/dune-project index 6f5d2d6..5bc99a5 100644 --- a/dune-project +++ b/dune-project @@ -1,7 +1,7 @@ (lang dune 3.2) (name runtime_events_tools) -(version "0.5.0") +(version "0.5.1") (generate_opam_files true) (source diff --git a/lib/olly_gc_stats/olly_gc_stats.ml b/lib/olly_gc_stats/olly_gc_stats.ml index 4a74cd2..d86761e 100644 --- a/lib/olly_gc_stats/olly_gc_stats.ml +++ b/lib/olly_gc_stats/olly_gc_stats.ml @@ -2,23 +2,30 @@ module H = Hdr_histogram module Ts = Runtime_events.Timestamp type ts = { mutable start_time : float; mutable end_time : float } - -let total_gc_time = ref 0 let wall_time = { start_time = 0.; end_time = 0. } -let total_cpu_time = ref 0. + +let domain_cpu_times = Array.make 128 (0.) let domain_gc_times = Array.make 128 0 -let lifecycle _domain_id _ts lifecycle_event _data = +let lifecycle domain_id _ts lifecycle_event _data = match lifecycle_event with - | Runtime_events.EV_RING_START -> wall_time.start_time <- Unix.gettimeofday () + | Runtime_events.EV_RING_START -> + let ts = Unix.gettimeofday () in + wall_time.start_time <- ts; + domain_cpu_times.(domain_id) <- ts | Runtime_events.EV_RING_STOP -> - wall_time.end_time <- Unix.gettimeofday (); - let times = Unix.times () in - total_cpu_time := times.tms_utime +. times.tms_cutime + let ts = Unix.gettimeofday () in + wall_time.end_time <- ts; + domain_cpu_times.(domain_id) <- ts -. domain_cpu_times.(domain_id) + | Runtime_events.EV_DOMAIN_SPAWN -> + domain_cpu_times.(domain_id) <- Unix.gettimeofday () + | Runtime_events.EV_DOMAIN_TERMINATE -> + domain_cpu_times.(domain_id) <- + Unix.gettimeofday () -. domain_cpu_times.(domain_id) | _ -> () let print_percentiles json output hist = - let ms ns = ns /. 1000000. in + let ms ns = ns /. 1_000_000. in let mean_latency = H.mean hist |> ms and max_latency = float_of_int (H.max hist) |> ms in let percentiles = @@ -46,7 +53,17 @@ let print_percentiles json output hist = let oc = match output with Some s -> open_out s | None -> stderr in let to_sec x = float_of_int x /. 1000000000. in let real_time = wall_time.end_time -. wall_time.start_time in - let gc_time = to_sec !total_gc_time in + let total_gc_time = to_sec @@ Array.fold_left ( + ) 0 domain_gc_times in + + let total_cpu_time = ref 0. in + let ap = Array.combine domain_cpu_times domain_gc_times in + Array.iteri (fun i (cpu_time, gc_time) -> + if gc_time > 0 && cpu_time = 0. then + Printf.fprintf stderr + "[Olly] Warning: Domain %d has GC time but no CPU time\n" i + else + total_cpu_time := !total_cpu_time +. cpu_time) ap; + if json then let distribs = List.init (Array.length percentiles) (fun i -> @@ -66,15 +83,17 @@ let print_percentiles json output hist = Printf.fprintf oc "Execution times:\n"; Printf.fprintf oc "Wall time (s):\t%.2f\n" real_time; Printf.fprintf oc "CPU time (s):\t%.2f\n" !total_cpu_time; - Printf.fprintf oc "GC time (s):\t%.2f\n" gc_time; + Printf.fprintf oc "GC time (s):\t%.2f\n" total_gc_time; Printf.fprintf oc "GC overhead (%% of CPU time):\t%.2f%%\n" - (gc_time /. !total_cpu_time *. 100.); + (total_gc_time /. !total_cpu_time *. 100.); Printf.fprintf oc "\n"; - Printf.fprintf oc "GC time per domain (s):\n"; - Array.iteri - (fun i x -> - if x > 0 then Printf.fprintf oc "Domain%d: \t%.2f\n" i (to_sec x)) - domain_gc_times; + Printf.fprintf oc "Per domain stats:\n"; + Printf.fprintf oc "Domain\t Wall(s)\t GC(s)\t GC(%%)\n"; + Array.iteri (fun i (c,g) -> + if c > 0. then + Printf.fprintf oc "%d\t %.2f\t %.2f\t %.2f\n" i c (to_sec g) + ((to_sec g) *. 100. /. c)) + (Array.combine domain_cpu_times domain_gc_times); Printf.fprintf oc "\n"; Printf.fprintf oc "GC latency profile:\n"; Printf.fprintf oc "#[Mean (ms):\t%.2f,\t Stddev (ms):\t%.2f]\n" mean_latency @@ -113,7 +132,6 @@ let gc_stats json output exec_args = Hashtbl.remove current_event ring_id; let latency = Int64.to_int (Int64.sub (Ts.to_int64 ts) saved_ts) in assert (H.record_value hist latency); - total_gc_time := !total_gc_time + latency; domain_gc_times.(ring_id) <- domain_gc_times.(ring_id) + latency | _ -> () in diff --git a/runtime_events_tools.opam b/runtime_events_tools.opam index 17f1053..a962ae8 100644 --- a/runtime_events_tools.opam +++ b/runtime_events_tools.opam @@ -1,6 +1,6 @@ # This file is generated by dune, edit dune-project instead opam-version: "2.0" -version: "0.5.0" +version: "0.5.1" synopsis: "Tools for the runtime events tracing system in OCaml" description: "Various tools for the runtime events tracing system in OCaml" maintainer: ["Sadiq Jaffer" "KC Sivaramakrishnan" "Sudha Parimala"] diff --git a/runtime_events_tools_bare.opam b/runtime_events_tools_bare.opam index 50d8ccd..050982c 100644 --- a/runtime_events_tools_bare.opam +++ b/runtime_events_tools_bare.opam @@ -1,6 +1,6 @@ # This file is generated by dune, edit dune-project instead opam-version: "2.0" -version: "0.5.0" +version: "0.5.1" synopsis: "Tools for the runtime events tracing system in OCaml" description: "Various tools for the runtime events tracing system in OCaml: minimal dependencies"