23.9. Tracing

QEMU can log several different events.

The most interesting are events which show instructions that QEMU ran, for which we have a helper:

./trace-boot --arch x86_64

Under the hood, this uses QEMU’s -trace option.

You can then inspect the address of each instruction run:

less "$(./getvar --arch x86_64 run_dir)/trace.txt"

Sample output excerpt:

exec_tb 0.000 pid=10692 tb=0x7fb4f8000040 pc=0xfffffff0
exec_tb 35.391 pid=10692 tb=0x7fb4f8000180 pc=0xfe05b
exec_tb 21.047 pid=10692 tb=0x7fb4f8000340 pc=0xfe066
exec_tb 12.197 pid=10692 tb=0x7fb4f8000480 pc=0xfe06a

Get the list of available trace events:

./run --trace help

TODO: any way to show the actualy disassembled instruction executed directly from there? Possible with QEMU -d tracing.

Enable other specific trace events:

./run --trace trace1,trace2
./qemu-trace2txt -a "$arch"
less "$(./getvar -a "$arch" run_dir)/trace.txt"

This functionality relies on the following setup:

  • ./configure --enable-trace-backends=simple. This logs in a binary format to the trace file.

    It makes 3x execution faster than the default trace backend which logs human readable data to stdout.

    Logging with the default backend log greatly slows down the CPU, and in particular leads to this boot message:

    All QSes seen, last rcu_sched kthread activity 5252 (4294901421-4294896169), jiffies_till_next_fqs=1, root ->qsmask 0x0
    swapper/0       R  running task        0     1      0 0x00000008
     ffff880007c03ef8 ffffffff8107aa5d ffff880007c16b40 ffffffff81a3b100
     ffff880007c03f60 ffffffff810a41d1 0000000000000000 0000000007c03f20
     fffffffffffffedc 0000000000000004 fffffffffffffedc ffffffff00000000
    Call Trace:
     <IRQ>  [<ffffffff8107aa5d>] sched_show_task+0xcd/0x130
     [<ffffffff810a41d1>] rcu_check_callbacks+0x871/0x880
     [<ffffffff810a799f>] update_process_times+0x2f/0x60

    in which the boot appears to hang for a considerable time.

  • patch QEMU source to remove the disable from exec_tb in the trace-events file. See also: https://rwmj.wordpress.com/2016/03/17/tracing-qemu-guest-execution/