Tracing in QEMU

Qemu is mainly written in C language. But did you see any printf in its source code for warning or debugging? No. Because the tracing of Qemu doesn’t work that way. In this article, I will introduce how to trace the content you need in Qemu.

In Qemu, there is a trace-events infrastructure created for observation. I will demonstrate how this system works with an example.

In this example, I want to check what IRQ number is assigned to the PCIe controller in the ACPI DSDT table an AArch64 architecture. The code appears in function acpi_dsdt_add_pci of file hw/arm/virt-acpi-build.c . My aim is simply to print the irq variable in the function.

Next I will show everything I did to get the information I want.

Define A Tracing Function

A file trace-events must exist in the directory that contains the source code file you are going to trace. Each line of the file defines a tracing function. In this example, the file hw/arm/trace-events has existed. What I did is adding a line for my trace content:

acpi_dsdt_add_pci(uint32_t irq) “irq = %d”

This line contains 3 parts:

1. acpi_dsdt_add_pci is the function in which I am going to add printings.
2. (uint32_t irq) is the parameter(s) for the printed string.
3. "irq = %d" is the printed string.

In top-level file meson.build , a variable trace_events_subdirs is defined. You must make sure the variable contains the folder where your traced source file and the trace-events located.

Use The Tracing Function

Now that the tracing function is ready, call it in the code you are interested in. In this case, the code is like:

The highlighted line is what I added to show the irq value. After adding the trace event in last step, a function trace_acpi_dsdt_add_pci will be generated before building the source code. The pattern of the tracing function name is:

trace_<the function of interest>

Configure

After preparing the source code, you need to reconfigure and build Qemu to generate the tracing function and call it.

In configuration, you need to specify the trace backends by adding the --enable-trace-backends option like:

./configure --enable-trace-backends=BACKENDS …

Before answering what is a trace-backend , let me ask you a question: Where do you want the traces be printed? Stdout, a files or anywhere? trace-backend answers this question, it specifies where the trace go.

Now the following backends are supported:

1. Nop — The “nop” backend generates empty trace event functions. It is a way to disable all the tracing.
2. Log — The “log” backend sends trace events directly to standard error.
3. Simpletrace — The “simple” backend writes binary trace logs to a file. You need to use a tool to decode. I will show that soon.
4. Ftrace — The “ftrace” backend writes trace data to ftrace marker.
5. Syslog — The “syslog” backend sends trace events using the POSIX syslog API.
6. LTTng Userspace Tracer — The “ust” backend uses the LTTng Userspace Tracer library.
7. SystemTap — The “dtrace” backend uses DTrace sdt probes but has only been tested with SystemTap.

In my example I used simpletrace :

Build

Then when you type make command to build, ./scripts/tracetool script will be called to generate the tracing functions.

Searching for trace_acpi_dsdt_add_pci , you can find out how the tracing works:

All the tracing functions are defined in ./build/trace directory. Each source code folder containing a trace-events file corresponds to a source file and a header file here. The folder names in the path are concatenated with _ and prefixed with trace- to make the tracing source/header file name.

Run & Observe

Now everything is ready, you can run your virtual machine, collect tracing data and observe.

In your qemu command, you need to specify what functions are traced by specifying --trace option, like:

Just pay attention to the highlighted part. I was only interested in one function, so I write the full name of the traced function in --trace parameter. If you have broad interest covering more functions, you can set multiple --trace options and use the wildcard * for patterns, like:

qemu --trace “kvm_*” --trace “virtio_*” …

If you have a lot of trace-event to care, you can put the tracing functions into a text file and specify the file name in this way:

After exiting the virtual machine, a new file was generated in my working directory: trace-8646. It is binary, you need to decode it with a Python script:

➜ qemu git:(debug) ✗ ./scripts/simpletrace.py /usr/share/qemu/trace-events-all trace-8646
acpi_dsdt_add_pci 0.000 pid=8646 irq=0x23
acpi_dsdt_add_pci 4377680.170 pid=8646 irq=0x23

In the output of the instruction, I saw the trace content I had added. And before my custom printing string, the function being traced, time stamp and PID was prepended.

Reference

qemu/tracing.rst at master · qemu/qemu