add manual page for the instrumented runtime
Enguerrand Decorne
parent
24806a0223
commit
f3ee9e3beb
3
Changes
3
Changes
|
|
@ -41,6 +41,9 @@ Working version
|
|||
in 'union'; note that find and find_opt return values, not bindings.
|
||||
(Jeremy Yallop, review by Gabriel Scherer and Florian Angeletti)
|
||||
|
||||
- #9541: Add a documentation page for the instrumented runtime
|
||||
(Enguerrand Decorne)
|
||||
|
||||
### Compiler user-interface and warnings:
|
||||
|
||||
|
||||
|
|
|
|||
|
|
@ -87,6 +87,7 @@ chapters (or sometimes sections) are mapped to a distinct `.etex` file:
|
|||
- Optimisation with Flambda: `flambda.etex`
|
||||
- Memory profiling with Spacetime: `spacetime-chapter.etex`
|
||||
- Fuzzing with afl-fuzz: `afl-fuzz.etex`
|
||||
- Runtime tracing with the instrumented runtime: `instrumented-runtime.etex`
|
||||
|
||||
Note that ocamlc,ocamlopt and the toplevel options overlap a lot.
|
||||
Consequently, these options are described together in the file
|
||||
|
|
|
|||
|
|
@ -73,6 +73,7 @@ and as a
|
|||
\input{flambda.tex}
|
||||
\input{spacetime-chapter.tex}
|
||||
\input{afl-fuzz.tex}
|
||||
\input{instrumented-runtime.tex}
|
||||
|
||||
\part{The OCaml library}
|
||||
\label{p:library}
|
||||
|
|
|
|||
|
|
@ -13,7 +13,7 @@ TRANSF = $(SET_LD_PATH) $(OCAMLRUN) $(TOOLS)/transf
|
|||
FILES = comp.tex top.tex runtime.tex native.tex lexyacc.tex intf-c.tex \
|
||||
ocamldep.tex profil.tex debugger.tex browser.tex ocamldoc.tex \
|
||||
warnings-help.tex ocamlbuild.tex flambda.tex spacetime-chapter.tex \
|
||||
afl-fuzz.tex unified-options.tex
|
||||
afl-fuzz.tex instrumented-runtime.tex unified-options.tex
|
||||
|
||||
WITH_TRANSF = top.tex intf-c.tex flambda.tex spacetime-chapter.tex \
|
||||
afl-fuzz.tex lexyacc.tex debugger.tex
|
||||
|
|
|
|||
|
|
@ -0,0 +1,312 @@
|
|||
\chapter{Runtime tracing with the instrumented runtime}
|
||||
%HEVEA\cutname{instrumented-runtime.html}
|
||||
|
||||
This chapter describes the OCaml instrumented runtime, a runtime variant
|
||||
allowing the collection of events and metrics.
|
||||
It aims to provide insight into a program's execution.
|
||||
|
||||
\section{s:instr-runtime-overview}{Overview}
|
||||
|
||||
Once compiled and linked with the instrumented runtime, any OCaml program
|
||||
can generate {\em trace files} that can then be read
|
||||
and analyzed by users in order to understand specific runtime behaviors.
|
||||
|
||||
The {\em Common Trace Format} is the general purpose binary
|
||||
format used to encode traces.
|
||||
A complete trace is comprised of:
|
||||
\begin{itemize}
|
||||
\item a {\em metadata file}, part of the OCaml distribution
|
||||
\item and a {\em trace file}, generated by the runtime\
|
||||
in the program being traced.
|
||||
\end{itemize}
|
||||
|
||||
For more information on the {\em Common Trace Format}, see the website at
|
||||
\ifouthtml
|
||||
\ahref{https://diamon.org/ctf/}{https://diamon.org/ctf/}.
|
||||
\else
|
||||
{\tt https://diamon.org/ctf/}
|
||||
\fi
|
||||
|
||||
\section{s:instr-runtime-enabling}{Enabling runtime instrumentation}
|
||||
|
||||
|
||||
For the following examples, we will use the following example program:
|
||||
|
||||
\begin{verbatim}
|
||||
module SMap = Map.Make(String)
|
||||
|
||||
let s i = String.make 512 (Char.chr (i mod 256))
|
||||
|
||||
let clear map = SMap.fold (fun k _ m -> SMap.remove k m) map map
|
||||
|
||||
let rec seq i =
|
||||
if i = 0 then Seq.empty else fun () -> (Seq.Cons (i, seq (i - 1)))
|
||||
|
||||
let () =
|
||||
seq 1_000_000
|
||||
|> Seq.fold_left (fun m i -> SMap.add (s i) i m) SMap.empty
|
||||
|> clear
|
||||
|> ignore
|
||||
|
||||
\end{verbatim}
|
||||
|
||||
Compiling the program and linking it with the instrumented runtime,
|
||||
can be done with {\tt -runtime-variant} flag {\tt i}:
|
||||
|
||||
\begin{verbatim}
|
||||
ocamlopt -runtime-variant i program.ml -o program
|
||||
\end{verbatim}
|
||||
|
||||
The resulting program can then be traced by running it with the environment
|
||||
variable {\tt OCAML\_EVENTLOG\_ENABLED}:
|
||||
|
||||
\begin{verbatim}
|
||||
OCAML_EVENTLOG_ENABLED=1 ./program
|
||||
\end{verbatim}
|
||||
|
||||
The program will execute and generate a trace file in the
|
||||
current directory.
|
||||
|
||||
\subsubsection*{sss:instr-runtime-build-more}{More build examples}
|
||||
|
||||
When using the {\em dune} build system, this compiler invocation can be
|
||||
replicated using the {\tt flags} {\tt stanza} when building an executable.
|
||||
|
||||
\begin{verbatim}
|
||||
(executable
|
||||
(name program)
|
||||
(flags "-runtime-variant=i"))
|
||||
\end{verbatim}
|
||||
|
||||
The instrumented runtime can as well be used with OCaml's bytecode interpreter.
|
||||
This can be done by either compiling the program using the
|
||||
{\tt -runtime-variant=i} flag with {\tt ocamlc}, or by running the generated
|
||||
bytecode through {\tt ocamlruni}:
|
||||
|
||||
\begin{verbatim}
|
||||
ocamlc program.ml -o program.byte
|
||||
OCAML_EVENTLOG_ENABLED=1 ocamlruni program.byte
|
||||
\end{verbatim}
|
||||
|
||||
See chapter~\ref{c:camlc} and chapter~\ref{c:runtime} for more information about
|
||||
{\tt ocamlc} and {\tt ocamlrun}.
|
||||
|
||||
\subsection{ss:instr-runtime-prefix}{Trace filename}
|
||||
|
||||
The default trace filename is {\tt caml-\{pid\}.eventlog}, where {\tt \{pid\}}
|
||||
is the process identifier of the traced program.
|
||||
|
||||
This filename can also be specified using the
|
||||
{\tt OCAML\_EVENTLOG\_PREFIX} environment variable.
|
||||
The given path will be suffixed with {\tt \{.pid\}.eventlog}.
|
||||
|
||||
\begin{verbatim}
|
||||
OCAML_EVENTLOG_PREFIX=/tmp/a_prefix OCAML_EVENTLOG_ENABLED=1 ./program
|
||||
\end{verbatim}
|
||||
|
||||
Note that this will only affect the prefix of the trace file, there is no
|
||||
option to specify the full effective file name.
|
||||
This restriction is in place to make room for future improvements to the
|
||||
instrumented runtime, where the single trace file per session design
|
||||
may replaced.
|
||||
|
||||
In this example, the trace will be available at path
|
||||
{\tt /tmp/a_prefix.\{pid\}.eventlog}.
|
||||
|
||||
For scripting purpose, matching against `\{pid\}` as well as the
|
||||
{\tt .eventlog} file extension should provide enough control over
|
||||
the generated files.
|
||||
|
||||
\subsection{ss:instr-runtime-pause}{Pausing and resuming tracing}
|
||||
Primitives are available to control events collection at runtime.
|
||||
|
||||
{\tt OCAML\_EVENTLOG\_ENABLED} can be set to the {\tt p} flag in order
|
||||
to {\em pause} events collection after the program has started.
|
||||
|
||||
\begin{verbatim}
|
||||
OCAML_EVENTLOG_ENABLED=p ./program
|
||||
\end{verbatim}
|
||||
|
||||
The program will have to resume events collection explicitly.
|
||||
This can be done via {\tt Gc.eventlog_resume} and
|
||||
{\tt Gc.eventlog_pause}, available in the {\stdmoduleref{Gc}} module.
|
||||
|
||||
Running the program provided earlier with {\tt OCAML\_EVENTLOG\_ENABLED=p}
|
||||
will for example yield the following result.
|
||||
|
||||
\begin{verbatim}
|
||||
$ OCAML_EVENTLOG_ENABLED=p ./a.out
|
||||
$ ocaml-eventlog-report caml-{pid}.eventlog
|
||||
==== eventlog/flush
|
||||
median flush time: 58ns
|
||||
total flush time: 58ns
|
||||
flush count: 1
|
||||
\end{verbatim}
|
||||
|
||||
The resulting trace contains only one event payload, namely a {\em flush} event,
|
||||
indicating how much time was taken to flush the trace file to disk.
|
||||
|
||||
However, if the program is changed to include a call to
|
||||
{\tt Gc.eventlog_resume}, events payloads can be seen again
|
||||
in the trace file.
|
||||
|
||||
\begin{verbatim}
|
||||
let () =
|
||||
Gc.eventlog_resume();
|
||||
seq 1_000_000
|
||||
|> Seq.fold_left (fun m i -> SMap.add (s i) i m) SMap.empty
|
||||
|> clear
|
||||
|> ignore
|
||||
|
||||
\end{verbatim}
|
||||
|
||||
The resulting trace will contain every events encountered during
|
||||
the program's execution:
|
||||
|
||||
\begin{verbatim}
|
||||
$ ocaml-eventlog-report caml-{pid}.eventlog
|
||||
[..omitted..]
|
||||
==== force_minor/alloc_small
|
||||
100.0K..200.0K: 174
|
||||
20.0K..30.0K: 1
|
||||
0..100: 1
|
||||
|
||||
==== eventlog/flush
|
||||
median flush time: 207.8us
|
||||
total flush time: 938.1us
|
||||
flush count: 5
|
||||
\end{verbatim}
|
||||
|
||||
\subsection{ss:instr-runtime-limitations}{Limitations}
|
||||
|
||||
The instrumented runtime does not support the {\tt fork} system call.
|
||||
A child process forked from an instrumented program will not be traced.
|
||||
|
||||
The instrumented runtime aims to provide insight into the runtime's execution
|
||||
while maintaining a low overhead.
|
||||
However, this overhead may become more noticeable depending on how a program
|
||||
executes.
|
||||
The instrumented runtime currently put a strong emphasis on
|
||||
tracing {\em garbage collection} events. This means that programs
|
||||
with heavy garbage collection activity may be more susceptible to
|
||||
tracing induced performance penalties.
|
||||
|
||||
While providing an accurate estimate of potential performance loss is difficult,
|
||||
test on various OCaml programs showed a total running time increase ranging
|
||||
from 1\% to 8\%.
|
||||
|
||||
For a program with an extended running time where the collection of only a
|
||||
small sample of events is required, using the {\em eventlog_resume} and
|
||||
{\em eventlog_pause} primitives may help relieve some of the
|
||||
tracing induced performance impact.
|
||||
|
||||
\section{s:instr-runtime-read}{Reading traces}
|
||||
|
||||
Traces generated by the instrumented runtime can be analyzed with tooling
|
||||
available outside of the OCaml distribution.
|
||||
|
||||
A complete trace is comprised of a {\em metadata file} and a {\em trace file}.
|
||||
Two simple ways to work with the traces are the {\em eventlog-tools} and
|
||||
{\em babeltrace} libraries.
|
||||
|
||||
\subsection{ss:instr-runtime-tools}{eventlog-tools}
|
||||
{\em eventlog-tools} is a set of libraries and tools written in OCaml
|
||||
that allow to decode and perform basic format conversions and analysis.
|
||||
|
||||
For more information about {\em eventlog-tools}, refer to the project's
|
||||
main page:
|
||||
\ifouthtml
|
||||
\ahref{https://github.com/ocaml-multicore/eventlog-tools}
|
||||
{https://github.com/ocaml-multicore/eventlog-tools}.
|
||||
\else
|
||||
{\tt https://github.com/ocaml-multicore/eventlog-tools}
|
||||
\fi
|
||||
|
||||
\subsection{ss:instr-runtime-babeltrace}{babeltrace}
|
||||
|
||||
{\em babeltrace} is a C library, as well as a Python binding and set of tools
|
||||
that serve as the reference implementation for the {\em Common Trace Format}.
|
||||
The {\em babeltrace} command line utility allows for a basic rendering
|
||||
of a trace's content, while the high level Python API can be used to
|
||||
decode the trace and process them programmatically with libraries
|
||||
such as {\em numpy} or {\em Jupyter}.
|
||||
|
||||
Unlike {\em eventlog-tools}, which possesses a specific knowledge of
|
||||
OCaml's {\em Common Trace Format} schema, it is required to provide
|
||||
the OCaml {\em metadata} file to {\em babeltrace}.
|
||||
|
||||
The metadata file is available in the OCaml installation.
|
||||
Its location can be obtained using the following command:
|
||||
|
||||
\begin{verbatim}
|
||||
ocamlc -where
|
||||
\end{verbatim}
|
||||
|
||||
The {\em eventlog_metadata} file can be found at this path and
|
||||
copied in the same directory as the generated trace file.
|
||||
However, {\em babeltrace} expects the file to be named
|
||||
{\tt metadata} in order to process the trace.
|
||||
Thus, it will need to be renamed when copied to the trace's directory.
|
||||
|
||||
Here is a naive decoder example, using {\em babeltrace}'s Python
|
||||
library, and {\em Python 3.8}:
|
||||
|
||||
\begin{verbatim}
|
||||
|
||||
import subprocess
|
||||
import shutil
|
||||
import sys
|
||||
import babeltrace as bt
|
||||
|
||||
def print_event(ev):
|
||||
print(ev['timestamp'])
|
||||
print(ev['pid'])
|
||||
if ev.name == "entry":
|
||||
print('entry_event')
|
||||
print(ev['phase'])
|
||||
if ev.name == "exit":
|
||||
print('exit_event')
|
||||
print(ev['phase'])
|
||||
if ev.name == "alloc":
|
||||
print(ev['count'])
|
||||
print(ev['bucket'])
|
||||
if ev.name == "counter":
|
||||
print(ev['count'])
|
||||
print(ev['kind'])
|
||||
if ev.name == "flush":
|
||||
print("flush")
|
||||
|
||||
def get_ocaml_dir():
|
||||
# Fetching OCaml's installation directory to extract the CTF metadata
|
||||
ocamlc_where = subprocess.run(['ocamlc', '-where'], stdout=subprocess.PIPE)
|
||||
ocaml_dir = ocamlc_where.stdout.decode('utf-8').rstrip('\n')
|
||||
return(ocaml_dir)
|
||||
|
||||
def main():
|
||||
trace_dir = sys.argv[1]
|
||||
ocaml_dir = get_ocaml_dir()
|
||||
metadata_path = ocaml_dir + "/eventlog_metadata"
|
||||
# copying the metadata to the trace's directory,
|
||||
# and renaming it to 'metadata'.
|
||||
shutil.copyfile(metadata_path, trace_dir + "/metadata")
|
||||
tr = bt.TraceCollection()
|
||||
tr.add_trace(trace_dir, 'ctf')
|
||||
for event in tr.events:
|
||||
print_event(event)
|
||||
|
||||
if __name__ == '__main__':
|
||||
main()
|
||||
|
||||
\end{verbatim}
|
||||
|
||||
This script expect to receive as an argument the directory containing the
|
||||
trace file. It will then copy the {\em CTF} metadata file to the trace's
|
||||
directory, and then decode the trace, printing each events in the process.
|
||||
|
||||
For more information on {\em babeltrace}, see the website at:
|
||||
\ifouthtml
|
||||
\ahref{https://babeltrace.org/}
|
||||
{https://babeltrace.org/}.
|
||||
\else
|
||||
{\tt https://babeltrace.org/}
|
||||
\fi
|
||||
Loading…
Reference in New Issue