GitHub - stefano-garzarella/qemu-boot-time: perf-script and (Linux, QEMU, SeaBIOS) patches to measure the boot time of a Linux VM with QEMU (original) (raw)

This repository collects perf-script and patches to measure the boot time of a Linux VM with QEMU. Using I/O writes, we can trace events in the firmware and Linux kernel.

We extended the I/O port addresses and values defined in qboot [https://github.com/bonzini/qboot/blob/master/benchmark.h] adding new trace points to trace the kernel boot time.

Patches

Linux

Apply the patches/linux.patch to your Linux kernel in order to trace kernel events

git checkout -b benchmark git am qemu-boot-time/patches/linux.patch

QEMU

Apply the patches/qemu.patch to your QEMU in order to trace optionrom events

git checkout -b benchmark git am qemu-boot-time/patches/qemu.patch

cd build-benchmark ../configure --target-list=x86_64-softmmu ... make

You can use qemu-system-x86_64 -L qemu/build-benchmark/pc-bios/optionrom/ ...to use the optionrom patched.

SeaBIOS

Apply the patches/seabios.patch to your SeaBIOS in order to trace bios events

git checkout -b benchmark git am qemu-boot-time/patches/seabios.patch

make clean distclean cp /path/to/qemu/roms/config.seabios-256k .config make oldnoconfig

You can use qemu-system-x86_64 -bios seabios/out/bios.bin ... to use the SeaBIOS image patched.

qboot

qboot already defines trace points, we just need to compile it definingBENCHMARK_HACK

BIOS_CFLAGS="-DBENCHMARK_HACK=1" make

You can use qemu-system-x86_64 -bios qboot/bios.bin ... to use the qboot image.

Prerequisites

The following steps allow perf record to get the kvm trace events:

echo 1 > /sys/kernel/debug/tracing/events/kvm/enable echo -1 > /proc/sys/kernel/perf_event_paranoid mount -o remount,mode=755 /sys/kernel/debug mount -o remount,mode=755 /sys/kernel/debug/tracing

How to use

Start perf record to collect the trace events

PERF_DATA="qemu_perf.data" perf record -a -e kvm:kvm_entry -e kvm:kvm_pio -e sched:sched_process_exec
-o $PERF_DATA & PERF_PID=$!

Wait some seconds to have perf record ready

sleep 3

You can run QEMU multiple times to get also some statistics (Avg/Min/Max)

qemu-system-x86_64 -machine q35,accel=kvm
-bios seabios/out/bios.bin
-L qemu/build-benchmark/pc-bios/optionrom/
-kernel linux/bzImage ... qemu-system-x86_64 -machine q35,accel=kvm
-bios seabios/out/bios.bin
-L qemu/build-benchmark/pc-bios/optionrom/
-kernel linux/bzImage ... qemu-system-x86_64 -machine q35,accel=kvm
-bios seabios/out/bios.bin
-L qemu/build-benchmark/pc-bios/optionrom/
-kernel linux/bzImage ...

Stop perf record

kill $PERF_PID

Get the measurements

perf script -s qemu-boot-time/perf-script/qemu-perf-script.py -i $PERF_DATA

Trace points

The benchmark.h file contains the following trace points used in thepatches:

Trace points are printed only if they are recorded, so you can only enable few of them.

Custom trace points

If you want to add new trace points, you can simply add an I/O write toLINUX_EXIT_PORT or FW_EXIT_PORT with a value (> 7) that identifies the trace point:

outb(10, LINUX_EXIT_PORT);

The perf script output will contain Exit point 10 line that identifies your trace point:

qemu_init_end: 143.770419 fw_start: 143.964328 (+0.193909) fw_do_boot: 164.71107 (+20.746742) Exit point 10: 165.396804 (+0.685734) linux_start_kernel: 165.979486 (+0.582682) linux_start_user: 272.178335 (+106.198849)

Example of output

$ perf script -s qemu-boot-time/perf-script/qemu-perf-script.py -i $PERF_DATA

in trace_begin sched__sched_process_exec 1 55061.435418353 289738 qemu-system-x86 kvm__kvm_entry 1 55061.466887708 289741 qemu-system-x86 kvm__kvm_pio 1 55061.467070650 289741 qemu-system-x86 rw=1, port=0xf5, size=1, count=1, val=1

kvm__kvm_pio 1 55061.475818073 289741 qemu-system-x86 rw=1, port=0xf5, size=1, count=1, val=4

kvm__kvm_pio 1 55061.477168037 289741 qemu-system-x86 rw=1, port=0xf4, size=1, count=1, val=3

kvm__kvm_pio 1 55061.558779540 289741 qemu-system-x86 rw=1, port=0xf4, size=1, count=1, val=5

kvm__kvm_pio 1 55061.686849663 289741 qemu-system-x86 rw=1, port=0xf4, size=1, count=1, val=6

sched__sched_process_exec 4 55067.461869075 289793 qemu-system-x86 kvm__kvm_entry 4 55067.496402472 289796 qemu-system-x86 kvm__kvm_pio 4 55067.496555385 289796 qemu-system-x86 rw=1, port=0xf5, size=1, count=1, val=1

kvm__kvm_pio 4 55067.505067184 289796 qemu-system-x86 rw=1, port=0xf5, size=1, count=1, val=4

kvm__kvm_pio 4 55067.506395502 289796 qemu-system-x86 rw=1, port=0xf4, size=1, count=1, val=3

kvm__kvm_pio 4 55067.584029910 289796 qemu-system-x86 rw=1, port=0xf4, size=1, count=1, val=5

kvm__kvm_pio 4 55067.704751791 289796 qemu-system-x86 rw=1, port=0xf4, size=1, count=1, val=6

sched__sched_process_exec 0 55070.073823767 289827 qemu-system-x86 kvm__kvm_entry 0 55070.110507211 289830 qemu-system-x86 kvm__kvm_pio 0 55070.110694645 289830 qemu-system-x86 rw=1, port=0xf5, size=1, count=1, val=1

kvm__kvm_pio 1 55070.120092692 289830 qemu-system-x86 rw=1, port=0xf5, size=1, count=1, val=4

kvm__kvm_pio 1 55070.121437922 289830 qemu-system-x86 rw=1, port=0xf4, size=1, count=1, val=3

kvm__kvm_pio 1 55070.198628779 289830 qemu-system-x86 rw=1, port=0xf4, size=1, count=1, val=5

kvm__kvm_pio 1 55070.315734630 289830 qemu-system-x86 rw=1, port=0xf4, size=1, count=1, val=6

in trace_end Trace qemu-system-x86

  1. pid 289738 qemu_init_end: 31.469355 fw_start: 31.652297 (+0.182942) fw_do_boot: 40.39972 (+8.747423) linux_start_boot: 41.749684 (+1.349964) linux_start_kernel: 123.361187 (+81.611503) linux_start_user: 251.43131 (+128.070123)
  2. pid 289793 qemu_init_end: 34.533397 fw_start: 34.68631 (+0.152913) fw_do_boot: 43.198109 (+8.511799) linux_start_boot: 44.526427 (+1.328318) linux_start_kernel: 122.160835 (+77.634408) linux_start_user: 242.882716 (+120.721881)
  3. pid 289827 qemu_init_end: 36.683444 fw_start: 36.870878 (+0.187434) fw_do_boot: 46.268925 (+9.398047) linux_start_boot: 47.614155 (+1.34523) linux_start_kernel: 124.805012 (+77.190857) linux_start_user: 241.910863 (+117.105851)

Avg qemu_init_end: 34.228732 fw_start: 34.403161 (+0.174429) fw_do_boot: 43.288918 (+8.885757) linux_start_boot: 44.630088 (+1.34117) linux_start_kernel: 123.442344 (+78.812256) linux_start_user: 245.408296 (+121.965952)

Min qemu_init_end: 31.469355 fw_start: 31.652297 (+0.182942) fw_do_boot: 40.39972 (+8.747423) linux_start_boot: 41.749684 (+1.349964) linux_start_kernel: 122.160835 (+80.411151) linux_start_user: 241.910863 (+119.750028)

Max qemu_init_end: 36.683444 fw_start: 36.870878 (+0.187434) fw_do_boot: 46.268925 (+9.398047) linux_start_boot: 47.614155 (+1.34523) linux_start_kernel: 124.805012 (+77.190857) linux_start_user: 242.882716 (+118.077704)