\chapter{Runtime tracing with runtime events}
\label{c:runtime-tracing}
%HEVEA\cutname{runtime-tracing.html}

This chapter describes the runtime events tracing system which enables
continuous extraction of performance information from the OCaml runtime with
very low overhead. The system and interfaces are low-level and tightly coupled
to the runtime implementation, it is intended for end-users to rely on tooling
to consume and visualise data of interest.

Data emitted includes:
\begin{itemize}
\item Event times of garbage collector and runtime phases
\item Minor and major heap sizings and utilization
\item Allocation and promotion rates between heaps
\end{itemize}

Additional events can be declared and consumed, providing higher-level
monitoring capabilities to OCaml libraries. They are referred to as {\em
custom events}.

\section{s:runtime-tracing-overview}{Overview}

There are three main classes of events emitted by the runtime events system:

\begin{description}
\item[Spans] Events spanning over a duration in time. For example, the runtime
events tracing system emits a span event that starts when a minor
collection begins in the OCaml garbage collector and ends when
the collection is completed. Spans can contain other spans, e.g other span
events may be emitted that begin after a minor collection has
begun and end before it does.
\item[Lifecycle events] Events that occur at a moment in time. For example,
when a domain terminates, a corresponding lifecycle event is emitted.
\item[Counters] Events that include a measurement of some quantity of
interest. For example, the number of words promoted from the minor to
the major heap during the last minor garbage collection is emitted as a
counter event.
\end{description}

The runtime events tracing system is designed to be used in different contexts:
\begin{description}
\item[Self monitoring] OCaml programs and libraries can install their own callbacks
to listen for runtime events and react to them programmatically, for example,
to export events to disk or over the network.
\item[External monitoring] An external process can consume the runtime events
of an OCaml program whose runtime tracing system has been enabled by setting
the corresponding environment variable.
\end{description}

The runtime events tracing system logs events to a {\em ring buffer}. Consequently,
old events are being overwritten by new events. Consumers can either continuously
consume events or choose to only do so in response to some circumstance, e.g if
a particular query or operation takes longer than expected to complete.

\section{s:runtime-tracing-architecture}{Architecture}

The runtime tracing system conceptually consists of two parts: 1) the event
sources which emit events and 2) the events transport that ingests and
transports these events.

\subsection{s:runtime-tracing-event-sources}{Event sources}
Event sources are event-emitting points. There are a number of such sources in
the OCaml runtime system. These are further split into two sets: 1) event
sources that are always available and 2) event sources that are only available
in the instrumented runtime. Event sources in the instrumented runtime are
primarily of interest to developers of the OCaml runtime and garbage collector
and, at present, only consist of major heap allocation size counter events.

The full set of events emitted by event sources and their documentation can be
found in
\ifouthtml
 \moduleref{libref}{Runtime_events}{Module \texttt{Runtime_events}}.
\else
 section~\ref{Runtime_events}.
\fi

\subsection{s:runtime-tracing-ingestion}{Events transport}

The events transport part of the system ingests events emitted by the event
sources and makes them available to consumers.

\subsubsection{s:runtime-tracing-ringbuffers}{Ring buffers}

Events are transported using a data structure known as a {\em ring buffer}. This
data structure consists of two pointers into a linear backing array, the tail
pointer points to a location where new events can be written and the head
pointer points to the oldest event in the buffer that can be read. When
insufficient space is available in the backing array to write new events, the
head pointer is advanced and the oldest events are overwritten by new ones.

The ring buffer implementation used in runtime events can be written by at most
one producer at a time but can be read simultaneously by multiple consumers
without coordination from the producer. There is a unique ring buffer for every
running domain and, on domain termination, ring buffers may be re-used for newly
spawned domains. Ring buffers are only allocated (including for the main
domain) when runtime events are enabled. The ring buffers themselves are stored
in a memory-mapped file with the processes identifier as the name and the
extension ".events", this enables them to be read from outside the main OCaml
process. See \moduleref{libref}{Runtime_events}{\texttt{Runtime_events}} for
more information.

\subsubsection{s:runtime-tracing-apis}{Consumption APIs}

The runtime event tracing system provides both OCaml and C APIs which are
cursor-based and polling-driven. The high-level process for consuming events
is as follows:

\begin{enumerate}
  \item A cursor is created via \texttt{Runtime_events.create_cursor} for either the
  current process or an external process (specified by a path and PID).
  \item \texttt{Runtime_events.Callbacks.create} is called to register a callback function to receive the events.
  \item The cursor is polled via \texttt{Runtime_events.read_poll} using the callbacks
  created in the previous step. For each matching event in the ring buffers, the
  provided callback functions are called. In addition to the emitted events,
  callbacks are given the emitter domain's ID and the emission timestamp.
\end{enumerate}

\section{s:runtime-tracing-usage}{Usage}

\subsection{s:runtime-tracing-ocaml-apis}{With OCaml APIs}

We start with a simple example that prints the name, begin and end times
of events emitted by the runtime event tracing system:

\begin{verbatim}
let runtime_begin _ ts phase =
    Printf.printf "Begin\t%s\t%Ld\n"
        (Runtime_events.runtime_phase_name phase)
        (Runtime_events.Timestamp.to_int64 ts)

let runtime_end _ ts phase =
    Printf.printf "End\t%s\t%Ld\n"
        (Runtime_events.runtime_phase_name phase)
        (Runtime_events.Timestamp.to_int64 ts)

let () =
    Runtime_events.start ();
    let cursor = Runtime_events.create_cursor None in
    let callbacks = Runtime_events.Callbacks.create ~runtime_begin ~runtime_end ()
    in
    while true do
        let list_ref = ref [] in (* for later fake GC work *)
        for _ = 1 to 100 do
            (* here we do some fake GC work *)
            list_ref := [];
            for _ = 1 to 10 do
                list_ref := (Sys.opaque_identity(ref 42)) :: !list_ref
            done;
            Gc.full_major ();
        done;
        ignore(Runtime_events.read_poll cursor callbacks None);
        Unix.sleep 1
    done
\end{verbatim}

The next step is to compile and link the program with the runtime_events
library. This can be done as follows:

\begin{verbatim}
       ocamlopt -I +runtime_events -I +unix unix.cmxa runtime_events.cmxa
            example.ml -o example
\end{verbatim}

When using the {\em dune} build system, this example can be built as follows:

\begin{verbatim}
(executable
 (name example)
 (modules example)
 (libraries unix runtime_events))
\end{verbatim}

Running the compiled binary of the example gives an output similar to:

\begin{verbatim}
Begin   explicit_gc_full_major  24086187297852
Begin   stw_leader      24086187298594
Begin   minor   24086187299404
Begin   minor_global_roots      24086187299807
End     minor_global_roots      24086187331461
Begin   minor_remembered_set    24086187331631
Begin   minor_finalizers_oldify 24086187544312
End     minor_finalizers_oldify 24086187544704
Begin   minor_remembered_set_promote    24086187544879
End     minor_remembered_set_promote    24086187606414
End     minor_remembered_set    24086187606584
Begin   minor_finalizers_admin  24086187606854
End     minor_finalizers_admin  24086187607152
Begin   minor_local_roots       24086187607329
Begin   minor_local_roots_promote       24086187609699
End     minor_local_roots_promote       24086187610539
End     minor_local_roots       24086187610709
End     minor   24086187611746
Begin   minor_clear     24086187612238
End     minor_clear     24086187612580
End     stw_leader      24086187613209
...
\end{verbatim}

This is an example of self-monitoring, where a program explicitly starts
listening to runtime events and monitors itself.

For external monitoring, a program does not need to be aware of the existence of runtime
events. Runtime events can be controlled via the environment variable
"OCAML_RUNTIME_EVENTS_START" which, when set, will cause the runtime
tracing system to be started at program initialization.

We could remove "Runtime_events.start ();" from the previous example and,
instead, call the program as below to produce the same result:

\begin{verbatim}
OCAML_RUNTIME_EVENTS_START=1 ./example
\end{verbatim}

\subsubsection{s:runtime-tracing-environment-variables}{Environment variables}

Environment variables can be used to control different aspects of the runtime
event tracing system. The following environment variables are available:

\begin{itemize}
  \item OCAML_RUNTIME_EVENTS_START if set will cause the runtime events system
  to be started as part of the OCaml runtime initialization.
  \item OCAML_RUNTIME_EVENTS_DIR sets the directory where the ".events"
  files containing the runtime event tracing system's ring buffers will be located.
  If not present the program's working directory will be used.
  \item OCAML_RUNTIME_EVENTS_PRESERVE if set will make the OCaml runtime
  preserve the runtime events ring buffer files past the termination of the OCaml program.
  This can be useful for monitoring very short running programs.
  If not set, the ".events" files of the OCaml program will be deleted
  at program termination.
\end{itemize}

The size of the runtime events ring buffers can be configured via OCAMLRUNPARAM,
see section \ref{s:ocamlrun-options} for more information.

\subsubsection{s:runtime-tracing-instrumented-runtime}{Building with the instrumented runtime}

Some events are only emitted by the instrumented runtime. To receive them, the
OCaml program needs to be compiled and linked against the instrumented runtime.
For our example program from earlier, this is achieved as follows:

\begin{verbatim}
ocamlopt -runtime-variant i -I +runtime_events -I +unix unix.cmxa runtime_events.cmxa example.ml -o example
\end{verbatim}

And for dune:

\begin{verbatim}
(executable
 (name example)
 (modules example)
 (flags "-runtime-variant=i")
 (libraries unix runtime_events))
\end{verbatim}

\subsection{s:runtime-tracing-tooling}{With tooling}

Programmatic access to events is intended primarily for writers of observability
libraries and tooling for end-users. The flexible API enables use of the
performance data from runtime events for logging and monitoring purposes.

In this section we cover several utilities in the \texttt{runtime_events_tools}
package which provide simple ways of extracting and summarising data from runtime
events. The trace utility in particular produces similar data to the previous
'eventlog' instrumentation system available in OCaml 4.12 to 4.14.

First, install \texttt{runtime_events_tools} in an OCaml 5.0+ opam switch:

\begin{verbatim}
opam install runtime_events_tools
\end{verbatim}

This should install the olly tool in your path. You can now generate
runtime traces for programs compiled with OCaml 5.0+ using the trace subcommand:

\begin{verbatim}
olly trace trace.json 'your_program.exe .. args ..'
\end{verbatim}

Runtime tracing data will be generated in the json Trace Event Format to trace.json.
This can then be loaded into the Chrome tracing viewer or into \ifouthtml
\ahref{https://ui.perfetto.dev/}{Perfetto}
\else
Perfetto
\fi
to visualize the collected trace.

\subsubsection{s:runtime-tracing-latency}{Measuring GC latency}

The olly utility also includes a latency subcommand which consumes runtime
events data and on program completion emits a parseable histogram summary of
pause durations. It can be run as follows:

\begin{verbatim}
olly latency 'your_program.exe .. args ..'
\end{verbatim}

This should produce an output similar to the following:

\begin{verbatim}
GC latency profile:
#[Mean (ms):	2.46,	 Stddev (ms):	3.87]
#[Min (ms):	0.01,	 max (ms):	9.17]

Percentile 	 Latency (ms)
25.0000 	 0.01
50.0000 	 0.23
60.0000 	 0.23
70.0000 	 0.45
75.0000 	 0.45
80.0000 	 0.45
85.0000 	 0.45
90.0000 	 9.17
95.0000 	 9.17
96.0000 	 9.17
97.0000 	 9.17
98.0000 	 9.17
99.0000 	 9.17
99.9000 	 9.17
99.9900 	 9.17
99.9990 	 9.17
99.9999 	 9.17
100.0000 	 9.17
\end{verbatim}

\section{s:runtime-tracing-custom-events}{Custom events}

\subsection{s:runtime-tracing-custom-events-overview}{Overview}

The runtime events system supports defining custom events. Identified by a
globally unique name, they are emitted with payloads of built-in (\texttt{unit},
\texttt{int}, \texttt{span}) and user-defined types. To understand the
manipulation of custom events, it is useful to know how they are transported and
stored: their representation consists of a name string (in fact, an index into
an array of all custom names) and an arbitrary byte sequence. Custom event
types can be \emph{registered} by providing encoding and decoding functions to
and from a byte sequence, via the function
\texttt{Runtime_events.Type.register}.

Defining a new custom event (whether its payload is of a built-in type or a
custom type) is done via another registration function,
\texttt{Runtime_events.User.register}. This function records the association
between the custom event's name, its type, and a \emph{tag}. The tag is then
used when emitting or consuming custom events; it acts as a shorthand for the
event name.

Once an event is registered, values for that event are emitted using
\texttt{Runtime_events.User.write}.

To summarize, for a user to emit and consume custom events using a custom type
they need to:

\begin{enumerate}
\item register the custom type
\item extend the \texttt{Runtime_events.User.tag} variant with a new constructor
\item register the new custom event, binding together the custom event name, the
  new tag, and the new custom type
\item emit instances of the event using \texttt{Runtime_events.User.write}
\item indicate a callback which should receive all events of the custom
  type using \texttt{Runtime_events.Callbacks.add_user_event} to register it
  inside a \texttt{Runtime_events.Callbacks.t} object to be used when polling
  (see section~\ref{s:runtime-tracing-ocaml-apis} above).
\item \emph{(Optional, if there are distinct events registered with the same
  custom type:)} In that callback, pattern-match on the event tag in order to
  discriminate between different event tags of the same custom type.
\end{enumerate}

Note that if the emitter and the consumer are different programs, both must
perform steps 1 to 3 to register custom events and custom event types (if any).
Note that the tag values need not be the same in both programs; the only values
that should match are the names.

Unregistered events for user-defined types are currently ignored. As a fallback,
unregistered, custom events of a built-in type are available, but are all
tagged \texttt{UNK} (unknown).

There are thus three cases for the consumer when an event is received:
\begin{itemize}
\item event is registered: payload and tag are available.
\item event is not registered and has a built-in event type (unit, int, span):
    only the payload is available.
\item event is not registered and has a custom event type: event is dropped.
\end{itemize}

Note that event consumers bind callbacks to event \emph{types}, so they can work
as generic listeners interpreting payloads coming from events that were not
registered. Because this only works for events of built-in types, it can be
useful to emit events in pairs: an event of a custom type with an event of a
built-in type, enabling the design of a specialized consumer while staying
compatible with generic tracing tools.

\subsection{s:runtime-tracing-custom-events-usage}{Tracing custom events: an
example}

The following program uses the \texttt{Runtime_events.User} and
\texttt{Runtime_events.Type} modules to declare two custom events providing
\texttt{span} and \texttt{int} values. The \texttt{tag} extensible variant is
extended with \texttt{CustomSpan} and \texttt{CustomInt}.

\begin{verbatim}
type Runtime_events.User.tag += CustomSpan | CustomInt

let count_span =
    Runtime_events.User.register "count.span" CustomSpan
        Runtime_events.Type.span

let count_value =
    Runtime_events.User.register "count.value" CustomInt
        Runtime_events.Type.int

let count () =
    Runtime_events.User.write count_span Begin;
    for i = 1 to 5 do
        Runtime_events.User.write count_value i
    done;
    Runtime_events.User.write count_span End

let () =
    Runtime_events.start ();
    for _ = 1 to 3 do
        count ()
    done
\end{verbatim}

On the consumer side, one can use the provided event tag and type to match on
the relevant events. For the sake of completeness, we assume that the consumer
is a different program, and repeat the definition of the new tag constructors,
as well as the registering of the custom events.

\begin{verbatim}
type Runtime_events.User.tag += CustomSpan | CustomInt

let count_span =
    Runtime_events.User.register "count.span" CustomSpan
        Runtime_events.Type.span

let count_value =
    Runtime_events.User.register "count.value" CustomInt
        Runtime_events.Type.int

let span_event_handler domain_id ts event value =
    (* we're only interested in our CustomSpan event *)
    match Runtime_events.User.tag event, value with
    | CustomSpan, Runtime_events.Type.Begin -> Printf.printf "> count begin\n"
    | CustomSpan, End -> Printf.printf "< count end\n"
    | _ -> ()

let int_event_handler domain_id ts event value =
    (* we're only interested in our CustomInt event *)
    match Runtime_events.User.tag event with
    | CustomInt -> Printf.printf "| count %d\n" value
    | _ -> ()

let () =
    let open Runtime_events in
    let cursor = create_cursor None in
    let callbacks =
        Callbacks.create ()
        |> Callbacks.add_user_event Type.span span_event_handler
        |> Callbacks.add_user_event Type.int int_event_handler
    in
    for _ = 0 to 100 do
        ignore(read_poll cursor callbacks None)
    done
\end{verbatim}

Giving the following output:
\begin{verbatim}
> count begin
| count 1
| count 2
| count 3
| count 4
| count 5
< count end
> count begin
| count 1
| count 2
[...]
\end{verbatim}