Table of Contents

  1. Motivation
  2. Setup
  3. Basic Usage

Motivation

A significant amount of time of a programmer is spent on finding out why a program does not behave as expected. Most often, this is done by looking at the code hard enough until the error becomes apparent, but sometimes more sophisticated debugging techniques are needed. Debuggers can help finding errors by allowing the programmer to inspect values of variables and step through the code. However, when the error is not consistently reproducible because the program is highly interactive or it results from concurrent execution, debugging can become a nightmare. One approach to debug such errors is to constantly persist the state of the program and then analyze it after the fact. The simplest form of this is to write log messages which works well for simple cases but can become cumbersome when the number of log messages grows.

The tracing crate for rust provides a more sophisticated way of generating application traces. In addition to log messages which are associated with a certain point in time, tracing also uses hierarchical spans which represent time periods that capture the flow of the program. Each log message and span additionally have a set of key-value pairs associated with them which is commonly known as structured logging . The crate is highly configurable and only specifies a Subscriber trait downstream libraries can implement to consume the traces. There exist a wide variety of subscribers to output traces in different formats. However, I felt that there was lacking a simple way to generate and view traces that generates minimal overhead does not require additional servers to be set up.

This is why I defined a lightweight binary format for such traces called tracing-tape. The format is designed to efficiently write traces to disk without generating too much overhead slowing down the program. Furthermore, I published the tracing-tape-recorder crate which provides a simple API to record traces and the trace-deck application for visualizing the traces which is either available as a standalone binary or as a web application . The tape metaphor is used to emphasize the simplicity of the format and the fact that it is designed to be written sequentially and read back in a linear fashion. While I might write a more detailed post about the format itself, this post concentrates on the usage of the recorder and the viewer.

Setup

Preparing an application for tracing using the tracing-tape format is straightforward. First, you need to add the dependencies tracing , tracing_subscriber , and tracing-tape-recorder to your application using: cargo add tracing tracing_subscriber tracing-tape-recorder. The tracing-tape-recorder builds on the tracing_subscriber crate which basically provides a flexible way to forward traces to multiple endpoints using layers. For more information, see its documentation . All that is left to do is to create a subscriber with the TapeRecorder layer and set it as the global default subscriber:

use tracing::subscriber::set_global_default;
use tracing_subscriber::{layer::SubscriberExt, Registry};
use tracing_tape_recorder::TapeRecorder;

let subscriber = Registry::default().with(TapeRecorder::default());
set_global_default(subscriber).expect("setting default subscriber failed");

That’s it, all traces will now be recorded to a file called {crate_name}-{timestamp}.tape in the current working directory.

Note: the snippets in this post assume a tracing-tape-recorder version of 0.1.0, the API might have changed in later versions, see the documentation for the most recent version.

Basic Usage

Let’s assume we have the followig (somewhat trivial) program for calculating a bunch of Fibonacci numbers:

fn fib(n: u64) -> u64 {
    if n == 0 || n == 1 {
        n
    } else {
        fib(n - 1) + fib(n - 2)
    }
}

fn main() {
    for i in 0..20 {
        let result = fib(i);
    }
}

In order to trace it’s execution, we can modify the program as follows:

use tracing::{subscriber::set_global_default, trace_span};
use tracing_subscriber::{layer::SubscriberExt, Registry};
use tracing_tape_recorder::TapeRecorder;

#[tracing::instrument]
fn fib(n: u64) -> u64 {
    if n == 0 || n == 1 {
        trace_span!("base case").in_scope(|| {
            n
        })
    } else {
        trace_span!("recursion").in_scope(|| {
            fib(n - 1) + fib(n - 2)
        })
    }
}

fn main() {
    let subscriber = Registry::default().with(TapeRecorder::default());
    set_global_default(subscriber).expect("setting default subscriber failed");

    for i in 0..20 {
        let result = fib(i);
        tracing::info!(result, fib = i, "calculated fib");
    }
}

Notice the #[tracing::instrument] attribute on the fib function which automatically creates a span for each invocation of the function that automatically captures its arguments. Additionally, I added trace_span! calls to create spans for the base case and the recursive case and log messages to capture the result of the calculation using the tracing::info! macro. For more information on how you can use the tracing crate, have a look at its documentation .

Executing this program will genrate a tracing *.tape file in the current working directory which you can load into the trace-deck application. You can install trace-deck by installing it using cargo install trace-deck or by using the web app at https://trace-deck.oehrl.dev . Trace files can be loaded by either dragging them into the application or, when installed locally, using the trace-deck <filename> command. After loading the trace you are greeted with the following view:

Trace Deck