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