Tracing

Crosvm supports tracing to allow developers to debug and diagnose problems and check performance optimizations.

The crate cros_tracing is used as a frontend for trace points across the crosvm codebase. It is disabled by default but we can enable it with a compile-time flag. It is written to be extensible and support multiple backends.

The currently supported backends are:

  • noop: No tracing is enabled. All trace points are compiled out of the application so there is no performance degradation. This is the default backend when no tracing flag is provided.
  • trace_marker: ftrace backend to log trace events to the Linux kernel. Only supported on Linux systems. Enabled by compiling crosvm with the --features trace_marker flag. (On CrOS it is USE flag crosvm-trace-marker)

cros_tracing Overview

The cros_tracing API consists of the following:

  • cros_tracing::init(): called at initialization time in src/main.rs to set up any tracing-specific initialization logic (opening files, set up global state, etc).
  • cros_tracing::push_descriptors!(): a macro that needs to be called every time crosvm sets up a sandbox jail before forking. It adds trace-specific file descriptors to the list of descriptors allowed to be accessed inside the jail, if any.
  • cros_tracing::trace_simple_print!(): a simple macro that behaves like a log() print and sends a simple message to the tracing backend. In case of the trace_marker backend, this will show up as a message in the ftrace/print list of events.
  • cros_tracing::trace_event_begin!(): a macro that tracks a tracing context for the given category and emits tracing events. It increased the counter of trace events for that context, if the category is enabled.
  • cros_tracing::trace_event_end!(): the opposite of trace_event_begin!(). It decreases the counter of currently traced events for that category, if the category is enabled.
  • cros_tracing::trace_event!(): a macro that returns a trace context. It records when it is first executed and the given tag + state. When the returned structure goes out of scope, it is automatically collected and the event is recorded. It is useful to trace entry and exit points in function calls. It is equivalent to calling trace_event_begin!(), logging data, and then calling trace_event_end!() before it goes out of scope. It's recommended to use trace_event!() rather than call trace_event_begin!() and trace_event_end!() individually.

The categories that are currently supported by cros_tracing are:

  • VirtioFs
  • VirtioNet
  • USB
  • gpu_display
  • VirtioBlk
  • VirtioScsi

The trace_marker Backend

The trace_marker backend assumes that the host kernel has tracefs enabled and /sys/kernel/tracing/trace_marker is writable by the host when the crosvm process starts. If the file cannot be accessed, tracing will not work.

Usage

First, we want to build crosvm with trace_marker enabled:

cargo build --features trace_marker

To verify that tracing is working, first start a trace capture on the host. You can use something like trace-cmd or manually enable tracing in the system from the terminal:

sudo echo 1 > /sys/kernel/tracing/tracing_on

We can check that virtiofs tracing is working by launching crosvm with a virtiofs filesystem:

sudo crosvm run --disable-sandbox --shared-dir ${MOUNTPOINT}:mtdroot:type=fs -p "rootfstype=virtiofs root=mtdroot rw init=/bin/bash" ${KERNEL}

Where ${MOUNTPOINT} is your virtiofs filesystem and ${KERNEL} is your linux kernel.

In another terminal, open a cat stream on the /sys/kernel/tracing/trace_pipe file to view the tracing events in real time:

sudo cat /sys/kernel/tracing/trace_pipe

As you issue virtiofs requests, you should see events showing up like:

<...>-3802142 [011] ..... 2179601.746212: tracing_mark_write: fuse server: handle_message: in_header=InHeader { len: 64, opcode: 18, unique: 814, nodeid: 42, uid: 0, gid: 0, pid: 0, padding: 0 }
<...>-3802142 [011] ..... 2179601.746226: tracing_mark_write: 503 VirtioFs Enter: release - (self.tag: "mtdroot")(inode: 42)(handle: 35)
<...>-3802142 [011] ..... 2179601.746244: tracing_mark_write: 503 VirtioFs Exit: release

Adding Trace Points

You can add you own trace points by changing the code and recompiling.

If you just need to add a simple one-off trace point, you can use trace_simple_print!() like this (taken from devices/src/virtio/fs/worker.rs):

#![allow(unused)]
fn main() {
pub fn process_fs_queue<F: FileSystem + Sync>(
    mem: &GuestMemory,
    interrupt: &Interrupt,
    queue: &mut Queue,
    server: &Arc<fuse::Server<F>>,
    tube: &Arc<Mutex<Tube>>,
    slot: u32,
) -> Result<()> {
    // Added simple print here
    cros_tracing::trace_simple_print!("Hello world.");
    let mapper = Mapper::new(Arc::clone(tube), slot);
    while let Some(avail_desc) = queue.pop(mem) {
        let reader =
            Reader::new(mem.clone(), avail_desc.clone()).map_err(Error::InvalidDescriptorChain)?;
        let writer =
            Writer::new(mem.clone(), avail_desc.clone()).map_err(Error::InvalidDescriptorChain)?;

        let total = server.handle_message(reader, writer, &mapper)?;

        queue.add_used(mem, avail_desc.index, total as u32);
        queue.trigger_interrupt();
    }
}

Recompile and you will see your message show up like:

<...>-3803691 [006] ..... 2180094.296405: tracing_mark_write: Hello world.

So far so good, but to get the most out of it you might want to record how long the function takes to run and some extra parameters. In that case you want to use trace_event!() instead:

#![allow(unused)]
fn main() {
pub fn process_fs_queue<F: FileSystem + Sync>(
    mem: &GuestMemory,
    interrupt: &Interrupt,
    queue: &mut Queue,
    server: &Arc<fuse::Server<F>>,
    tube: &Arc<Mutex<Tube>>,
    slot: u32,
) -> Result<()> {
    // Added trace event with slot
    let _trace = cros_tracing::trace_event!(VirtioFs, "process_fs_queue", slot);
    let mapper = Mapper::new(Arc::clone(tube), slot);
    while let Some(avail_desc) = queue.pop(mem) {
        let reader =
            Reader::new(mem.clone(), avail_desc.clone()).map_err(Error::InvalidDescriptorChain)?;
        let writer =
            Writer::new(mem.clone(), avail_desc.clone()).map_err(Error::InvalidDescriptorChain)?;

        let total = server.handle_message(reader, writer, &mapper)?;

        queue.add_used(mem, avail_desc.index, total as u32);
        queue.trigger_interrupt();
    }
}

Recompile and this will show up:

<...>-3805264 [017] ..... 2180567.774540: tracing_mark_write: 512 VirtioFs Enter: process_fs_queue - (slot: 0)
<...>-3805264 [017] ..... 2180567.774551: tracing_mark_write: 512 VirtioFs Exit: process_fs_queue

The number 512 in the log corresponds to a unique identifier for that event so it's easier to trace which Enter corresponds to which Exit. Note how the value of slot also has been recorded. To be able to output the state, the data type needs to support the fmt::Debug trait.

NOTE: The unique identifier for each event is unique only per-process. If the crosvm process forks (like spawning new devices) then it is possible for two events from different processes to have the same ID, in which case it's important to look at the recorded PID that emitted each event in the trace.

The numbers like 2180567.774540 and 2180567.774551 in the example above are the timestamps for that event, in <sec>.<usec> format. We can see that the process_fs_queue call took 11usec to execute.

In this last example we used the VirtioFs category tag. If you want to add a new category tag to trace_marker, it can be done by adding it to the the setup_trace_marker!() call in cros_tracing/src/trace_marker.rs:

#![allow(unused)]
fn main() {
// List of categories that can be enabled.
setup_trace_marker!(
    (VirtioFs, true),
    (VirtioNet, true),
    (USB, true),
    (gpu_display, true),
    (VirtioBlk, true),
    (VirtioScsi, true),
    (NewCategory, true)
);
}

If the value is false then the events will not be traced. This can be useful when you just want to trace a specific category and don't care about the rest, you can disable them in the code and recompile crosvm.

NOTE: Trace events are compile-time to reduce runtime overhead in non-tracing builds so a lot of changes require recompiling and re-deploying crosvm.