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
41Compatibility
42-------------
43Most of the facade is compatible with C and C++, the only exception to this is
44the Scope and Function tracing macros which are convenience wrappers only
45available in C++.
46
47Dependencies
48-------------
49``pw_preprocessor``
50
51Example
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------------
84Trace macros
85------------
86
87The ``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
94These 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
115This 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
127Modules
128-------
129In addition to these arguments, traces can be grouped into modules similar to
130logging. This is done by redefining the ``PW_TRACE_MODULE_NAME``.
131
132Flags
133-----
134Each trace event also has a flags field which can be used to provide additional
135compile time trace information. Each trace macro has a matching macro which
136allows 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
148When not specified the flag uses the value of the macro ``PW_TRACE_FLAGS``.
149
150Data
151----
152Each 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
170These 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
178Currently 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
196C++ Only Traces
197---------------
198Scope API measures durations until the object loses scope. This can for
199example, 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
204Function API measures durations until the function returns. This is the only
205macro which does not require a *label*, and instead uses the function name as the
206label. 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-----------
212Backend API
213-----------
214Each of the trace event macros get sent to one of two macros which are
215implemented 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
221The ``event_type`` value will be whatever the backend defined for that specific
222trace type using the macros defined below.
223
224The backend can optionally not define ``PW_TRACE_DATA`` to have those traces
225disabled.
226
227Trace types
228-----------
229Although 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
235This 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
247The backend must define these macros to have them enabled. If any are left
248undefined, any traces of that type are removed.
249
250Defaults
251--------
252The backend can use these macros to change what the default value is if not
253provided.
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----------
260Sample App
261----------
262A sample application is provided in the examples folder. This code attempts to
263provide examples of the multiple ways tracing can be used. Furthermore,
264trace backends can include the sample app in their own examples to show how to
265use other features.
266
267The 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
276Jobs are intentionally made to have multiple stages of processing (simulated by
277being re-added to the work-queue). This results in multiple jobs being handled
278at the same time, the trace_id is used to separate these traces.
279
280----------------------
281Python Trace Generator
282----------------------
283The Python tool is still in early developments, but currently it supports
284generating a list of json lines from a list of trace events.
285
286To view the trace, these lines can be saved to a file and loaded into
287chrome://tracing.
288
289Future work will look to add:
290
291- Config options to customize output.
292- A method of providing custom data formatters.
293- Perfetto support.
294