mirror of
https://gitlab.torproject.org/tpo/core/tor.git
synced 2024-11-24 04:13:28 +01:00
trace: Comments and improve doc/HACKING/Tracing.md
Signed-off-by: David Goulet <dgoulet@torproject.org>
This commit is contained in:
David Goulet
parent
c8f632784b
commit
79d6127a47
@ -2,19 +2,26 @@
|
||||
|
||||
This document describes how the event tracing subsystem works in tor so
|
||||
developers can add events to the code base but also hook them to an event
|
||||
tracing framework.
|
||||
tracing framework (i.e. tracer).
|
||||
|
||||
## Basics
|
||||
|
||||
Event tracing is separated in two concepts, trace events and a tracer. The
|
||||
tracing subsystem can be found in `src/trace`. The `events.h` header file is
|
||||
the main file that maps the different tracers to trace events.
|
||||
Tracing is separated in two different concepts. The tracing API and the
|
||||
tracing probes.
|
||||
|
||||
The API is in `src/lib/trace/` which defines how to call tracepoints in the
|
||||
tor code. Every C files should include `src/lib/trace/events.h" if they want
|
||||
to call a tracepoint.
|
||||
|
||||
The probes are what actually record the tracepoint data. Because they often
|
||||
need to access specific subsystem objects, the probes are within each
|
||||
subsystem. They are defined in the `trace-probes-<subsystem>.c` files.
|
||||
|
||||
### Events
|
||||
|
||||
A trace event is basically a function from which we can pass any data that
|
||||
we want to collect. In addition, we specify a context for the event such as
|
||||
a subsystem and an event name.
|
||||
A trace event is basically a function from which we can pass any data that we
|
||||
want to collect. In addition, we specify a context for the event such as the
|
||||
subsystem and an event name.
|
||||
|
||||
A trace event in tor has the following standard format:
|
||||
|
||||
@ -23,69 +30,106 @@ A trace event in tor has the following standard format:
|
||||
The `subsystem` parameter is the name of the subsytem the trace event is in.
|
||||
For example that could be "scheduler" or "vote" or "hs". The idea is to add
|
||||
some context to the event so when we collect them we know where it's coming
|
||||
from. The `event_name` is the name of the event which helps a lot with
|
||||
adding some semantic to the event. Finally, `args` is any number of
|
||||
arguments we want to collect.
|
||||
from.
|
||||
|
||||
The `event\_name` is the name of the event which adds better semantic to the
|
||||
event.
|
||||
|
||||
The `args` can be any number of arguments we want to collect.
|
||||
|
||||
Here is an example of a possible tracepoint in main():
|
||||
|
||||
tor_trace(main, init_phase, argc)
|
||||
|
||||
The above is a tracepoint in the `main` subsystem with `init_phase` as the
|
||||
event name and the `int argc` is passed to the event as well.
|
||||
The above is a tracepoint in the `main` subsystem with `init\_phase` as the
|
||||
event name and the `int argc` is passed to the event as one argument.
|
||||
|
||||
How `argc` is collected or used has nothing to do with the instrumentation
|
||||
(adding trace events to the code). It is the work of the tracer so this is why
|
||||
the trace events and collection framework (tracer) are decoupled. You _can_
|
||||
have trace events without a tracer.
|
||||
|
||||
### Tracer
|
||||
### Instrumentation ###
|
||||
|
||||
In `src/trace/events.h`, we map the `tor_trace()` function to the right
|
||||
tracer. A tracer support is only enabled at compile time. For instance, the
|
||||
file `src/trace/debug.h` contains the mapping of the generic tracing function
|
||||
`tor_trace()` to the `log_debug()` function. More specialized function can be
|
||||
mapped depending on the tracepoint.
|
||||
In `src/lib/trace/events.h`, we map the high level `tor\_trace()` macro to one
|
||||
or many enabled instrumentation.
|
||||
|
||||
Currently, we have 3 types of possible instrumentation:
|
||||
|
||||
1. Debug
|
||||
|
||||
This will map every tracepoint to `log\_debug()`. However, none of the
|
||||
arguments will be passed on because we don't know their type nor the string
|
||||
format of the debug log. The output is standardized like this:
|
||||
|
||||
[debug] __FUNC__: Tracepoint <event_name> from subsystem <subsystem> hit.
|
||||
|
||||
2. USDT
|
||||
|
||||
User Statically-Defined Tracing (USDT) is a kind of probe which can be
|
||||
handled by a variety of tracers such as SystemTap, DTrace, perf, eBPF and
|
||||
ftrace.
|
||||
|
||||
For each tracer, one will need to define the ABI in order for the tracer to
|
||||
be able to extract the data from the tracepoint objects. For instance, the
|
||||
tracer needs to know how to print the circuit state of a `circuit\_t`
|
||||
object.
|
||||
|
||||
3. LTTng-UST
|
||||
|
||||
LTTng Userspace is a tracer that has it own type of instrumentation. The
|
||||
probe definitions are created within the C code and is strongly typed.
|
||||
|
||||
For more information, see https://lttng.org/docs.
|
||||
|
||||
## Build System
|
||||
|
||||
This section describes how it is integrated into the build system of tor.
|
||||
This section describes how the instrumentation is integrated into the build
|
||||
system of tor.
|
||||
|
||||
By default, every tracing events are disabled in tor that is `tor_trace()`
|
||||
is a NOP.
|
||||
By default, every tracing events are disabled in tor that is `tor\_trace()` is
|
||||
a NOP thus has no execution cost time.
|
||||
|
||||
To enable a tracer, there is a configure option on the form of:
|
||||
To enable a specific instrumentation, there are configure options:
|
||||
|
||||
--enable-tracing-<tracer>
|
||||
1. Debug: `--enable-tracing-instrumentation-debug`
|
||||
|
||||
We have an option that will send every trace events to a `log_debug()` (as
|
||||
mentionned above) which will print you the subsystem and name of the event but
|
||||
not the arguments for technical reasons. This is useful if you want to quickly
|
||||
see if your trace event is being hit or well written. To do so, use this
|
||||
configure option:
|
||||
2. USDT: `--enable-tracing-instrumentation-usdt`
|
||||
|
||||
--enable-tracing-debug
|
||||
3. LTTng: `--enable-tracing-instrumentation-lttng`
|
||||
|
||||
## Instrument Tor
|
||||
They can all be used together or independently. If one of them is set,
|
||||
`HAVE\_TRACING` define is set. And for each instrumentation, a
|
||||
`USE\_TRACING\_INSTRUMENTATION\_<type>` is set.
|
||||
|
||||
## Adding a Tracepoint ##
|
||||
|
||||
This is pretty easy. Let's say you want to add a trace event in
|
||||
`src/feature/rend/rendcache.c`, you only have to add this include statement:
|
||||
`src/feature/rend/rendcache.c`, you first need to include this file:
|
||||
|
||||
#include "trace/events.h"
|
||||
#include "lib/trace/events.h"
|
||||
|
||||
Once done, you can add as many as you want `tor_trace()` that you need.
|
||||
Please use the right subsystem (here it would be `hs`) and a unique name that
|
||||
tells what the event is for. For example:
|
||||
Then, the `tor\_trace()` macro can be used with the specific format detailled
|
||||
before in a previous section. As an example:
|
||||
|
||||
tor_trace(hs, store_desc_as_client, desc, desc_id);
|
||||
|
||||
If you look in `src/trace/events.h`, you'll see that if tracing is enabled it
|
||||
will be mapped to a function called:
|
||||
For `Debug` instrumentation, you have nothing else to do.
|
||||
|
||||
tor_trace_hs_store_desc_as_client(desc, desc_id)
|
||||
For `USDT`, instrumentation, you will need to define the probes in a way the
|
||||
specific tracer can understand. For instance, SystemTap requires you to define
|
||||
a `tapset` for each tracepoints.
|
||||
|
||||
And the point of all this is for that function to be defined in a new file
|
||||
that you might want to add named `src/trace/hs.{c|h}` which would defined how
|
||||
to collect the data for the `tor_trace_hs_store_desc_as_client()` function
|
||||
like for instance sending it to a `log_debug()` or do more complex operations
|
||||
or use a userspace tracer like LTTng (https://lttng.org).
|
||||
For `LTTng`, you will need to define the probes in the
|
||||
`trace-probes-<subsystem>.{c|h}` file. See the `trace-probes-circuit.{c|h}`
|
||||
file as an example and https://lttng.org/docs/v2.11/#doc-instrumenting.
|
||||
|
||||
## Performance ##
|
||||
|
||||
A word about performance when a tracepoint is enabled. One of the goal of a
|
||||
tracepoint (USDT, LTTng-UST, ...) is that they can be enabled or disabled. By
|
||||
default, they are disabled which means the tracer will not record the data but
|
||||
it has to do a check thus the cost is basically the one of a `branch`.
|
||||
|
||||
If enabled, then the performance depends on the tracer. In the case of
|
||||
LTTng-UST, the event costs around 110nsec.
|
||||
|
||||
@ -24,6 +24,13 @@
|
||||
|
||||
#include <lttng/tracepoint.h>
|
||||
|
||||
/*
|
||||
* Circuit Purposes
|
||||
*
|
||||
* The following defines an enumeration of all possible circuit purpose so
|
||||
* they appear in the trace with the define name (first parameter of
|
||||
* ctf_enum_value) instead of the numerical value.
|
||||
*/
|
||||
TRACEPOINT_ENUM(tor_circuit, purpose,
|
||||
TP_ENUM_VALUES(
|
||||
/* Initializing. */
|
||||
@ -70,6 +77,13 @@ TRACEPOINT_ENUM(tor_circuit, purpose,
|
||||
)
|
||||
)
|
||||
|
||||
/*
|
||||
* Circuit End Reasons
|
||||
*
|
||||
* The following defines an enumeration of all possible circuit end reasons so
|
||||
* they appear in the trace with the define name (first parameter of
|
||||
* ctf_enum_value) instead of the numerical value.
|
||||
*/
|
||||
TRACEPOINT_ENUM(tor_circuit, end_reason,
|
||||
TP_ENUM_VALUES(
|
||||
/* Local reasons. */
|
||||
@ -120,6 +134,13 @@ TRACEPOINT_ENUM(tor_circuit, end_reason,
|
||||
)
|
||||
)
|
||||
|
||||
/*
|
||||
* Circuit State
|
||||
*
|
||||
* The following defines an enumeration of all possible circuit state so they
|
||||
* appear in the trace with the define name (first parameter of
|
||||
* ctf_enum_value) instead of the numerical value.
|
||||
*/
|
||||
TRACEPOINT_ENUM(tor_circuit, state,
|
||||
TP_ENUM_VALUES(
|
||||
ctf_enum_value("BUILDING", CIRCUIT_STATE_BUILDING)
|
||||
@ -130,6 +151,15 @@ TRACEPOINT_ENUM(tor_circuit, state,
|
||||
)
|
||||
)
|
||||
|
||||
/*
|
||||
* Event Class
|
||||
*
|
||||
* A tracepoint class is a class of tracepoints which share the same output
|
||||
* event field definitions. They are then used by the
|
||||
* TRACEPOINT_EVENT_INSTANCE() macro as a base field definition.
|
||||
*/
|
||||
|
||||
/* Class for origin circuit. */
|
||||
TRACEPOINT_EVENT_CLASS(tor_circuit, origin_circuit_t_class,
|
||||
TP_ARGS(const origin_circuit_t *, circ),
|
||||
TP_FIELDS(
|
||||
@ -139,6 +169,7 @@ TRACEPOINT_EVENT_CLASS(tor_circuit, origin_circuit_t_class,
|
||||
)
|
||||
)
|
||||
|
||||
/* Class for or circuit. */
|
||||
TRACEPOINT_EVENT_CLASS(tor_circuit, or_circuit_t_class,
|
||||
TP_ARGS(const or_circuit_t *, circ),
|
||||
TP_FIELDS(
|
||||
@ -149,32 +180,44 @@ TRACEPOINT_EVENT_CLASS(tor_circuit, or_circuit_t_class,
|
||||
|
||||
/*
|
||||
* Origin circuit events.
|
||||
*
|
||||
* Tracepoint use the origin_circuit_t object.
|
||||
*/
|
||||
|
||||
/* Tracepoint emitted when a new origin circuit has been created. */
|
||||
TRACEPOINT_EVENT_INSTANCE(tor_circuit, origin_circuit_t_class, new_origin,
|
||||
TP_ARGS(const origin_circuit_t *, circ)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when an origin circuit has opened. */
|
||||
TRACEPOINT_EVENT_INSTANCE(tor_circuit, origin_circuit_t_class, opened,
|
||||
TP_ARGS(const origin_circuit_t *, circ)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when an origin circuit has established. */
|
||||
TRACEPOINT_EVENT_INSTANCE(tor_circuit, origin_circuit_t_class, establish,
|
||||
TP_ARGS(const origin_circuit_t *, circ)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when an origin circuit has been cannibalized. */
|
||||
TRACEPOINT_EVENT_INSTANCE(tor_circuit, origin_circuit_t_class, cannibalized,
|
||||
TP_ARGS(const origin_circuit_t *, circ)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when an origin circuit has timed out. This is called
|
||||
* when circuit_expire_building() as selected the circuit and is about to
|
||||
* close it for timeout. */
|
||||
TRACEPOINT_EVENT_INSTANCE(tor_circuit, origin_circuit_t_class, timeout,
|
||||
TP_ARGS(const origin_circuit_t *, circ)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when an origin circuit has timed out due to idleness.
|
||||
* This is when the circuit is closed after MaxCircuitDirtiness. */
|
||||
TRACEPOINT_EVENT_INSTANCE(tor_circuit, origin_circuit_t_class, idle_timeout,
|
||||
TP_ARGS(const origin_circuit_t *, circ)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when an origin circuit sends out its first onion skin. */
|
||||
TRACEPOINT_EVENT(tor_circuit, first_onion_skin,
|
||||
TP_ARGS(const origin_circuit_t *, circ, const crypt_path_t *, hop),
|
||||
TP_FIELDS(
|
||||
@ -186,6 +229,8 @@ TRACEPOINT_EVENT(tor_circuit, first_onion_skin,
|
||||
)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when an origin circuit sends out an intermediate onion
|
||||
* skin. */
|
||||
TRACEPOINT_EVENT(tor_circuit, intermediate_onion_skin,
|
||||
TP_ARGS(const origin_circuit_t *, circ, const crypt_path_t *, hop),
|
||||
TP_FIELDS(
|
||||
@ -199,16 +244,22 @@ TRACEPOINT_EVENT(tor_circuit, intermediate_onion_skin,
|
||||
|
||||
/*
|
||||
* OR circuit events.
|
||||
*
|
||||
* Tracepoint use the or_circuit_t object.
|
||||
*/
|
||||
|
||||
/* Tracepoint emitted when a new or circuit has been created. */
|
||||
TRACEPOINT_EVENT_INSTANCE(tor_circuit, or_circuit_t_class, new_or,
|
||||
TP_ARGS(const or_circuit_t *, circ)
|
||||
)
|
||||
|
||||
/*
|
||||
* General circuit events.
|
||||
*
|
||||
* Tracepoint use the circuit_t object.
|
||||
*/
|
||||
|
||||
/* Tracepoint emitted when a circuit is freed. */
|
||||
TRACEPOINT_EVENT(tor_circuit, free,
|
||||
TP_ARGS(const circuit_t *, circ),
|
||||
TP_FIELDS(
|
||||
@ -220,6 +271,7 @@ TRACEPOINT_EVENT(tor_circuit, free,
|
||||
)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when a circuit is marked for close. */
|
||||
TRACEPOINT_EVENT(tor_circuit, mark_for_close,
|
||||
TP_ARGS(const circuit_t *, circ),
|
||||
TP_FIELDS(
|
||||
@ -235,6 +287,7 @@ TRACEPOINT_EVENT(tor_circuit, mark_for_close,
|
||||
)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when a circuit changes purpose. */
|
||||
TRACEPOINT_EVENT(tor_circuit, change_purpose,
|
||||
TP_ARGS(const circuit_t *, circ, int, old_purpose, int, new_purpose),
|
||||
TP_FIELDS(
|
||||
@ -247,6 +300,7 @@ TRACEPOINT_EVENT(tor_circuit, change_purpose,
|
||||
)
|
||||
)
|
||||
|
||||
/* Tracepoint emitted when a circuit changes state. */
|
||||
TRACEPOINT_EVENT(tor_circuit, change_state,
|
||||
TP_ARGS(const circuit_t *, circ, int, old_state, int, new_state),
|
||||
TP_FIELDS(
|
||||
@ -261,7 +315,7 @@ TRACEPOINT_EVENT(tor_circuit, change_state,
|
||||
|
||||
#endif /* TOR_TRACE_PROBES_CIRCUIT_H */
|
||||
|
||||
/* Must be include after the probes declaration. */
|
||||
/* Must be included after the probes declaration. */
|
||||
#include <lttng/tracepoint-event.h>
|
||||
|
||||
#endif /* USE_TRACING_INSTRUMENTATION_LTTNG */
|
||||
|
||||
Loading…
Reference in New Issue
Block a user