gazagnaire.org
Trace Event Format summary CLI
ocaml-catapult: summarize user probe counters
author
Thomas Gazagnaire
date
(Jun 12, 2026, 7:13 PM UTC)
commit
46c75e09
46c75e0920241e03535f1b36295e505ce67eb6b2
parent
88f0e702
88f0e702c4b3cbcb23bb2719811ee2f98e731f59
+196
-26
+42
-25
bin/main.ml
+42
-25
bin/main.ml
···
262
262
Hashtbl.replace acc name
263
263
(n + 1, Float.min mn value, Float.max mx value, sum +. value)
264
264
265
-
let collect_counters (events : Catapult.Event.t list) =
265
+
let is_runtime_counter name =
266
+
String.starts_with ~prefix:"gc busy us" name
267
+
|| String.starts_with ~prefix:"ocaml_probe.energy" name
268
+
269
+
let collect_counters ~runtime (events : Catapult.Event.t list) =
266
270
let acc : (string, int * float * float * float) Hashtbl.t =
267
271
Hashtbl.create 16
268
272
in
···
274
278
(fun (key, v) ->
275
279
match number_arg v with
276
280
| None -> ()
277
-
| Some value -> add_counter acc (counter_name e.name key) value)
281
+
| Some value ->
282
+
let name = counter_name e.name key in
283
+
if runtime || not (is_runtime_counter name) then
284
+
add_counter acc name value)
278
285
e.args
279
286
| _ -> ())
280
287
events;
···
292
299
Fmt.str "%g" mx;
293
300
])
294
301
295
-
let print_counters events =
296
-
let acc = collect_counters events in
302
+
let print_counters ~runtime events =
303
+
let acc = collect_counters ~runtime events in
297
304
if Hashtbl.length acc > 0 then begin
298
305
let columns =
299
306
Tty.Table.
···
320
327
match e.ph with
321
328
| Catapult.Phase.Instant ->
322
329
let name = Option.value ~default:"" e.name in
323
-
Hashtbl.replace counts name
324
-
(1 + Option.value ~default:0 (Hashtbl.find_opt counts name));
325
-
List.iter
326
-
(fun (key, v) ->
327
-
match number_arg v with
328
-
| None -> ()
329
-
| Some value ->
330
-
let hdr, sum =
331
-
match Hashtbl.find_opt values (name, key) with
332
-
| Some hs -> hs
333
-
| None ->
334
-
let hs = (Hdr.v (), ref 0.) in
335
-
Hashtbl.add values (name, key) hs;
336
-
hs
337
-
in
338
-
Hdr.record hdr (max 1 (int_of_float value));
339
-
sum := !sum +. value)
340
-
e.args
330
+
if name <> "ocaml_probe.metadata" then begin
331
+
Hashtbl.replace counts name
332
+
(1 + Option.value ~default:0 (Hashtbl.find_opt counts name));
333
+
List.iter
334
+
(fun (key, v) ->
335
+
match number_arg v with
336
+
| None -> ()
337
+
| Some value ->
338
+
let hdr, sum =
339
+
match Hashtbl.find_opt values (name, key) with
340
+
| Some hs -> hs
341
+
| None ->
342
+
let hs = (Hdr.v (), ref 0.) in
343
+
Hashtbl.add values (name, key) hs;
344
+
hs
345
+
in
346
+
Hdr.record hdr (max 1 (int_of_float value));
347
+
sum := !sum +. value)
348
+
e.args
349
+
end
341
350
| _ -> ())
342
351
events;
343
352
(counts, values)
···
427
436
if !decode_errors > 0 then
428
437
Fmt.pr "@.Warning: %d packets failed to decode.@." !decode_errors
429
438
430
-
let summarize file top by =
439
+
let summarize file top by runtime =
431
440
Fmt_tty.setup_std_outputs ();
432
441
let content = In_channel.with_open_bin file In_channel.input_all in
433
442
match Catapult.of_string ~file content with
···
455
464
| Some key -> print_by ~top key slices
456
465
| None ->
457
466
print_spans slices;
458
-
print_counters events;
467
+
print_counters ~runtime events;
459
468
print_instants ~top events);
460
469
0
461
470
···
474
483
in
475
484
Arg.(value & opt (some string) None & info [ "by" ] ~doc ~docv:"KEY")
476
485
477
-
let summary_term = Term.(const summarize $ file_arg $ top_arg $ by_arg)
486
+
let runtime_arg =
487
+
let doc =
488
+
"Include probe runtime counters such as GC-busy and process energy. By \
489
+
default summary shows user-declared counters only."
490
+
in
491
+
Arg.(value & flag & info [ "runtime" ] ~doc)
492
+
493
+
let summary_term =
494
+
Term.(const summarize $ file_arg $ top_arg $ by_arg $ runtime_arg)
478
495
479
496
let summary_cmd =
480
497
let doc = "Summarize a trace: span tree with latency quantiles" in
+2
-1
test/cram/dune
+2
-1
test/cram/dune
+16
test/cram/helpers.sh
+16
test/cram/helpers.sh
···
1
+
#!/bin/sh
2
+
export PATH="$PWD/../helpers:$PATH"
3
+
4
+
normalize_summary() {
5
+
sed -E \
6
+
-e 's/[0-9]+ events, [0-9]+ slices, [0-9]+\.[0-9]+ms of trace/EVENTS events, SLICES slices, TIMEms of trace/g' \
7
+
-e 's/total=[0-9]+\.[0-9]+ms/total=TIMEms/g' \
8
+
-e 's/p50=[0-9]+\.[0-9]+ms/p50=TIMEms/g' \
9
+
-e 's/p99=[0-9]+\.[0-9]+ms/p99=TIMEms/g' \
10
+
-e 's/max=[0-9]+\.[0-9]+ms/max=TIMEms/g' \
11
+
-e 's/(fixture.large_alloc.*alloc=)[0-9.]+[kKMGT]?B/\1LARGE/g' \
12
+
-e 's/(fixture.noalloc.*alloc=)[0-9.]+[kKMGT]?B/\1LOW/g' \
13
+
-e 's/alloc=[0-9.]+[kKMGT]?B/alloc=BYTES/g' \
14
+
-e 's/(gc busy us \\(domain [0-9]+\\) busy[[:space:]]+1)[[:space:]]+[^[:space:]]+[[:space:]]+[^[:space:]]+[[:space:]]+[^[:space:]]+/\1 TIME TIME TIME/g' \
15
+
-e 's/(ocaml_probe.energy energy_nj[[:space:]]+1)[[:space:]]+[^[:space:]]+[[:space:]]+[^[:space:]]+[[:space:]]+[^[:space:]]+/\1 TIME TIME TIME/g'
16
+
}
+3
test/cram/helpers/dune
+3
test/cram/helpers/dune
+92
test/cram/helpers/probe_workload.ml
+92
test/cram/helpers/probe_workload.ml
···
1
+
open Cmdliner
2
+
3
+
let workload_span =
4
+
Probe.span "fixture.workload" ~doc:"Whole controlled probe workload"
5
+
Probe.Fields.unit
6
+
7
+
let request_span =
8
+
Probe.span "fixture.request" ~doc:"One synthetic request"
9
+
Probe.Fields.(
10
+
obj (fun method_ path -> (method_, path))
11
+
|> field "method" string ~enc:fst
12
+
|> field "path" string ~enc:snd
13
+
|> seal)
14
+
15
+
let step_span =
16
+
Probe.span "fixture.step" ~doc:"One synthetic request step"
17
+
Probe.Fields.(
18
+
obj (fun phase -> phase)
19
+
|> field "phase" string ~enc:(fun phase -> phase)
20
+
|> seal)
21
+
22
+
let noalloc_span =
23
+
Probe.span "fixture.noalloc"
24
+
~doc:"Synthetic path with no intentional allocation" Probe.Fields.unit
25
+
26
+
let large_alloc_span =
27
+
Probe.span "fixture.large_alloc" ~doc:"Synthetic path with visible allocation"
28
+
Probe.Fields.unit
29
+
30
+
let io_event =
31
+
Probe.event "fixture.io" ~doc:"Synthetic I/O operation"
32
+
Probe.Fields.(
33
+
obj (fun direction bytes -> (direction, bytes))
34
+
|> field "direction" string ~enc:fst
35
+
|> field "bytes" int ~enc:snd |> seal)
36
+
37
+
let result_event =
38
+
Probe.event "fixture.result" ~doc:"Synthetic request result"
39
+
Probe.Fields.(
40
+
obj (fun status body_bytes -> (status, body_bytes))
41
+
|> field "status" int ~enc:fst
42
+
|> field "body_bytes" int ~enc:snd
43
+
|> seal)
44
+
45
+
let queue_counter =
46
+
Probe.counter "fixture.queue_depth" ~doc:"Synthetic queue depth"
47
+
Probe.Fields.(
48
+
obj (fun depth -> depth)
49
+
|> field "depth" int ~enc:(fun depth -> depth)
50
+
|> seal)
51
+
52
+
let alloc_some_words n =
53
+
let data = Array.init n (fun i -> string_of_int (i land 15)) in
54
+
ignore (Sys.opaque_identity data)
55
+
56
+
let noalloc_path () =
57
+
let acc = ref 0 in
58
+
Probe.run noalloc_span () @@ fun () ->
59
+
for i = 1 to 100_000 do
60
+
acc := !acc + i
61
+
done;
62
+
ignore !acc
63
+
64
+
let large_alloc_path () =
65
+
Probe.run large_alloc_span () @@ fun () -> alloc_some_words 20_000
66
+
67
+
let step phase words =
68
+
Probe.run step_span phase @@ fun () ->
69
+
alloc_some_words words;
70
+
Unix.sleepf 0.001
71
+
72
+
let run _config =
73
+
Probe.run workload_span () @@ fun () ->
74
+
Probe.record queue_counter 0;
75
+
Probe.emit io_event ("tx", 1200);
76
+
Probe.run request_span ("GET", "/fixture") @@ fun () ->
77
+
Probe.emit io_event ("rx", 900);
78
+
step "recv" 64;
79
+
step "decode" 128;
80
+
noalloc_path ();
81
+
large_alloc_path ();
82
+
Probe.record queue_counter 1;
83
+
Probe.emit result_event (200, 42);
84
+
print_endline "fixture workload complete"
85
+
86
+
let cmd =
87
+
let doc = "Emit a deterministic probe workload for catapult tests" in
88
+
Cmd.v
89
+
(Cmd.info "probe-workload" ~doc)
90
+
Term.(const run $ Observe.setup "catapult-fixture")
91
+
92
+
let () = exit (Cmd.eval cmd)
+41
test/cram/probe-summary.t/run.t
+41
test/cram/probe-summary.t/run.t
···
1
+
Catapult summary of a controlled probe workload
2
+
===============================================
3
+
4
+
The fixture emits nested spans, point events and a counter through
5
+
ocaml-probe. The Catapult summary is the debug surface: it should show the
6
+
operation tree and aggregate event values without inspecting the raw JSON.
7
+
8
+
$ probe_workload.exe --probe probe.json
9
+
fixture workload complete
10
+
11
+
$ catapult summary probe.json | normalize_summary
12
+
EVENTS events, SLICES slices, TIMEms of trace
13
+
14
+
Spans
15
+
16
+
fixture.workload n=1 total=TIMEms p50=TIMEms p99=TIMEms max=TIMEms alloc=BYTES
17
+
└── fixture.request n=1 total=TIMEms p50=TIMEms p99=TIMEms max=TIMEms alloc=BYTES
18
+
├── fixture.large_alloc n=1 total=TIMEms p50=TIMEms p99=TIMEms max=TIMEms alloc=LARGE
19
+
├── fixture.noalloc n=1 total=TIMEms p50=TIMEms p99=TIMEms max=TIMEms
20
+
└── fixture.step n=2 total=TIMEms p50=TIMEms p99=TIMEms max=TIMEms alloc=BYTES
21
+
22
+
Counters
23
+
24
+
Counter Points Min Mean Max
25
+
fixture.queue_depth depth 2 0 0.5 1
26
+
27
+
28
+
Events
29
+
30
+
Event Count
31
+
fixture.io 2
32
+
fixture.result 1
33
+
34
+
35
+
Event values
36
+
37
+
Event value n Sum Mean p50 p99 Max
38
+
fixture.io bytes 2 2100 1050.0 900 1200 1200
39
+
fixture.result status 1 200 200.0 200 200 200
40
+
fixture.result body_bytes 1 42 42.0 42 42 42
41
+