commit 79d6127a4733cd01cece0c7bdf07d277fe8a08e3 Author: David Goulet dgoulet@torproject.org Date: Tue Feb 11 15:06:50 2020 -0500
trace: Comments and improve doc/HACKING/Tracing.md
Signed-off-by: David Goulet dgoulet@torproject.org --- doc/HACKING/Tracing.md | 130 +++++++++++++++++++++++++------------ src/core/or/trace_probes_circuit.h | 56 +++++++++++++++- 2 files changed, 142 insertions(+), 44 deletions(-)
diff --git a/doc/HACKING/Tracing.md b/doc/HACKING/Tracing.md index e1e97abe6..8cf68321a 100644 --- a/doc/HACKING/Tracing.md +++ b/doc/HACKING/Tracing.md @@ -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/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.
-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. +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. + +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. + +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 ##
- tor_trace_hs_store_desc_as_client(desc, desc_id) +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`.
-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). +If enabled, then the performance depends on the tracer. In the case of +LTTng-UST, the event costs around 110nsec. diff --git a/src/core/or/trace_probes_circuit.h b/src/core/or/trace_probes_circuit.h index d2d70686f..44842efb0 100644 --- a/src/core/or/trace_probes_circuit.h +++ b/src/core/or/trace_probes_circuit.h @@ -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 */