Skip to main content
Version: Nightly 🚧

Tracing

This article has examples in the following target languages:

Tracing is a powerful tool when it comes to analysis and debugging of applications. Unfortunately, most tracing tools that are readily available are designed specifically for analyzing processes, threads and system calls. Specialized tools are required to enable analysis that is tailored to an alternative model of computation such as Reactors. The tools should be capable of understanding the fundamental concepts of the model, such as the distinction between logical and physical time, as well as structural units such as reactors and reactions. This page gives an overview of the currently supported trace mechanism, as well as an outline of alternative tools that could be useful in the future.

Tracing is different from logging. Logging produces human-readable output in textual form and incurs significant overhead. Tracing produces binary data that must be further processed to be useful and is designed to have minimal impact on the execution time of a program.

Tracing is currently supported in the C, Python, and C++ targets. The mechanism used in C and Python is different from that used in C++. Tracing in C++ requires third-party tools that may only be available in Linux. Tracing in C and Python does not require any third-party tools.

Default Tracing in C and Python​

The default C and Python tracing mechanism depends only on the availability of the pthread library. Like C++ tracing, tracing is enabled by a target parameter:

target C {
    tracing: true
};

Once it is enabled, when the compiled program, say Foo.lf, is executed, a trace file is created, Foo.lft (the extension is for "Lingua Franca trace"). If you wish to customize the root name of the trace file, you can specify the following target property instead:

target C {
    tracing: {trace-file-name: "Bar"}
};

This will result in the trace file being named Bar.lft, regardless of the name of the .lf file.

The trace file is a binary file. It is not human readable. There are utilities for reading it:

  • trace_to_csv: This program creates a text file with one line per traced event in comma-separated list format.
  • trace_to_chrome: This program creates a text file in JSON format that is suitable for reading into the same Google Trace Viewer, which runs in Google Chrome, as used above in C++ tracing.
  • trace_to_influxdb : This program will send the traced event to a running InfluxDB database server.
  • fedsd: This program creates a timed sequence diagram showing the interactions between components of a federated program (see Tracing Federated Programs below).

These four programs are located in reactor-c at lingua-franca/core/src/main/resources/lib/c/reactor-c/util/tracing. Running sudo make install in that directory will put executables into usr/local/bin.

Consider for example the ThreadedThreaded.lf test, which executes a number of heavyweight computations in parallel on multiple cores. If you enable tracing as shown above and run the program, a ThreadedTheread.lft file will appear. Running

   trace_to_csv ThreadedThreaded

will create a file called ThreadedThreaded.csv that looks like this:

Event, Reactor, Reaction, Worker, Elapsed Logical Time, Microstep, Elapsed Physical Time, Trigger, Extra Delay
Schedule called, a, 0, 0, 0, 0, 704000, a.t, 0
Schedule called, a, 0, 0, 0, 0, 704000, a.t, 200000000
Schedule called, a, 0, 0, 200000000, 0, 177916000, a.t, 200000000
...
Reaction starts, a, 0, 1, 0, 0, 765000, NO TRIGGER, 0
Reaction ends, a, 0, 1, 0, 0, 765000, NO TRIGGER, 0
Reaction starts, t[0], 0, 1, 0, 0, 793000, NO TRIGGER, 0
Reaction ends, t[0], 0, 1, 0, 0, 177520000, NO TRIGGER, 0
Reaction starts, t[3], 0, 1, 200000000, 0, 177955000, NO TRIGGER, 0
Reaction ends, t[3], 0, 1, 200000000, 0, 348602000, NO TRIGGER, 0

The first line defines each of the columns. For example, the second line records a call to lf_schedule() for reactor named a, with no associated reaction, in worker thread 0, at (elapsed) logical time 0 with microstep 0. The call occurred at (elapsed) physical time 704 microseconds and is scheduling the trigger named a.t (a timer) with extra delay 0. This file can be imported into any spreadsheet program and sorted and analyzed.

The trace_to_csv utility will also create a summary file called ThreadedThreaded_summary.csv that looks like this after importing in Excel:

CSV summary file

If you call

   trace_to_chrome ThreadedThreaded

then a ThreadedThreaded.json file is created. To visualize the data, point your Chrome browser to chrome://tracing/. Click on the Load button and select the .json file that you just created. The result should look something like this:

Chrome tracing visualization

The tan-colored regions whose labels start with "A" and "W" represent time spent advancing logical time and waiting for activity on the reaction queue, respectively. When logical time advances, unless you have specified the -fast option, one of the worker threads blocks execution until physical time catches up with logical time. The remaining worker threads block waiting for reactions that are ready to execute appear on the reaction queue.

The JSON trace format can be found here. There is also a list of available color codes.

User-Defined Tracepoints​

Users can add their own tracepoints in order to provide low-overhead recording of events and events with values that occur during the execution of reactions. To do this, the first step is to register the trace event in a startup reaction as follows:

    reaction(startup) {=
        if (!register_user_trace_event("Description of event")) {
            fprintf(stderr, "ERROR: Failed to register trace event.\n");
            exit(1);
        }
    =}

The description of the event is an arbitrary string, but the string must be unique. All events with the same description will be collected together in any display of events.

To then actually record an event, in a reaction, call tracepoint_user_event, passing it the same string. E.g.,

	reaction(in) -> out {=
	    ...
	    tracepoint_user_event("Description of event");
	    ...
	=}

You can also pass a value to the trace. The type of the value is long long, so it can be a time value or an int. For example,

	reaction(in) -> out {=
	    ...
	    tracepoint_user_value("Description of event", 42);
	    ...
	=}

An example of a Chrome display of a run of the Tracing regression test is here:

Chrome tracing visualization

In this image, "Number of Destination invocations" is an event description to which values 1 through 10 were passed. This results in the shaded value plot shown first. The other four rows are just pure events (with no value). They are shown by (extremely) thin lines positioned at the physical time of the occurrence of the event. Dragging the mouse over those thin lines shows further details about the event in the window below.

Global User-Defined Tracepoints​

Sometimes it is useful to define tracepoints that are global to the program, rather than local to a reactor. This can be done by defining the tracepoint in a startup reaction of the main reactor as follows:

main reactor {
  ...
  reaction(startup) {=
    global user_trace_event_id
    user_trace_event_id = self.register_user_trace_event("Global user trace event")
    if user_trace_event_id == 0:
      print("Failed to register user trace event.")
      exit(1)
  =}
  ...
}

Then, in any reaction, you can record the event by calling tracepoint_user_event or tracepoint_user_value, passing it the global tracepoint ID. E.g.,

  reaction(in) -> out {=
    ...
    global user_trace_event_id
    self.tracepoint_user_event(user_trace_event_id);
    self.tracepoint_user_value(user_trace_event_id, 42);
    ...
  =}

Tracing Federated Programs​

When the tracing target parameter is set to true in a federated program, then each federate plus the RTI will generate a binary trace file. The utility fedsd generates an HTML file containing an SVG graphic that shows the messages exchanged between components over time. Like the other utilities, fedsd is defined in lingua_franca/util/tracing and installed using make install.

Consider the following LF program:

Feedback exampleCreator: FreeHEP Graphics2D Driver Producer: de.cau.cs.kieler.klighd.piccolo.freehep.SemanticSVGGraphics2D Revision Source: Date: Friday, March 24, 2023 at 7:39:05 PM Central European Standard TimeFeedbackf1 : Fed1(10 msec)xf2 : Fed212xzyf3 : Fed3xy

Setting tracing: true in this program and running it produces four .lft files. Running fedsd on those files:

   fedsd

results in converting the files to .csv files and then generating a trace_svg.html file. Opening that file reveals a trace, the beginning of which looks like this:

Feedback trace

This section of the trace shows only the initial negotiation for the start time for the federation. The vertical axis represents physical time, and the labels on that axis display physical time relative to the start time that is the result of this initial negotiation. The vertical axis is not linear so that more events can be displayed in a small space. The horizontal lines represent messages sent and received, with the message type and tag information (if any) shown.

A more interesting part of the trace is shown here:

Feedback trace

This shows f1 (on the right) advancing time to 10 ms, and sending a message (in red, via the RTI) to f2, which then forwards it to f3 (again, via the RTI).

Live Tracing in C via the Xronos Dashboard​

In addition to the default file-based tracing described above, you can use the lf-trace-xronos plugin to stream live traces to the Xronos Dashboard using OpenTelemetry. This plugin provides real-time visualization of trace data without the need for post-processing.

To use the plugin, you need to build and install it, then configure your LF program to use it via the trace-plugin target property. Refer to the lf-trace-xronos repository for detailed build instructions and usage examples.

LF Trace via Xronos Dashboard