third_party/pigweed/repo/pw_trace/docs.rst

   1 .. _module-pw_trace:
   2
   3 ========
   4 pw_trace
   5 ========
   6 Pigweed's tracing module provides facilities for applications to trace
   7 information about the execution of their application. The module is split into
   8 two components:
   9
  10 1. The facade (this module) which is only a macro interface layer
  11 2. The backend, provided elsewhere, implements the low level tracing.
  12
  13 ------
  14 Status
  15 ------
  16 This module is currently in development, and is therefore still undergoing
  17 significant changes.
  18
  19 Future work will add:
  20
  21 1. A Python library to generate trace files which can be viewed. (pwbug/205)
  22 2. Add more examples with sample output. (pwbug/207)
  23 3. Implement a trace backend module. (pwbug/260)
  24
  25 --------
  26 Overview
  27 --------
  28 Traces provide a useful view which shows the flow of events through a system,
  29 and can greatly assist in understanding complex software problems. These traces
  30 can either show what tasks are running at any given time, or use added code
  31 (similar to logging), to help annotate specific interesting flows.
  32
  33 Fundamentally, tracing is similar to logging in that it provides the developer
  34 with a view into what the system was doing at a particular time. The fundamental
  35 difference between logs and tracing is that logs present information as ad-hoc
  36 human-readable strings and are better suited to providing the current state of
  37 the system. Instead, traces capture sequences of events with precise timestamps,
  38 and are therefore useful at understanding the flow of events in the system over
  39 time.
  40
  41 Compatibility
  42 -------------
  43 Most of the facade is compatible with C and C++, the only exception to this is
  44 the Scope and Function tracing macros which are convenience wrappers only
  45 available in C++.
  46
  47 Dependencies
  48 -------------
  49 ``pw_preprocessor``
  50
  51 Example
  52 -------
  53
  54 .. code-block:: cpp
  55
  56   #define PW_TRACE_MODULE_NAME "Input"
  57   #include "pw_trace/trace.h"
  58
  59   void SendButton() {
  60     PW_TRACE_FUNCTION()
  61     // do something
  62   }
  63
  64   void InputLoop() {
  65     while(1) {
  66       auto event = WaitNewInputEvent()
  67       TRACE_SCOPE("Handle Event");  // measure until loop finished
  68       if (event == kNewButton){
  69         SendButton();
  70         PW_TRACE_END("button");  // Trace event was started in ButtonIsr
  71       } else {
  72         PW_TRACE_INSTANT("Unknown event");
  73       }
  74     }
  75   }
  76
  77   void ButtonIsr() {
  78     PW_TRACE_START("button");
  79     SendNewInputEvent(kNewButton);
  80   }
  81
  82
  83 ------------
  84 Trace macros
  85 ------------
  86
  87 The ``pw_trace`` public API provides three basic trace events:
  88
  89 - ``PW_TRACE_INSTANT`` - This is used to trace an instant event, which has no
  90   duration.
  91 - ``PW_TRACE_START`` & ``PW_TRACE_END`` - Trace 'start' and 'end' events are
  92   paired together to measure the duration of an event.
  93
  94 These trace event macros all have the same arguments:
  95
  96 - *label* - Each of these trace events must have a label, which is a string
  97   describing the event. In addition to the required label, each of these traces
  98   can optionally provide a group label and trace id.
  99 - *group_label* - The *optional* group label is used if many traces are all
 100   measuring the same thing and should be grouped together. This information will
 101   be used when visualizing the trace to ensure the information appears together.
 102 - *trace_id* - The *optional* trace id is similar to the group_id, but instead
 103   groups events using a runtime value. This can be used if multiple trace flow
 104   might happen at the same time and need to be grouped together.
 105   For example, this could be used to trace data packets flowing through the
 106   system; when a new sample might arrive before the previous packet is finished
 107   processing. This would result in two start events occurring before the end
 108   event. By providing a trace id with a different value for each packet, these
 109   can be separated when decoding.
 110
 111 .. tip::
 112
 113   All of these arguments must be the same for a *start* and *end* pair.
 114
 115 This results in 9 different trace calls:
 116
 117 .. cpp:function:: PW_TRACE_INSTANT(label)
 118 .. cpp:function:: PW_TRACE_INSTANT(label, group_label)
 119 .. cpp:function:: PW_TRACE_INSTANT(label, group_label, trace_id)
 120 .. cpp:function:: PW_TRACE_START(label)
 121 .. cpp:function:: PW_TRACE_START(label, group_label)
 122 .. cpp:function:: PW_TRACE_START(label, group_label, trace_id)
 123 .. cpp:function:: PW_TRACE_END(label)
 124 .. cpp:function:: PW_TRACE_END(label, group_label)
 125 .. cpp:function:: PW_TRACE_END(label, group_label, trace_id)
 126
 127 Modules
 128 -------
 129 In addition to these arguments, traces can be grouped into modules similar to
 130 logging. This is done by redefining the ``PW_TRACE_MODULE_NAME``.
 131
 132 Flags
 133 -----
 134 Each trace event also has a flags field which can be used to provide additional
 135 compile time trace information. Each trace macro has a matching macro which
 136 allows specifying the flag:
 137
 138 .. cpp:function:: PW_TRACE_INSTANT_FLAG(flag, label)
 139 .. cpp:function:: PW_TRACE_INSTANT_FLAG(flag, label, group_label)
 140 .. cpp:function:: PW_TRACE_INSTANT_FLAG(flag, label, group_label, trace_id)
 141 .. cpp:function:: PW_TRACE_START_FLAG(flag, label)
 142 .. cpp:function:: PW_TRACE_START_FLAG(flag, label, group_label)
 143 .. cpp:function:: PW_TRACE_START_FLAG(flag, label, group_label, trace_id)
 144 .. cpp:function:: PW_TRACE_END_FLAG(flag, label)
 145 .. cpp:function:: PW_TRACE_END_FLAG(flag, label, group_label)
 146 .. cpp:function:: PW_TRACE_END_FLAG(flag, label, group_label, trace_id)
 147
 148 When not specified the flag uses the value of the macro ``PW_TRACE_FLAGS``.
 149
 150 Data
 151 ----
 152 Each macro also has a variant which allows appending additional data:
 153
 154 .. cpp:function:: PW_TRACE_INSTANT_DATA(label, data_format_string, data, size)
 155 .. cpp:function:: PW_TRACE_INSTANT_DATA(\
 156    label, group_label, data_format_string, data, size)
 157 .. cpp:function:: PW_TRACE_INSTANT_DATA(\
 158    label, group_label, trace_id, data_format_string, data, size)
 159 .. cpp:function:: PW_TRACE_START_DATA(label, data_format_string, data, size)
 160 .. cpp:function:: PW_TRACE_START_DATA(\
 161    label, group_label, data_format_string, data, size)
 162 .. cpp:function:: PW_TRACE_START_DATA(\
 163    label, group_label, trace_id, data_format_string, data, size)
 164 .. cpp:function:: PW_TRACE_END_DATA(label, data_format_string, data, size)
 165 .. cpp:function:: PW_TRACE_END_DATA(\
 166    label, group_label, data_format_string, data, size)
 167 .. cpp:function:: PW_TRACE_END_DATA(\
 168    label, group_label, trace_id, data_format_string, data, size)
 169
 170 These macros require 3 additional arguments:
 171
 172 - *data_format_string* - A string which is used by the decoder to identify the
 173   data. This could for example either be printf style tokens, python struct
 174   packed fmt string or a custom label recognized by the decoder.
 175 - *data* - A pointer to a buffer of arbitrary caller-provided data (void*).
 176 - *size* - The size of the data (size_t).
 177
 178 Currently the included python tool supports a few different options for
 179 *data_format_string*:
 180
 181 - *@pw_arg_label* - Uses the string in the data as the trace event label.
 182 - *@pw_arg_group* - Uses the string in the data as the trace event group.
 183 - *@pw_arg_counter* - Uses the data as a little endian integer value, and
 184   visualizes it as a counter value in the trace (on a graph).
 185 - *@pw_py_struct_fmt:* - Interprets the string after the ":" as a python struct
 186   format string, and uses that format string to unpack the data elements. This
 187   can be used to either provide a single value type, or provide multiple
 188   different values with a variety of types. Options for format string types can
 189   be found here: https://docs.python.org/3/library/struct.html#format-characters
 190
 191 .. tip::
 192
 193   It is ok for only one event of a start/end pair to contain data, as long the
 194   *label*, *group_label*, and *trace_id*, are all the same.
 195
 196 C++ Only Traces
 197 ---------------
 198 Scope API measures durations until the object loses scope. This can for
 199 example, provide a convenient method of tracing functions or loops.
 200
 201 .. cpp:function:: PW_TRACE_SCOPE(label)
 202 .. cpp:function:: PW_TRACE_SCOPE(label, group_label)
 203
 204 Function API measures durations until the function returns. This is the only
 205 macro which does not require a *label*, and instead uses the function name as the
 206 label. It still can optionally be provided a *group_id*.
 207
 208 .. cpp:function:: PW_TRACE_FUNCTION()
 209 .. cpp:function:: PW_TRACE_FUNCTION(group_label)
 210
 211 -----------
 212 Backend API
 213 -----------
 214 Each of the trace event macros get sent to one of two macros which are
 215 implemented by the backend:
 216
 217 .. cpp:function:: PW_TRACE(event_type, flags, label, group_label, trace_id)
 218 .. cpp:function:: PW_TRACE_DATA(event_type, flags, label, group_label, \
 219    trace_id, data_format_string, data, size)
 220
 221 The ``event_type`` value will be whatever the backend defined for that specific
 222 trace type using the macros defined below.
 223
 224 The backend can optionally not define ``PW_TRACE_DATA`` to have those traces
 225 disabled.
 226
 227 Trace types
 228 -----------
 229 Although there are only 3 basic trace types, each has 3 variants:
 230
 231 - Label only
 232 - Label and group
 233 - Label, group, and trace_id
 234
 235 This combination creates 9 different trace event types:
 236
 237 - *PW_TRACE_TYPE_INSTANT*: Instant trace, with only a label.
 238 - *PW_TRACE_TYPE_DURATION_START*: Start trace, with only a label.
 239 - *PW_TRACE_TYPE_DURATION_END*: End trace, with only a label.
 240 - *PW_TRACE_TYPE_INSTANT_GROUP*: Instant trace, with a label and a group.
 241 - *PW_TRACE_TYPE_DURATION_GROUP_START*: Start trace, with a label and a group.
 242 - *PW_TRACE_TYPE_DURATION_GROUP_END*: End trace, with a label and a group.
 243 - *PW_TRACE_TYPE_ASYNC_INSTANT*: Instant trace, with label, group, and trace_id
 244 - *PW_TRACE_TYPE_ASYNC_START*: Start trace, with label, group, and trace_id.
 245 - *PW_TRACE_TYPE_ASYNC_END*: End trace, with label, group, and trace_id.
 246
 247 The backend must define these macros to have them enabled. If any are left
 248 undefined, any traces of that type are removed.
 249
 250 Defaults
 251 --------
 252 The backend can use these macros to change what the default value is if not
 253 provided.
 254
 255 - *PW_TRACE_FLAGS_DEFAULT*: Default value if no flags are provided.
 256 - *PW_TRACE_TRACE_ID_DEFAULT*: Default value if no trace_id provided.
 257 - *PW_TRACE_GROUP_LABEL_DEFAULT*: Default value if no group_label provided.
 258
 259 ----------
 260 Sample App
 261 ----------
 262 A sample application is provided in the examples folder. This code attempts to
 263 provide examples of the multiple ways tracing can be used. Furthermore,
 264 trace backends can include the sample app in their own examples to show how to
 265 use other features.
 266
 267 The sample app contains 3 "fake" tasks, which are each in their own
 268 `PW_TRACE_MODULE`.
 269
 270 - *Input*: Simulating a driver, which gets data periodically, and sends to
 271   *Processing* task.
 272 - *Processing*: Has a work queue, which handles processing the jobs.
 273 - *Kernel*: A simple work loop which demonstrates a possible integration of
 274   tracing with a RTOS/Kernel.
 275
 276 Jobs are intentionally made to have multiple stages of processing (simulated by
 277 being re-added to the work-queue). This results in multiple jobs being handled
 278 at the same time, the trace_id is used to separate these traces.
 279
 280 ----------------------
 281 Python Trace Generator
 282 ----------------------
 283 The Python tool is still in early developments, but currently it supports
 284 generating a list of json lines from a list of trace events.
 285
 286 To view the trace, these lines can be saved to a file and loaded into
 287 chrome://tracing.
 288
 289 Future work will look to add:
 290
 291 - Config options to customize output.
 292 - A method of providing custom data formatters.
 293 - Perfetto support.