Merge pull request #39 from talex5/gc-stats

Add gc-stats

Author: talex5

README.md

@@ -86,6 +86,27 @@ eio-trace render trace.fxt
 
 You can also use `--format=png` for PNG output.
 
+To calculate time spent in GC:
+
+```
+eio-trace gc-stats trace.fxt
+
+./trace.fxt:                       
+
+Ring   GC/s     App/s    Total/s   %GC
+  0    0.273    2.258    2.530    10.78
+  1    0.304    0.855    1.159    26.22
+  2    0.301    0.859    1.160    25.98
+  3    0.302    0.859    1.161    26.02
+  4    0.301    0.858    1.159    25.96
+  5    0.300    0.866    1.165    25.72
+  6    0.297    0.873    1.170    25.36
+
+All    2.077    7.427    9.504    21.86
+
+Note: all times are wall-clock and so include time spent blocking.
+```
+
 ## Reading traces
 
 Eio fibers are shown as horizontal bars.

src/gc_stats.ml

@@ -0,0 +1,99 @@
+open Eio.Std
+
+module Read = Fxt.Read
+module Rings = Map.Make(Int)
+
+let ( ++ ) = Int64.add
+let ( -- ) = Int64.sub
+
+type ring_stats = {
+  mutable last_event : int64;
+  mutable gc_depth : int;
+  mutable app_time : int64;
+  mutable gc_time : int64;
+}
+
+type stats = {
+  mutable rings : ring_stats Rings.t;
+}
+
+let pp_header f =
+  Fmt.pf f "Ring   GC/s     App/s    Total/s   %%GC@,"
+
+let pp_times f ~gc ~app =
+  let gc = Int64.to_float gc /. 1e9 in
+  let app = Int64.to_float app /. 1e9 in
+  Fmt.pf f "%8.3f %8.3f %8.3f %8.2f" gc app (gc +. app)
+    (100. *. (gc /. (gc +. app)))
+
+let pp_ring f (id, stats) =
+  Fmt.pf f "%3d " id; pp_times f ~gc:stats.gc_time ~app:stats.app_time
+
+let pp_stats f { rings } =
+  pp_header f;
+  Fmt.(list ~sep:cut) pp_ring f (Rings.bindings rings);
+  let gc_time = Rings.fold (fun _ ring acc -> acc ++ ring.gc_time) rings 0L in
+  let app_time = Rings.fold (fun _ ring acc -> acc ++ ring.app_time) rings 0L in
+  Fmt.pf f "@,@,All "; pp_times f ~gc:gc_time ~app:app_time
+
+let i64 = Int64.to_int
+
+let get_ring ~timestamp t ring =
+  match Rings.find_opt ring t.rings with
+  | Some x -> x
+  | None ->
+    let x = { last_event = timestamp; gc_time = 0L; app_time = 0L; gc_depth = 0 } in
+    t.rings <- Rings.add ring x t.rings;
+    x
+
+let ring_of_thread ~timestamp t (thread : Read.thread) =
+  let id = i64 thread.tid in
+  if id land 3 = 1 then (
+    let ring = id lsr 2 in
+    Some (get_ring t ring ~timestamp)
+  ) else None
+
+let process_event stats e =
+  let { Read.Event.ty; timestamp; thread; category; name = _; args = _ } = e in
+  match ring_of_thread stats thread ~timestamp with
+  | None -> ()
+  | Some ring ->
+    let used = timestamp -- ring.last_event in
+    if ring.gc_depth = 0 then
+      ring.app_time <- ring.app_time ++ used
+    else
+      ring.gc_time <- ring.gc_time ++ used;
+    ring.last_event <- timestamp;
+    match category, ty with
+    | "gc", Duration_begin -> ring.gc_depth <- ring.gc_depth + 1
+    | "gc", Duration_end ->
+      (* todo: we could notice if the event is a top-level one and
+         reset the depth to 0 in that case, to cope with missed events. *)
+      if ring.gc_depth > 0 then
+        ring.gc_depth <- ring.gc_depth - 1
+      else
+        traceln "Warning: unexpected GC end event."
+    | _ -> ()
+
+let analyse reader =
+  let stats = { rings = Rings.empty } in
+  Read.records reader |> Seq.iter (fun (r : Read.record) ->
+      match r with
+      | Event e -> process_event stats e
+      | User _ -> ()
+      | Scheduling _ -> ()
+      | Metadata -> ()
+      | Kernel _ -> ()
+      | Unknown _ -> ()
+    );
+  stats
+
+let main out tracefiles =
+  tracefiles |> List.iter (fun tracefile ->
+      Eio.Path.with_open_in tracefile @@
+      Eio.Buf_read.parse_exn ~max_size:max_int @@ fun r ->
+      let stats = analyse r in
+      Fmt.pf out "@[<v>%s:@,@,%a@]@." (Eio.Path.native_exn tracefile) pp_stats stats;
+      Fmt.pf out "@.Note: all times are wall-clock and so include time spent blocking.@.";
+    );
+  Ok ()

src/gc_stats.mli

@@ -0,0 +1,4 @@
+val main :
+  Format.formatter ->
+  _ Eio.Path.t list ->
+  (unit, 'a) result

src/main.ml

@@ -109,6 +109,7 @@ let cmd env =
     "run",    run ~fs ~proc_mgr              $$ freq $ child_args;
     "show",   show                           $$ tracefiles;
     "render", render                         $$ tracefiles $ imagefile $ fmt $ start_time $ duration;
+    "gc-stats", Gc_stats.main Format.std_formatter $$ (List.map path $$ tracefiles);
   ]
 
 let () =

src/record.ml

@@ -63,6 +63,16 @@ let callbacks t =
             ~category:"gc"
             ~ts:(Runtime_events.Timestamp.to_int64 ts)
       )
+    ~lifecycle:(fun ring_id ts event _data ->
+        let ts = Runtime_events.Timestamp.to_int64 ts in
+        let thread = ring_thread t ring_id in
+        match event with
+        | EV_DOMAIN_SPAWN ->
+          Write.instant_event t.fxt ~thread ~ts ~name:"domain-spawn" ~category:"ocaml"
+        | EV_DOMAIN_TERMINATE ->
+          Write.instant_event t.fxt ~thread ~ts ~name:"domain-terminate" ~category:"ocaml"
+        | _ -> ()
+      )
     ~lost_events:(fun ring n -> traceln "Warning: ring %d lost %d events" ring n)
   |> Eio_runtime_events.add_callbacks
     (fun ring_id ts e ->