trace: Add a basic event-tracing infrastructure.

This commit adds the src/trace directory containing the basics for our tracing
subsystem. It is not used in the code base. The "src/trace/debug.h" file
contains an example on how we can map our tor trace events to log_debug().

The tracing subsystem can only be enabled by tracing framework at compile
time. This commit introduces the "--enable-tracing-debug" option that will
make all "tor_trace()" function be maped to "log_debug()".

Closes #13802

Signed-off-by: David Goulet <dgoulet@torproject.org>
This commit is contained in:
David Goulet 2017-01-23 14:28:10 -05:00 committed by Nick Mathewson
parent 91dd4a00f7
commit cb8ac1f331
10 changed files with 205 additions and 0 deletions

3
.gitignore vendored
View File

@ -125,6 +125,9 @@ uptime-*.json
/src/Makefile /src/Makefile
/src/Makefile.in /src/Makefile.in
# /src/trace
/src/trace/libor-trace.a
# /src/common/ # /src/common/
/src/common/Makefile /src/common/Makefile
/src/common/Makefile.in /src/common/Makefile.in

5
changes/ticket13802 Normal file
View File

@ -0,0 +1,5 @@
o Minor features (testing):
- Add general tracing instrumentation to Tor. For now, this subsystem is
not being used by any part of the code, it is for future use or external
testing that is not part of the upstream code base. Any tracing
framework needs to be enabled at compile time. Closes #13802.

View File

@ -189,6 +189,16 @@ AC_ARG_ENABLE(seccomp,
AC_ARG_ENABLE(libscrypt, AC_ARG_ENABLE(libscrypt,
AS_HELP_STRING(--disable-libscrypt, [do not attempt to use libscrypt])) AS_HELP_STRING(--disable-libscrypt, [do not attempt to use libscrypt]))
dnl Enable event tracing which are transformed to debug log statement.
AC_ARG_ENABLE(event-tracing-debug,
AS_HELP_STRING(--enable-event-tracing-debug, [build with event tracing to debug log]))
AM_CONDITIONAL([USE_EVENT_TRACING_DEBUG], [test "x$enable_event_tracing_debug" = "xyes"])
if test x$enable_event_tracing_debug = xyes; then
AC_DEFINE([USE_EVENT_TRACING_DEBUG], [1], [Tracing framework to log debug])
AC_DEFINE([TOR_EVENT_TRACING_ENABLED], [1], [Compile the event tracing instrumentation])
fi
dnl check for the correct "ar" when cross-compiling. dnl check for the correct "ar" when cross-compiling.
dnl (AM_PROG_AR was new in automake 1.11.2, which we do not yet require, dnl (AM_PROG_AR was new in automake 1.11.2, which we do not yet require,
dnl so kludge up a replacement for the case where it isn't there yet.) dnl so kludge up a replacement for the case where it isn't there yet.)

90
doc/HACKING/Tracing.md Normal file
View File

@ -0,0 +1,90 @@
# Tracing #
This document describes how the tracing subsystem works in tor so developers
can add events to the code base but also hook them to a tracing framework.
## Basics ###
Tracing is seperated 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.
### 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 in tor has the following standard format:
tor_trace(subsystem, event\_name, args...)
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.
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.
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 ###
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.
## Build System ##
This section describes how it is integrated into the build system of tor.
By default, every tracing events are disabled in tor that is `tor_trace()`
is a NOP.
To enable a tracer, there is a configure option on the form of:
--enable-tracing-<tracer>
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:
--enable-tracing-debug
## Instrument Tor ##
This is pretty easy. Let's say you want to add a trace event in
`src/or/rendcache.c`, you only have to add this include statement:
#include "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:
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:
tor_trace_hs_store_desc_as_client(desc, desc_id)
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).

View File

@ -7,3 +7,4 @@ include src/tools/include.am
include src/win32/include.am include src/win32/include.am
include src/config/include.am include src/config/include.am
include src/test/fuzz/include.am include src/test/fuzz/include.am
include src/trace/include.am

View File

@ -120,6 +120,7 @@ src_or_tor_LDFLAGS = @TOR_LDFLAGS_zlib@ @TOR_LDFLAGS_openssl@ @TOR_LDFLAGS_libev
src_or_tor_LDADD = src/or/libtor.a src/common/libor.a src/common/libor-ctime.a \ src_or_tor_LDADD = src/or/libtor.a src/common/libor.a src/common/libor-ctime.a \
src/common/libor-crypto.a $(LIBKECCAK_TINY) $(LIBDONNA) \ src/common/libor-crypto.a $(LIBKECCAK_TINY) $(LIBDONNA) \
src/common/libor-event.a src/trunnel/libor-trunnel.a \ src/common/libor-event.a src/trunnel/libor-trunnel.a \
src/trace/libor-trace.a \
@TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ @TOR_OPENSSL_LIBS@ \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ @TOR_OPENSSL_LIBS@ \
@TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ @TOR_SYSTEMD_LIBS@ \ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ @TOR_SYSTEMD_LIBS@ \
@TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@

View File

@ -193,6 +193,7 @@ src_test_test_LDADD = src/or/libtor-testing.a \
src/common/libor-ctime-testing.a \ src/common/libor-ctime-testing.a \
src/common/libor-event-testing.a \ src/common/libor-event-testing.a \
src/trunnel/libor-trunnel-testing.a \ src/trunnel/libor-trunnel-testing.a \
src/trace/libor-trace.a \
@TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \
@TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \ @TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \
@TOR_SYSTEMD_LIBS@ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@ @TOR_SYSTEMD_LIBS@ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@
@ -216,6 +217,7 @@ src_test_bench_LDADD = src/or/libtor.a src/common/libor.a \
src/common/libor-ctime.a \ src/common/libor-ctime.a \
src/common/libor-crypto.a $(LIBKECCAK_TINY) $(LIBDONNA) \ src/common/libor-crypto.a $(LIBKECCAK_TINY) $(LIBDONNA) \
src/common/libor-event.a src/trunnel/libor-trunnel.a \ src/common/libor-event.a src/trunnel/libor-trunnel.a \
src/trace/libor-trace.a \
@TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \
@TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \ @TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \
@TOR_SYSTEMD_LIBS@ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@ @TOR_SYSTEMD_LIBS@ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@
@ -227,6 +229,7 @@ src_test_test_workqueue_LDADD = src/or/libtor-testing.a \
src/common/libor-ctime-testing.a \ src/common/libor-ctime-testing.a \
src/common/libor-crypto-testing.a $(LIBKECCAK_TINY) $(LIBDONNA) \ src/common/libor-crypto-testing.a $(LIBKECCAK_TINY) $(LIBDONNA) \
src/common/libor-event-testing.a \ src/common/libor-event-testing.a \
src/trace/libor-trace.a \
@TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \
@TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \ @TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \
@TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@ @TOR_LZMA_LIBS@ @TOR_ZSTD_LIBS@
@ -264,6 +267,7 @@ src_test_test_ntor_cl_LDFLAGS = @TOR_LDFLAGS_zlib@ @TOR_LDFLAGS_openssl@
src_test_test_ntor_cl_LDADD = src/or/libtor.a src/common/libor.a \ src_test_test_ntor_cl_LDADD = src/or/libtor.a src/common/libor.a \
src/common/libor-ctime.a \ src/common/libor-ctime.a \
src/common/libor-crypto.a $(LIBKECCAK_TINY) $(LIBDONNA) \ src/common/libor-crypto.a $(LIBKECCAK_TINY) $(LIBDONNA) \
src/trace/libor-trace.a \
@TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ \ @TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ \
@TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \ @TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@ \
@TOR_LZMA_LIBS@ @TOR_LZMA_LIBS@
@ -285,6 +289,7 @@ noinst_PROGRAMS += src/test/test-bt-cl
src_test_test_bt_cl_SOURCES = src/test/test_bt_cl.c src_test_test_bt_cl_SOURCES = src/test/test_bt_cl.c
src_test_test_bt_cl_LDADD = src/common/libor-testing.a \ src_test_test_bt_cl_LDADD = src/common/libor-testing.a \
src/common/libor-ctime-testing.a \ src/common/libor-ctime-testing.a \
src/trace/libor-trace.a \
@TOR_LIB_MATH@ \ @TOR_LIB_MATH@ \
@TOR_LIB_WS32@ @TOR_LIB_GDI@ @TOR_LIB_WS32@ @TOR_LIB_GDI@
src_test_test_bt_cl_CFLAGS = $(AM_CFLAGS) $(TEST_CFLAGS) src_test_test_bt_cl_CFLAGS = $(AM_CFLAGS) $(TEST_CFLAGS)

25
src/trace/debug.h Normal file
View File

@ -0,0 +1,25 @@
/* Copyright (c) 2017, The Tor Project, Inc. */
/* See LICENSE for licensing information */
#ifndef TOR_TRACE_LOG_DEBUG_H
#define TOR_TRACE_LOG_DEBUG_H
#include "torlog.h"
/* Stringify pre-processor trick. */
#define XSTR(d) STR(d)
#define STR(s) #s
/* Send every event to a debug log level. This is useful to debug new trace
* events without implementing them for a specific event tracing framework.
* Note that the arguments are ignored since at this step we do not know the
* types and amount there is. */
/* Example on how to map a tracepoint to log_debug(). */
#undef tor_trace
#define tor_trace(subsystem, name, args...) \
log_debug(LD_GENERAL, "Trace event \"" XSTR(name) "\" from " \
"\"" XSTR(subsystem) "\" hit. " \
"(line "XSTR(__LINE__) ")")
#endif /* TOR_TRACE_LOG_DEBUG_H */

45
src/trace/events.h Normal file
View File

@ -0,0 +1,45 @@
/* Copyright (c) 2017, The Tor Project, Inc. */
/* See LICENSE for licensing information */
/**
* \file events.h
* \brief Header file for Tor event tracing.
**/
#ifndef TOR_TRACE_EVENTS_H
#define TOR_TRACE_EVENTS_H
/*
* The following defines a generic event tracing function name that has to be
* used to trace events in the code base.
*
* That generic function is then defined by a event tracing framework. For
* instance, the "log debug" framework sends all trace events to log_debug()
* which is defined in src/trace/debug.h which can only be enabled at compile
* time (--enable-event-tracing-debug).
*
* By default, every trace events in the code base are replaced by a NOP. See
* doc/HACKING/Tracing.md for more information on how to use event tracing or
* add events.
*/
#ifdef TOR_EVENT_TRACING_ENABLED
/* Map every trace event to a per subsystem macro. */
#define tor_trace(subsystem, name, ...) \
tor_trace_##subsystem(name, __VA_ARGS__)
/* Enable event tracing for the debug framework where all trace events are
* mapped to a log_debug(). */
#ifdef USE_EVENT_TRACING_DEBUG
#include "trace/debug.h"
#endif
#else /* TOR_EVENT_TRACING_ENABLED */
/* Reaching this point, we NOP every event declaration because event tracing
* is not been enabled at compile time. */
#define tor_trace(subsystem, name, args...)
#endif /* TOR_EVENT_TRACING_ENABLED */
#endif /* TOR_TRACE_EVENTS_H */

20
src/trace/include.am Normal file
View File

@ -0,0 +1,20 @@
# Include the src/ so we can use the trace/events.h statement when including
# any file in that directory.
AM_CPPFLAGS += -I$(srcdir)/src
noinst_LIBRARIES += \
src/trace/libor-trace.a
LIBOR_TRACE_A_SOURCES =
TRACEHEADERS = \
src/trace/events.h
if USE_EVENT_TRACING_DEBUG
TRACEHEADERS += \
src/trace/debug.h
endif
# Library source files.
src_trace_libor_trace_a_SOURCES = $(LIBOR_TRACE_A_SOURCES)
noinst_HEADERS+= $(TRACEHEADERS)