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

#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:

PW_TRACE_INSTANT(label)
PW_TRACE_INSTANT(label, group_label)
PW_TRACE_INSTANT(label, group_label, trace_id)
PW_TRACE_START(label)
PW_TRACE_START(label, group_label)
PW_TRACE_START(label, group_label, trace_id)
PW_TRACE_END(label)
PW_TRACE_END(label, group_label)
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:

PW_TRACE_INSTANT_FLAG(flag, label)
PW_TRACE_INSTANT_FLAG(flag, label, group_label)
PW_TRACE_INSTANT_FLAG(flag, label, group_label, trace_id)
PW_TRACE_START_FLAG(flag, label)
PW_TRACE_START_FLAG(flag, label, group_label)
PW_TRACE_START_FLAG(flag, label, group_label, trace_id)
PW_TRACE_END_FLAG(flag, label)
PW_TRACE_END_FLAG(flag, label, group_label)
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:

PW_TRACE_INSTANT_DATA(label, data_format_string, data, size)
PW_TRACE_INSTANT_DATA(label, group_label, data_format_string, data, size)
PW_TRACE_INSTANT_DATA(label, group_label, trace_id, data_format_string, data, size)
PW_TRACE_START_DATA(label, data_format_string, data, size)
PW_TRACE_START_DATA(label, group_label, data_format_string, data, size)
PW_TRACE_START_DATA(label, group_label, trace_id, data_format_string, data, size)
PW_TRACE_END_DATA(label, data_format_string, data, size)
PW_TRACE_END_DATA(label, group_label, data_format_string, data, size)
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.

PW_TRACE_SCOPE(label)
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.

PW_TRACE_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:

PW_TRACE(event_type, flags, label, group_label, trace_id)
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 development, 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.