1.. _module-pw_trace: 2 3======== 4pw_trace 5======== 6Pigweed's tracing module provides facilities for applications to trace 7information about the execution of their application. The module is split into 8two components: 9 101. The facade (this module) which is only a macro interface layer 112. The backend, provided elsewhere, implements the low level tracing. 12 13------ 14Status 15------ 16This module is currently in development, and is therefore still undergoing 17significant changes. 18 19Future work will add: 20 211. A Python library to generate trace files which can be viewed. (pwbug/205) 222. Add more examples with sample output. (pwbug/207) 233. Implement a trace backend module. (pwbug/260) 24 25-------- 26Overview 27-------- 28Traces provide a useful view which shows the flow of events through a system, 29and can greatly assist in understanding complex software problems. These traces 30can 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 33Fundamentally, tracing is similar to logging in that it provides the developer 34with a view into what the system was doing at a particular time. The fundamental 35difference between logs and tracing is that logs present information as ad-hoc 36human-readable strings and are better suited to providing the current state of 37the system. Instead, traces capture sequences of events with precise timestamps, 38and are therefore useful at understanding the flow of events in the system over 39time. 40 41The default backend for pw_trace is pw_trace_null, which disables tracing. 42 43Compatibility 44------------- 45Most of the facade is compatible with C and C++, the only exception to this is 46the Scope and Function tracing macros which are convenience wrappers only 47available in C++. 48 49pw_trace:null 50------------- 51``pw_trace_null`` is a ``pw_trace backend`` that ignores all ``pw_trace`` 52statements. The backend implements ``pw_trace`` with empty inline functions. 53Using empty functions ensure that the arguments are evaluated and their types 54are correct. Since the functions are inline in the header, the compiler will 55optimize out the function call. 56 57This backend can be used to completely disable ``pw_trace``. 58 59Dependencies 60------------- 61``pw_preprocessor`` 62 63Example 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------------ 96Trace macros 97------------ 98 99The ``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 106These 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 127This 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 139Modules 140------- 141In addition to these arguments, traces can be grouped into modules similar to 142logging. This is done by redefining the ``PW_TRACE_MODULE_NAME``. 143 144Flags 145----- 146Each trace event also has a flags field which can be used to provide additional 147compile time trace information. Each trace macro has a matching macro which 148allows 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 160When not specified the flag uses the value of the macro ``PW_TRACE_FLAGS``. 161 162Data 163---- 164Each 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 182These 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 190Currently 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 . The data is always assumed to be packed with little-endian ordering if not 203 indicated otherwise:: 204 205 // Example 206 data_format_string = "@pw_py_struct_fmt:ll" 207 data = 0x1400000014000000 208 args = {data_0: 20, data_1:20} 209- *@pw_py_map_fmt:* - Interprets the string after the ":" as a dictionary 210 relating the data field name to the python struct format string. Once 211 collected, the format strings are concatenated and used to unpack the data 212 elements as above. The data is always assumed to be packed with little-endian 213 ordering if not indicated otherwise. To specify a different ordering, 214 construct the format string as ``@pw_py_map_fmt:[@=<>!]{k:v,...}``:: 215 216 // Example 217 data_format_string = "@pw_py_map_fmt:{Field: l, Field2: l }" 218 data = 0x1400000014000000 219 args = {Field: 20, Field2:20} 220 221.. tip:: 222 223 It is ok for only one event of a start/end pair to contain data, as long the 224 *label*, *group_label*, and *trace_id*, are all the same. 225 226C++ Only Traces 227--------------- 228Scope API measures durations until the object loses scope. This can for 229example, provide a convenient method of tracing functions or loops. 230 231.. cpp:function:: PW_TRACE_SCOPE(label) 232.. cpp:function:: PW_TRACE_SCOPE(label, group_label) 233 234Function API measures durations until the function returns. This is the only 235macro which does not require a *label*, and instead uses the function name as the 236label. It still can optionally be provided a *group_id*. 237 238.. cpp:function:: PW_TRACE_FUNCTION() 239.. cpp:function:: PW_TRACE_FUNCTION(group_label) 240 241Compile time enabling/disabling 242------------------------------- 243Traces in a file can be enabled/disabled at compile time by defining through 244the ``PW_TRACE_ENABLE`` macro. A value of 0 causes traces to be disabled. 245A non-zero value will enable traces. While tracing defaults to enabled, 246it is best practice to define ``PW_TRACE_ENABLE`` explicitly in files that 247use tracing as the default may change in the future. 248 249A good pattern is to have a module level configuration parameter for enabling 250tracing and define ``PW_TRACE_ENABLE`` in terms of that at the top of each 251of the module's files: 252 253 254.. code-block:: cpp 255 256 // Enable tracing based on pw_example module config parameter. 257 #define PW_TRACE_ENABLE PW_EXAMPLE_TRACE_ENABLE 258 259 260Additionally specific trace points (or sets of points) can be enabled/disabled 261using the following pattern: 262 263.. code-block:: cpp 264 265 // Assuming tracing is disabled at the top of the file. 266 267 // Enable specific trace. 268 #undef PW_TRACE_ENABLE 269 #define PW_TRACE_ENABLE 1 270 PW_TRACE_INSTANT("important trace"); 271 272 // Set traces back to disabled. PW_TRACE_ENABLE can not be left 273 // undefined. 274 #undef PW_TRACE_ENABLE 275 #define PW_TRACE_ENABLE 0 276 277----------- 278Backend API 279----------- 280Each of the trace event macros get sent to one of two macros which are 281implemented by the backend: 282 283.. cpp:function:: PW_TRACE(event_type, flags, label, group_label, trace_id) 284.. cpp:function:: PW_TRACE_DATA(event_type, flags, label, group_label, \ 285 trace_id, data_format_string, data, size) 286 287The ``event_type`` value will be whatever the backend defined for that specific 288trace type using the macros defined below. 289 290The backend can optionally not define ``PW_TRACE_DATA`` to have those traces 291disabled. 292 293Trace types 294----------- 295Although there are only 3 basic trace types, each has 3 variants: 296 297- Label only 298- Label and group 299- Label, group, and trace_id 300 301This combination creates 9 different trace event types: 302 303- *PW_TRACE_TYPE_INSTANT*: Instant trace, with only a label. 304- *PW_TRACE_TYPE_DURATION_START*: Start trace, with only a label. 305- *PW_TRACE_TYPE_DURATION_END*: End trace, with only a label. 306- *PW_TRACE_TYPE_INSTANT_GROUP*: Instant trace, with a label and a group. 307- *PW_TRACE_TYPE_DURATION_GROUP_START*: Start trace, with a label and a group. 308- *PW_TRACE_TYPE_DURATION_GROUP_END*: End trace, with a label and a group. 309- *PW_TRACE_TYPE_ASYNC_INSTANT*: Instant trace, with label, group, and trace_id 310- *PW_TRACE_TYPE_ASYNC_START*: Start trace, with label, group, and trace_id. 311- *PW_TRACE_TYPE_ASYNC_END*: End trace, with label, group, and trace_id. 312 313The backend must define these macros to have them enabled. If any are left 314undefined, any traces of that type are removed. 315 316Defaults 317-------- 318The backend can use these macros to change what the default value is if not 319provided. 320 321- *PW_TRACE_FLAGS_DEFAULT*: Default value if no flags are provided. 322- *PW_TRACE_TRACE_ID_DEFAULT*: Default value if no trace_id provided. 323- *PW_TRACE_GROUP_LABEL_DEFAULT*: Default value if no group_label provided. 324 325---------- 326Sample App 327---------- 328A sample application is provided in the examples folder. This code attempts to 329provide examples of the multiple ways tracing can be used. Furthermore, 330trace backends can include the sample app in their own examples to show how to 331use other features. 332 333The sample app contains 3 "fake" tasks, which are each in their own 334`PW_TRACE_MODULE`. 335 336- *Input*: Simulating a driver, which gets data periodically, and sends to 337 *Processing* task. 338- *Processing*: Has a work queue, which handles processing the jobs. 339- *Kernel*: A simple work loop which demonstrates a possible integration of 340 tracing with a RTOS/Kernel. 341 342Jobs are intentionally made to have multiple stages of processing (simulated by 343being re-added to the work-queue). This results in multiple jobs being handled 344at the same time, the trace_id is used to separate these traces. 345 346---------------------- 347Python Trace Generator 348---------------------- 349The Python tool is still in early development, but currently it supports 350generating a list of json lines from a list of trace events. 351 352To view the trace, these lines can be saved to a file and loaded into 353chrome://tracing. 354 355Future work will look to add: 356 357- Config options to customize output. 358- A method of providing custom data formatters. 359- Perfetto support. 360 361 362.. toctree:: 363 :hidden: 364 :maxdepth: 1 365 366 Backends <backends> 367