A collection of observability tools around the runtime events tracing system introduced in OCaml 5.0.
To install runtime_events_tools:
opam install runtime_events_tools
The main tool is called olly, it provides a number of sub-commands for gathering runtime events and reporting. Run olly --help to see all available options.
Running olly gc-stats will report the GC running time and GC tail latency profile of an OCaml executable.
| Metric | Description |
|---|---|
| Wall time | Real execution time of the program |
| CPU time | Total CPU time across all domains |
| GC time | Total time spent by the program performing garbage collection (major and minor) |
| GC overhead | Percentage of time taken up by GC against the total execution time |
| GC time per domain | Time spent by every domain performing garbage collection (major and minor cycles). |
| GC latency profile | Mean, standard deviation and percentile latency profile of GC events. |
Note: all times are wall-clock and so include time spent blocking.
$ olly gc-stats 'EXECUTABLE' # Use quotes for commands with arguments
Execution times:
Wall time (s): 114.15
CPU time (s): 1012.84
GC time (s): 173.08
GC overhead (% of CPU time): 17.09%
Per domain stats:
Domain Wall(s) GC(s) GC(%)
0 114.15 11.52 10.10
1 112.19 20.00 17.83
2 112.19 20.64 18.40
3 112.21 20.20 18.01
4 112.19 20.33 18.12
5 112.28 19.91 17.73
6 112.20 20.32 18.11
7 112.87 19.75 17.49
8 112.57 20.41 18.13
GC latency profile:
#[Mean (ms): 4.95, Stddev (ms): 5.58]
#[Min (ms): 0.00, max (ms): 72.55]
Percentile Latency (ms)
25.0000 0.05
50.0000 4.66
60.0000 5.51
70.0000 6.38
75.0000 6.89
80.0000 7.54
85.0000 8.54
90.0000 10.56
95.0000 14.58
96.0000 16.27
97.0000 18.14
98.0000 21.10
99.0000 26.62
99.9000 47.19
99.9900 66.98
99.9990 72.55
99.9999 72.55
100.0000 72.55
GC allocations (in words):
Total heap: 501516808
Minor heap: 602373895
Promoted words: 100857087 (16.74%)
Minor Gen: 904 collections
Major Gen: 34 collections 0 forced collections
Compactions: 0Note: if the GC pauses for longer than the histogram's highest bucket can record, the output will include a line of the form #[Beyond histogram (> 17179869 ms): 5 events, mean (ms): 19000000, max (ms): 20000000] In this case, mean and standard deviation results only apply to the histogram contents and do not include the outlier values. The max result does.
olly trace will record the runtime trace log in
Fuchsia trace format
or
Chrome tracing format
. The trace format can be specified with the --format option, with the default being Fuchsia trace format.
$ olly trace --format=fuchsia menhir_sysver.trace 'menhir -v --table sysver.mly' # Fuchsia trace format
<snip>
$ ls menhir_sysver.trace
menhir_sysver.trace
$ olly trace --format=json menhir_sysver.trace 'menhir -v --table sysver.mly' # Chrome tracing format
<snip>
$ ls menhir_sysver.trace
menhir_sysver.traceTraces in either formats can be viewed in perfetto trace viewer. Chrome format trace can also be viewed in chrome://tracing in chromium-based browsers.
If olly does not read a domain's ring buffer fast enough then some events will be lost, which is reported as [ring_id=6] Lost 1584944 events. If this occurs the results from olly may be inaccurate. There are several ways to fix this:
- Use
--freqoption to make olly read the ring buffer more frequently. - Set
OCAMLRUNPARAM=e=20to increase the size of the ring buffer. - If events are being lost at startup, consider adding a brief sleep to the beginning of your program so olly has time to attach to it.
The library depends on hdr_histogram_ocaml.