| .. _chapter-pw-trace: |
| |
| .. default-domain:: cpp |
| |
| .. highlight:: cpp |
| |
| ======== |
| pw_trace |
| ======== |
| Pigweed's tracing module provides facilities for applications to trace |
| information about the execution of their application. The module is split into |
| two components: |
| |
| 1. The facade (this module) which is only a macro interface layer |
| 2. The backend, provided elsewhere, implements the low level tracing. |
| |
| ------ |
| Status |
| ------ |
| This module is currently in development, and is therefore still undergoing |
| significant changes. |
| |
| Future work will add: |
| |
| 1. A Python library to generate trace files which can be viewed. (pwbug/205) |
| 2. Add more examples with sample output. (pwbug/207) |
| 3. Implement a trace backend module. (pwbug/260) |
| |
| -------- |
| Overview |
| -------- |
| Traces provide a useful view which shows the flow of events through a system, |
| and can greatly assist in understanding complex software problems. These traces |
| can either show what tasks are running at any given time, or use added code |
| (similar to logging), to help annotate specific interesting flows. |
| |
| Fundamentally, tracing is similar to logging in that it provides the developer |
| with a view into what the system was doing at a particular time. The fundamental |
| difference between logs and tracing is that logs present information as ad-hoc |
| human-readable strings and are better suited to providing the current state of |
| the system. Instead, traces capture sequences of events with precise timestamps, |
| and are therefore useful at understanding the flow of events in the system over |
| time. |
| |
| Compatibility |
| ------------- |
| Most of the facade is compatible with C and C++, the only exception to this is |
| the Scope and Function tracing macros which are convenience wrappers only |
| available in C++. |
| |
| Dependencies |
| ------------- |
| ``pw_preprocessor`` |
| |
| Example |
| ------- |
| |
| .. code-block:: cpp |
| |
| #define PW_TRACE_MODULE_NAME "Input" |
| #include "pw_trace/trace.h" |
| |
| void SendButton() { |
| PW_TRACE_FUNCTION() |
| // do something |
| } |
| |
| void InputLoop() { |
| while(1) { |
| auto event = WaitNewInputEvent() |
| TRACE_SCOPE("Handle Event"); // measure until loop finished |
| if (event == kNewButton){ |
| SendButton(); |
| PW_TRACE_END("button"); // Trace event was started in ButtonIsr |
| } else { |
| PW_TRACE_INSTANT("Unknown event"); |
| } |
| } |
| } |
| |
| void ButtonIsr() { |
| PW_TRACE_START("button"); |
| SendNewInputEvent(kNewButton); |
| } |
| |
| |
| ------------ |
| Trace macros |
| ------------ |
| |
| The ``pw_trace`` public API provides three basic trace events: |
| |
| - ``PW_TRACE_INSTANT`` - This is used to trace an instant event, which has no |
| duration. |
| - ``PW_TRACE_START`` & ``PW_TRACE_END`` - Trace 'start' and 'end' events are |
| paired together to measure the duration of an event. |
| |
| These trace event macros all have the same arguments: |
| |
| - *label* - Each of these trace events must have a label, which is a string |
| describing the event. In addition to the required label, each of these traces |
| can optionally provide a group label and trace id. |
| - *group_label* - The *optional* group label is used if many traces are all |
| measuring the same thing and should be grouped together. This information will |
| be used when visualizing the trace to ensure the information appears together. |
| - *trace_id* - The *optional* trace id is similar to the group_id, but instead |
| groups events using a runtime value. This can be used if multiple trace flow |
| might happen at the same time and need to be grouped together. |
| For example, this could be used to trace data packets flowing through the |
| system; when a new sample might arrive before the previous packet is finished |
| processing. This would result in two start events occurring before the end |
| event. By providing a trace id with a different value for each packet, these |
| can be separated when decoding. |
| |
| .. tip:: |
| |
| All of these arguments must be the same for a *start* and *end* pair. |
| |
| This results in 9 different trace calls: |
| |
| .. cpp:function:: PW_TRACE_INSTANT(label) |
| .. cpp:function:: PW_TRACE_INSTANT(label, group_label) |
| .. cpp:function:: PW_TRACE_INSTANT(label, group_label, trace_id) |
| .. cpp:function:: PW_TRACE_START(label) |
| .. cpp:function:: PW_TRACE_START(label, group_label) |
| .. cpp:function:: PW_TRACE_START(label, group_label, trace_id) |
| .. cpp:function:: PW_TRACE_END(label) |
| .. cpp:function:: PW_TRACE_END(label, group_label) |
| .. cpp:function:: PW_TRACE_END(label, group_label, trace_id) |
| |
| Modules |
| ------- |
| In addition to these arguments, traces can be grouped into modules similar to |
| logging. This is done by redefining the ``PW_TRACE_MODULE_NAME``. |
| |
| Flags |
| ----- |
| Each trace event also has a flags field which can be used to provide additional |
| compile time trace information. Each trace macro has a matching macro which |
| allows specifying the flag: |
| |
| .. cpp:function:: PW_TRACE_INSTANT_FLAG(flag, label) |
| .. cpp:function:: PW_TRACE_INSTANT_FLAG(flag, label, group_label) |
| .. cpp:function:: PW_TRACE_INSTANT_FLAG(flag, label, group_label, trace_id) |
| .. cpp:function:: PW_TRACE_START_FLAG(flag, label) |
| .. cpp:function:: PW_TRACE_START_FLAG(flag, label, group_label) |
| .. cpp:function:: PW_TRACE_START_FLAG(flag, label, group_label, trace_id) |
| .. cpp:function:: PW_TRACE_END_FLAG(flag, label) |
| .. cpp:function:: PW_TRACE_END_FLAG(flag, label, group_label) |
| .. cpp:function:: PW_TRACE_END_FLAG(flag, label, group_label, trace_id) |
| |
| When not specified the flag uses the value of the macro ``PW_TRACE_FLAGS``. |
| |
| Data |
| ---- |
| Each macro also has a variant which allows appending additional data: |
| |
| .. cpp:function:: PW_TRACE_INSTANT_DATA(label, data_format_string, data, size) |
| .. cpp:function:: PW_TRACE_INSTANT_DATA(\ |
| label, group_label, data_format_string, data, size) |
| .. cpp:function:: PW_TRACE_INSTANT_DATA(\ |
| label, group_label, trace_id, data_format_string, data, size) |
| .. cpp:function:: PW_TRACE_START_DATA(label, data_format_string, data, size) |
| .. cpp:function:: PW_TRACE_START_DATA(\ |
| label, group_label, data_format_string, data, size) |
| .. cpp:function:: PW_TRACE_START_DATA(\ |
| label, group_label, trace_id, data_format_string, data, size) |
| .. cpp:function:: PW_TRACE_END_DATA(label, data_format_string, data, size) |
| .. cpp:function:: PW_TRACE_END_DATA(\ |
| label, group_label, data_format_string, data, size) |
| .. cpp:function:: PW_TRACE_END_DATA(\ |
| label, group_label, trace_id, data_format_string, data, size) |
| |
| These macros require 3 additional arguments: |
| |
| - *data_format_string* - A string which is used by the decoder to identify the |
| data. This could for example either be printf style tokens, python struct |
| packed fmt string or a custom label recognized by the decoder. |
| - *data* - A pointer to a buffer of arbitrary caller-provided data (void*). |
| - *size* - The size of the data (size_t). |
| |
| Currently the included python tool supports a few different options for |
| *data_format_string*: |
| |
| - *@pw_arg_label* - Uses the string in the data as the trace event label. |
| - *@pw_arg_group* - Uses the string in the data as the trace event group. |
| - *@pw_arg_counter* - Uses the data as a little endian integer value, and |
| visualizes it as a counter value in the trace (on a graph). |
| - *@pw_py_struct_fmt:* - Interprets the string after the ":" as a python struct |
| format string, and uses that format string to unpack the data elements. This |
| can be used to either provide a single value type, or provide multiple |
| different values with a variety of types. Options for format string types can |
| be found here: https://docs.python.org/3/library/struct.html#format-characters |
| |
| .. tip:: |
| |
| It is ok for only one event of a start/end pair to contain data, as long the |
| *label*, *group_label*, and *trace_id*, are all the same. |
| |
| C++ Only Traces |
| --------------- |
| Scope API measures durations until the object loses scope. This can for |
| example, provide a convenient method of tracing functions or loops. |
| |
| .. cpp:function:: PW_TRACE_SCOPE(label) |
| .. cpp:function:: PW_TRACE_SCOPE(label, group_label) |
| |
| Function API measures durations until the function returns. This is the only |
| macro which does not require a *label*, and instead uses the function name as the |
| label. It still can optionally be provided a *group_id*. |
| |
| .. cpp:function:: PW_TRACE_FUNCTION() |
| .. cpp:function:: PW_TRACE_FUNCTION(group_label) |
| |
| ----------- |
| Backend API |
| ----------- |
| Each of the trace event macros get sent to one of two macros which are |
| implemented by the backend: |
| |
| .. cpp:function:: PW_TRACE(event_type, flags, label, group_label, trace_id) |
| .. cpp:function:: PW_TRACE_DATA(event_type, flags, label, group_label, \ |
| trace_id, data_format_string, data, size) |
| |
| The ``event_type`` value will be whatever the backend defined for that specific |
| trace type using the macros defined below. |
| |
| The backend can optionally not define ``PW_TRACE_DATA`` to have those traces |
| disabled. |
| |
| Trace types |
| ----------- |
| Although there are only 3 basic trace types, each has 3 variants: |
| |
| - Label only |
| - Label and group |
| - Label, group, and trace_id |
| |
| This combination creates 9 different trace event types: |
| |
| - *PW_TRACE_TYPE_INSTANT*: Instant trace, with only a label. |
| - *PW_TRACE_TYPE_DURATION_START*: Start trace, with only a label. |
| - *PW_TRACE_TYPE_DURATION_END*: End trace, with only a label. |
| - *PW_TRACE_TYPE_INSTANT_GROUP*: Instant trace, with a label and a group. |
| - *PW_TRACE_TYPE_DURATION_GROUP_START*: Start trace, with a label and a group. |
| - *PW_TRACE_TYPE_DURATION_GROUP_END*: End trace, with a label and a group. |
| - *PW_TRACE_TYPE_ASYNC_INSTANT*: Instant trace, with label, group, and trace_id |
| - *PW_TRACE_TYPE_ASYNC_START*: Start trace, with label, group, and trace_id. |
| - *PW_TRACE_TYPE_ASYNC_END*: End trace, with label, group, and trace_id. |
| |
| The backend must define these macros to have them enabled. If any are left |
| undefined, any traces of that type are removed. |
| |
| Defaults |
| -------- |
| The backend can use these macros to change what the default value is if not |
| provided. |
| |
| - *PW_TRACE_FLAGS_DEFAULT*: Default value if no flags are provided. |
| - *PW_TRACE_TRACE_ID_DEFAULT*: Default value if no trace_id provided. |
| - *PW_TRACE_GROUP_LABEL_DEFAULT*: Default value if no group_label provided. |
| |
| ---------- |
| Sample App |
| ---------- |
| A sample application is provided in the examples folder. This code attempts to |
| provide examples of the multiple ways tracing can be used. Furthermore, |
| trace backends can include the sample app in their own examples to show how to |
| use other features. |
| |
| The sample app contains 3 "fake" tasks, which are each in their own |
| `PW_TRACE_MODULE`. |
| |
| - *Input*: Simulating a driver, which gets data periodically, and sends to |
| *Processing* task. |
| - *Processing*: Has a work queue, which handles processing the jobs. |
| - *Kernel*: A simple work loop which demonstrates a possible integration of |
| tracing with a RTOS/Kernel. |
| |
| Jobs are intentionally made to have multiple stages of processing (simulated by |
| being re-added to the work-queue). This results in multiple jobs being handled |
| at the same time, the trace_id is used to separate these traces. |
| |
| ---------------------- |
| Python Trace Generator |
| ---------------------- |
| The Python tool is still in early developments, but currently it supports |
| generating a list of json lines from a list of trace events. |
| |
| To view the trace, these lines can be saved to a file and loaded into |
| chrome://tracing. |
| |
| Future work will look to add: |
| |
| - Config options to customize output. |
| - A method of providing custom data formatters. |
| - Perfetto support. |