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