doc/developer/tracing.rst

   1 .. _tracing:
   2
   3 Tracing
   4 =======
   5
   6 FRR has a small but growing number of static tracepoints available for use with
   7 various tracing systems. These tracepoints can assist with debugging,
   8 performance analysis and to help understand program flow. They can also be used
   9 for monitoring.
  10
  11 Developers are encouraged to write new static tracepoints where sensible. They
  12 are not compiled in by default, and even when they are, they have no overhead
  13 unless enabled by a tracer, so it is okay to be liberal with them.
  14
  15
  16 Supported tracers
  17 -----------------
  18
  19 Presently two types of tracepoints are supported:
  20
  21 - `LTTng tracepoints <https://lttng.org/>`_
  22 - `USDT probes <http://dtrace.org/guide/chp-usdt.html>`_
  23
  24 LTTng is a tracing framework for Linux only. It offers extremely low overhead
  25 and very rich tracing capabilities. FRR supports LTTng-UST, which is the
  26 userspace implementation. LTTng tracepoints are very rich in detail. No kernel
  27 modules are needed. Besides only being available for Linux, the primary
  28 downside of LTTng is the need to link to ``lttng-ust``.
  29
  30 USDT probes originate from Solaris, where they were invented for use with
  31 dtrace. They are a kernel feature. At least Linux and FreeBSD support them. No
  32 library is needed; support is compiled in via a system header
  33 (``<sys/sdt.h>``). USDT probes are much slower than LTTng tracepoints and offer
  34 less flexibility in what information can be gleaned from them.
  35
  36 LTTng is capable of tracing USDT probes but has limited support for them.
  37 SystemTap and dtrace both work only with USDT probes.
  38
  39
  40 Usage
  41 -----
  42
  43 To compile with tracepoints, use one of the following configure flags:
  44
  45 .. program:: configure.ac
  46
  47 .. option:: --enable-lttng=yes
  48
  49    Generate LTTng tracepoints
  50
  51 .. option:: --enable-usdt=yes
  52
  53    Generate USDT probes
  54
  55 To trace with LTTng, compile with either one (prefer :option:`--enable-lttng`
  56 run the target in non-forking mode (no ``-d``) and use LTTng as usual (refer to
  57 LTTng user manual). When using USDT probes with LTTng, follow the example in
  58 `this article
  59 <https://lttng.org/blog/2019/10/15/new-dynamic-user-space-tracing-in-lttng/>`_.
  60 To trace with dtrace or SystemTap, compile with `--enable-usdt=yes` and
  61 use your tracer as usual.
  62
  63 To see available USDT probes::
  64
  65    readelf -n /usr/lib/frr/bgpd
  66
  67 Example::
  68
  69    root@host ~> readelf -n /usr/lib/frr/bgpd
  70
  71    Displaying notes found in: .note.ABI-tag
  72      Owner                 Data size    Description
  73      GNU                  0x00000010    NT_GNU_ABI_TAG (ABI version tag)
  74        OS: Linux, ABI: 3.2.0
  75
  76    Displaying notes found in: .note.gnu.build-id
  77      Owner                 Data size    Description
  78      GNU                  0x00000014    NT_GNU_BUILD_ID (unique build ID bitstring)
  79        Build ID: 4f42933a69dcb42a519bc459b2105177c8adf55d
  80
  81    Displaying notes found in: .note.stapsdt
  82      Owner                 Data size    Description
  83      stapsdt              0x00000045    NT_STAPSDT (SystemTap probe descriptors)
  84        Provider: frr_bgp
  85        Name: packet_read
  86        Location: 0x000000000045ee48, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
  87        Arguments: 8@-96(%rbp) 8@-104(%rbp)
  88      stapsdt              0x00000047    NT_STAPSDT (SystemTap probe descriptors)
  89        Provider: frr_bgp
  90        Name: open_process
  91        Location: 0x000000000047c43b, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
  92        Arguments: 8@-224(%rbp) 2@-226(%rbp)
  93      stapsdt              0x00000049    NT_STAPSDT (SystemTap probe descriptors)
  94        Provider: frr_bgp
  95        Name: update_process
  96        Location: 0x000000000047c4bf, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
  97        Arguments: 8@-208(%rbp) 2@-210(%rbp)
  98      stapsdt              0x0000004f    NT_STAPSDT (SystemTap probe descriptors)
  99        Provider: frr_bgp
 100        Name: notification_process
 101        Location: 0x000000000047c557, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
 102        Arguments: 8@-192(%rbp) 2@-194(%rbp)
 103      stapsdt              0x0000004c    NT_STAPSDT (SystemTap probe descriptors)
 104        Provider: frr_bgp
 105        Name: keepalive_process
 106        Location: 0x000000000047c5db, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
 107        Arguments: 8@-176(%rbp) 2@-178(%rbp)
 108      stapsdt              0x0000004a    NT_STAPSDT (SystemTap probe descriptors)
 109        Provider: frr_bgp
 110        Name: refresh_process
 111        Location: 0x000000000047c673, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
 112        Arguments: 8@-160(%rbp) 2@-162(%rbp)
 113      stapsdt              0x0000004d    NT_STAPSDT (SystemTap probe descriptors)
 114        Provider: frr_bgp
 115        Name: capability_process
 116        Location: 0x000000000047c6f7, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
 117        Arguments: 8@-144(%rbp) 2@-146(%rbp)
 118      stapsdt              0x0000006f    NT_STAPSDT (SystemTap probe descriptors)
 119        Provider: frr_bgp
 120        Name: output_filter
 121        Location: 0x000000000048e33a, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
 122        Arguments: 8@-144(%rbp) 8@-152(%rbp) 4@-156(%rbp) 4@-160(%rbp) 8@-168(%rbp)
 123      stapsdt              0x0000007d    NT_STAPSDT (SystemTap probe descriptors)
 124        Provider: frr_bgp
 125        Name: process_update
 126        Location: 0x0000000000491f10, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
 127        Arguments: 8@-800(%rbp) 8@-808(%rbp) 4@-812(%rbp) 4@-816(%rbp) 4@-820(%rbp) 8@-832(%rbp)
 128      stapsdt              0x0000006e    NT_STAPSDT (SystemTap probe descriptors)
 129        Provider: frr_bgp
 130        Name: input_filter
 131        Location: 0x00000000004940ed, Base: 0x00000000005a09d2, Semaphore: 0x0000000000000000
 132        Arguments: 8@-144(%rbp) 8@-152(%rbp) 4@-156(%rbp) 4@-160(%rbp) 8@-168(%rbp)
 133
 134
 135 To see available LTTng probes, run the target, create a session and then::
 136
 137    lttng list --userspace | grep frr
 138
 139 Example::
 140
 141    root@host ~> lttng list --userspace | grep frr
 142    PID: 11157 - Name: /usr/lib/frr/bgpd
 143          frr_libfrr:route_node_get (loglevel: TRACE_DEBUG_LINE (13)) (type: tracepoint)
 144          frr_libfrr:list_sort (loglevel: TRACE_DEBUG_LINE (13)) (type: tracepoint)
 145          frr_libfrr:list_delete_node (loglevel: TRACE_DEBUG_LINE (13)) (type: tracepoint)
 146          frr_libfrr:list_remove (loglevel: TRACE_DEBUG_LINE (13)) (type: tracepoint)
 147          frr_libfrr:list_add (loglevel: TRACE_DEBUG_LINE (13)) (type: tracepoint)
 148          frr_libfrr:memfree (loglevel: TRACE_DEBUG_LINE (13)) (type: tracepoint)
 149          frr_libfrr:memalloc (loglevel: TRACE_DEBUG_LINE (13)) (type: tracepoint)
 150          frr_libfrr:frr_pthread_stop (loglevel: TRACE_DEBUG_LINE (13)) (type: tracepoint)
 151          frr_libfrr:frr_pthread_run (loglevel: TRACE_DEBUG_LINE (13)) (type: tracepoint)
 152          frr_libfrr:thread_call (loglevel: TRACE_INFO (6)) (type: tracepoint)
 153          frr_libfrr:event_cancel_async (loglevel: TRACE_INFO (6)) (type: tracepoint)
 154          frr_libfrr:event_cancel (loglevel: TRACE_INFO (6)) (type: tracepoint)
 155          frr_libfrr:schedule_write (loglevel: TRACE_INFO (6)) (type: tracepoint)
 156          frr_libfrr:schedule_read (loglevel: TRACE_INFO (6)) (type: tracepoint)
 157          frr_libfrr:schedule_event (loglevel: TRACE_INFO (6)) (type: tracepoint)
 158          frr_libfrr:schedule_timer (loglevel: TRACE_INFO (6)) (type: tracepoint)
 159          frr_libfrr:hash_release (loglevel: TRACE_INFO (6)) (type: tracepoint)
 160          frr_libfrr:hash_insert (loglevel: TRACE_INFO (6)) (type: tracepoint)
 161          frr_libfrr:hash_get (loglevel: TRACE_INFO (6)) (type: tracepoint)
 162          frr_bgp:output_filter (loglevel: TRACE_INFO (6)) (type: tracepoint)
 163          frr_bgp:input_filter (loglevel: TRACE_INFO (6)) (type: tracepoint)
 164          frr_bgp:process_update (loglevel: TRACE_INFO (6)) (type: tracepoint)
 165          frr_bgp:packet_read (loglevel: TRACE_INFO (6)) (type: tracepoint)
 166          frr_bgp:refresh_process (loglevel: TRACE_INFO (6)) (type: tracepoint)
 167          frr_bgp:capability_process (loglevel: TRACE_INFO (6)) (type: tracepoint)
 168          frr_bgp:notification_process (loglevel: TRACE_INFO (6)) (type: tracepoint)
 169          frr_bgp:update_process (loglevel: TRACE_INFO (6)) (type: tracepoint)
 170          frr_bgp:keepalive_process (loglevel: TRACE_INFO (6)) (type: tracepoint)
 171          frr_bgp:open_process (loglevel: TRACE_INFO (6)) (type: tracepoint)
 172
 173 When using LTTng, you can also get zlogs as trace events by enabling
 174 the ``lttng_ust_tracelog:*`` event class.
 175
 176 To see available SystemTap USDT probes, run::
 177
 178    stap -L 'process("/usr/lib/frr/bgpd").mark("*")'
 179
 180 Example::
 181
 182    root@host ~> stap -L 'process("/usr/lib/frr/bgpd").mark("*")'
 183    process("/usr/lib/frr/bgpd").mark("capability_process") $arg1:long $arg2:long
 184    process("/usr/lib/frr/bgpd").mark("input_filter") $arg1:long $arg2:long $arg3:long $arg4:long $arg5:long
 185    process("/usr/lib/frr/bgpd").mark("keepalive_process") $arg1:long $arg2:long
 186    process("/usr/lib/frr/bgpd").mark("notification_process") $arg1:long $arg2:long
 187    process("/usr/lib/frr/bgpd").mark("open_process") $arg1:long $arg2:long
 188    process("/usr/lib/frr/bgpd").mark("output_filter") $arg1:long $arg2:long $arg3:long $arg4:long $arg5:long
 189    process("/usr/lib/frr/bgpd").mark("packet_read") $arg1:long $arg2:long
 190    process("/usr/lib/frr/bgpd").mark("process_update") $arg1:long $arg2:long $arg3:long $arg4:long $arg5:long $arg6:long
 191    process("/usr/lib/frr/bgpd").mark("refresh_process") $arg1:long $arg2:long
 192    process("/usr/lib/frr/bgpd").mark("update_process") $arg1:long $arg2:long
 193
 194 When using SystemTap, you can also easily attach to an existing function::
 195
 196    stap -L 'process("/usr/lib/frr/bgpd").function("bgp_update_receive")'
 197
 198 Example::
 199
 200    root@host ~> stap -L 'process("/usr/lib/frr/bgpd").function("bgp_update_receive")'
 201    process("/usr/lib/frr/bgpd").function("bgp_update_receive@bgpd/bgp_packet.c:1531") $peer:struct peer* $size:bgp_size_t $attr:struct attr $restart:_Bool $nlris:struct bgp_nlri[] $__func__:char const[] const
 202
 203 Complete ``bgp.stp`` example using SystemTap to show BGP peer, prefix and aspath
 204 using ``process_update`` USDT::
 205
 206    global pkt_size;
 207    probe begin
 208    {
 209      ansi_clear_screen();
 210      println("Starting...");
 211    }
 212    probe process("/usr/lib/frr/bgpd").function("bgp_update_receive")
 213    {
 214      pkt_size <<< $size;
 215    }
 216    probe process("/usr/lib/frr/bgpd").mark("process_update")
 217    {
 218      aspath = @cast($arg6, "attr")->aspath;
 219      printf("> %s via %s (%s)\n",
 220        user_string($arg2),
 221        user_string(@cast($arg1, "peer")->host),
 222        user_string(@cast(aspath, "aspath")->str));
 223    }
 224    probe end
 225    {
 226      if (@count(pkt_size))
 227        print(@hist_linear(pkt_size, 0, 20, 2));
 228    }
 229
 230 Output::
 231
 232    Starting...
 233    > 192.168.0.0/24 via 192.168.0.1 (65534)
 234    > 192.168.100.1/32 via 192.168.0.1 (65534)
 235    > 172.16.16.1/32 via 192.168.0.1 (65534 65030)
 236    ^Cvalue |-------------------------------------------------- count
 237        0 |                                                   0
 238        2 |                                                   0
 239        4 |@                                                  1
 240        6 |                                                   0
 241        8 |                                                   0
 242          ~
 243      18 |                                                   0
 244      20 |                                                   0
 245      >20 |@@@@@                                              5
 246
 247
 248 Concepts
 249 --------
 250
 251 Tracepoints are statically defined points in code where a developer has
 252 determined that outside observers might gain something from knowing what is
 253 going on at that point. It's like logging but with the ability to dump large
 254 amounts of internal data with much higher performance. LTTng has a good summary
 255 `here <https://lttng.org/docs/#doc-what-is-tracing>`_.
 256
 257 Each tracepoint has a "provider" and name. The provider is basically a
 258 namespace; for example, ``bgpd`` uses the provider name ``frr_bgp``. The name
 259 is arbitrary, but because providers share a global namespace on the user's
 260 system, all providers from FRR should be prefixed by ``frr_``. The tracepoint
 261 name is just the name of the event. Events are globally named by their provider
 262 and name. For example, the event when BGP reads a packet from a peer is
 263 ``frr_bgp:packet_read``.
 264
 265 To do tracing, the tracing tool of choice is told which events to listen to.
 266 For example, to listen to all events from FRR's BGP implementation, you would
 267 enable the events ``frr_bgp:*``. In the same tracing session you could also
 268 choose to record all memory allocations by enabling the ``malloc`` tracepoints
 269 in ``libc`` as well as all kernel skb operations using the various in-kernel
 270 tracepoints. This allows you to build as complete a view as desired of what the
 271 system is doing during the tracing window (subject to what tracepoints are
 272 available).
 273
 274 Of particular use are the tracepoints for FRR's internal event scheduler;
 275 tracing these allows you to see all events executed by all event loops for the
 276 target(s) in question. Here's a couple events selected from a trace of BGP
 277 during startup::
 278
 279    ...
 280
 281    [18:41:35.750131763] (+0.000048901) host frr_libfrr:thread_call: { cpu_id =
 282    1 }, { threadmaster_name = "default", function_name = "zclient_connect",
 283    scheduled_from = "lib/zclient.c", scheduled_on_line = 3877, thread_addr =
 284    0x0, file_descriptor = 0, event_value = 0, argument_ptr = 0xA37F70, timer =
 285    0 }
 286
 287    [18:41:35.750175124] (+0.000020001) host frr_libfrr:thread_call: { cpu_id =
 288    1 }, { threadmaster_name = "default", function_name = "frr_config_read_in",
 289    scheduled_from = "lib/libfrr.c", scheduled_on_line = 934, thread_addr = 0x0,
 290    file_descriptor = 0, event_value = 0, argument_ptr = 0x0, timer = 0 }
 291
 292    [18:41:35.753341264] (+0.000010532) host frr_libfrr:thread_call: { cpu_id =
 293    1 }, { threadmaster_name = "default", function_name = "bgp_event",
 294    scheduled_from = "bgpd/bgpd.c", scheduled_on_line = 142, thread_addr = 0x0,
 295    file_descriptor = 2, event_value = 2, argument_ptr = 0xE4D780, timer = 2 }
 296
 297    [18:41:35.753404186] (+0.000004910) host frr_libfrr:thread_call: { cpu_id =
 298    1 }, { threadmaster_name = "default", function_name = "zclient_read",
 299    scheduled_from = "lib/zclient.c", scheduled_on_line = 3891, thread_addr =
 300    0x0, file_descriptor = 40, event_value = 40, argument_ptr = 0xA37F70, timer
 301    = 40 }
 302
 303    ...
 304
 305
 306 Very useful for getting a time-ordered look into what the process is doing.
 307
 308
 309 Adding Tracepoints
 310 ------------------
 311
 312 Adding new tracepoints is a two step process:
 313
 314 1. Define the tracepoint
 315 2. Use the tracepoint
 316
 317 Tracepoint definitions state the "provider" and name of the tracepoint, along
 318 with any values it will produce, and how to format them. This is done with
 319 macros provided by LTTng. USDT probes do not use definitions and are inserted
 320 at the trace site with a single macro. However, to maintain support for both
 321 platforms, you must define an LTTng tracepoint when adding a new one.
 322 ``frrtrace()`` will expand to the appropriate ``DTRACE_PROBEn`` macro when USDT
 323 is in use.
 324
 325 If you are adding new tracepoints to a daemon that has no tracepoints, that
 326 daemon's ``subdir.am`` must be updated to conditionally link ``lttng-ust``.
 327 Look at ``bgpd/subdir.am`` for an example of how to do this; grep for
 328 ``UST_LIBS``. Create new files named ``<daemon>_trace.[ch]``. Use
 329 ``bgpd/bgp_trace.[h]`` as boilerplate. If you are adding tracepoints to a
 330 daemon that already has them, look for the ``<daemon>_trace.h`` file;
 331 tracepoints are written here.
 332
 333 Refer to the `LTTng developer docs
 334 <https://lttng.org/docs/#doc-c-application>`_ for details on how to define
 335 tracepoints.
 336
 337 To use them, simply add a call to ``frrtrace()`` at the point you'd like the
 338 event to be emitted, like so:
 339
 340 .. code-block:: c
 341
 342    ...
 343
 344    switch (type) {
 345    case BGP_MSG_OPEN:
 346            frrtrace(2, frr_bgp, open_process, peer, size); /* tracepoint */
 347            atomic_fetch_add_explicit(&peer->open_in, 1,
 348                                      memory_order_relaxed);
 349            mprc = bgp_open_receive(peer, size);
 350
 351    ...
 352
 353 After recompiling this tracepoint will now be available, either as a USDT probe
 354 or LTTng tracepoint, depending on your compilation choice.
 355
 356
 357 trace.h
 358 ^^^^^^^
 359
 360 Because FRR supports multiple types of tracepoints, the code for creating them
 361 abstracts away the underlying system being used. This abstraction code is in
 362 ``lib/trace.h``. There are 2 function-like macros that are used for working
 363 with tracepoints.
 364
 365 - ``frrtrace()`` defines tracepoints
 366 - ``frrtrace_enabled()`` checks whether a tracepoint is enabled
 367
 368 There is also ``frrtracelog()``, which is used in zlog core code to make zlog
 369 messages available as trace events to LTTng. This should not be used elsewhere.
 370
 371 There is additional documentation in the header. The key thing to note is that
 372 you should never include ``trace.h`` in source where you plan to put
 373 tracepoints; include the tracepoint definition header instead (e.g.
 374 :file:`bgp_trace.h`).
 375
 376
 377 Limitations
 378 -----------
 379
 380 Tracers do not like ``fork()`` or ``dlopen()``. LTTng has some workarounds for
 381 this involving interceptor libraries using ``LD_PRELOAD``.
 382
 383 If you're running FRR in a typical daemonizing way (``-d`` to the daemons)
 384 you'll need to run the daemons like so:
 385
 386 .. code-block:: shell
 387
 388    LD_PRELOAD=liblttng-ust-fork.so <daemon>
 389
 390
 391 If you're using systemd this you can accomplish this for all daemons by
 392 modifying ``frr.service`` like so:
 393
 394 .. code-block:: diff
 395
 396    --- a/frr.service
 397    +++ b/frr.service
 398    @@ -7,6 +7,7 @@ Before=network.target
 399     OnFailure=heartbeat-failed@%n
 400
 401     [Service]
 402    +Environment="LD_PRELOAD=liblttng-ust-fork.so"
 403     Nice=-5
 404     Type=forking
 405     NotifyAccess=all
 406
 407
 408 USDT tracepoints are relatively high overhead and probably shouldn't be used
 409 for "flight recorder" functionality, i.e. enabling and passively recording all
 410 events for monitoring purposes. It's generally okay to use LTTng like this,
 411 though.