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
fromexec_tb
in thetrace-events
file. See also: https://rwmj.wordpress.com/2016/03/17/tracing-qemu-guest-execution/