A fair amount of the development work I do is related to storage performance in QEMU/KVM. Although I have written about disk I/O benchmarking and my performance analysis workflow in the past, I haven't covered the performance tools that I frequently rely on. In this post I'll go over what's in my toolbox and hopefully this will be helpful to others.
Performance analysis is hard when the system is slow but there is no clear bottleneck. If a CPU profile shows that a function is consuming significant amounts of time, then that's a good target for optimizations. On the other hand, if the profile is uniform and each function only consumes a small fraction of time, then it is difficult to gain much by optimizing just one function (although taking function call nesting into account may point towards parent functions that can be optimized):
If you are measuring just one metric, then eventually the profile will become uniform and there isn't much left to optimize. It helps to measure at multiple layers of the system in order to increase the chance of finding bottlenecks.
Here are the tools I like to use when hunting for QEMU storage performance optimizations.
kvm_stat
kvm_stat is a tool that runs on the host and counts events from the kvm.ko kernel module, including device register accesses (MMIO), interrupt injections, and more. These are often associated with vmentry/vmexit events where control passes between the guest and the hypervisor. Each time this happens there is a cost and it is preferrable to minimize the number of vmentry/vmexit events.
kvm_stat will let you identify inefficiencies when guest drivers are accessing devices as well as low-level activity (MSRs, nested page tables, etc) that can be optimized.
Here is output from an I/O intensive workload:
Event Total %Total CurAvg/s kvm_entry 1066255 20.3 43513 kvm_exit 1066266 20.3 43513 kvm_hv_timer_state 954944 18.2 38754 kvm_msr 487702 9.3 19878 kvm_apicv_accept_irq 278926 5.3 11430 kvm_apic_accept_irq 278920 5.3 11430 kvm_vcpu_wakeup 250055 4.8 10128 kvm_pv_tlb_flush 250000 4.8 10123 kvm_msi_set_irq 229439 4.4 9345 kvm_ple_window_update 213309 4.1 8836 kvm_fast_mmio 123433 2.3 5000 kvm_wait_lapic_expire 39855 0.8 1628 kvm_apic_ipi 9614 0.2 457 kvm_apic 9614 0.2 457 kvm_unmap_hva_range 9 0.0 1 kvm_fpu 42 0.0 0 kvm_mmio 28 0.0 0 kvm_userspace_exit 21 0.0 0 vcpu_match_mmio 19 0.0 0 kvm_emulate_insn 19 0.0 0 kvm_pio 2 0.0 0 Total 5258472 214493
Here I'm looking for high CurAvg/s rates. Any counters at 100k/s are well worth investigating.
Important events:
- kvm_entry/kvm_exit: vmentries and vmexits are when the CPU transfers control between guest mode and the hypervisor.
- kvm_msr: Model Specific Register accesses
- kvm_msi_set_irq: Interrupt injections (Message Signalled Interrupts)
- kvm_fast_mmio/kvm_mmio/kvm_pio: Device register accesses
sysstat
sysstat is a venerable suite of performance monitoring tools cover CPU, network, disk, memory activity. It can be used equally within guests and on the host. It is like an extended version of the classic vmstat(8) tool.
The mpstat, pidstat, and iostat tools are the ones I use most often:
- mpstat reports CPU consumption, including %usr (userspace), %sys (kernel), %guest (guest mode), %steal (hypervisor), and more. Use this to find CPUs that are maxed out or poor use of parallelism/multi-threading.
- pidstat reports per-process and per-thread statistics. This is useful for identifying specific threads that are consuming resources.
- iostat reports disk statistics. This is useful for comparing I/O statistics between bare metal and guests.
blktrace
blktrace monitors Linux block I/O activity. This can be used equally within guests and on the host. Often it's interesting to capture traces in both the guest and on the host so they can be compared. If the I/O pattern is different then something in the I/O stack is modifying requests. That can be a sign of a misconfiguration.
The blktrace data can be analyzed and plotted with the btt command. For example, the latencies from driver submission to completion can be summarized to find the overhead compared to bare metal.
perf-top
In its default mode, perf-top is a sampling CPU profiler. It periodically collects the CPU's program counter value so that a profile can be generated showing hot functions. It supports call graph recording with the -g option if you want to aggregate nested function calls and find out which parent functions are responsible for the most CPU usage.
perf-top (and its non-interactive perf-record/perf-report cousin) is good at identifying inner loops of programs, excessive memcpy/memset, expensive locking instructions, instructions with poor cache hit rates, etc. When I use it to profile QEMU it shows the host kernel and QEMU userspace activity. It does not show guest activity.
Here is the output without call graph recording where we can see vmexit activity, QEMU virtqueue processing, and excessive memset at the top of the profile:
3.95% [kvm_intel] [k] vmx_vmexit 3.37% qemu-system-x86_64 [.] virtqueue_split_pop 2.64% libc.so.6 [.] __memset_evex_unaligned_erms 2.50% [kvm_intel] [k] vmx_spec_ctrl_restore_host 1.57% [kernel] [k] native_irq_return_iret 1.13% qemu-system-x86_64 [.] bdrv_co_preadv_part 1.13% [kernel] [k] sync_regs 1.09% [kernel] [k] native_write_msr 1.05% [nvme] [k] nvme_poll_cq
The goal is to find functions or families of functions that consume significant amounts of CPU time so they can be optimized. If the profile is uniform with most functions taking less then 1%, then the bottlenecks are more likely to be found with other tools.
perf-trace
perf-trace is an strace-like tool for monitoring system call activity. For performance monitoring it has a --summary option that shows time spent in system calls and the counts. This is how you can identify system calls that block for a long time or that are called too often.
Here is an example from the host showing a summary of a QEMU IOThread that uses io_uring for disk I/O and ioeventfd/irqfd for VIRTIO device activity:
IO iothread1 (332737), 1763284 events, 99.9%
syscall calls errors total min avg max stddev
(msec) (msec) (msec) (msec) (%)
--------------- -------- ------ -------- --------- --------- --------- ------
io_uring_enter 351680 0 8016.308 0.003 0.023 0.209 0.11%
write 390189 0 1238.501 0.002 0.003 0.098 0.08%
read 121057 0 305.355 0.002 0.003 0.019 0.14%
ppoll 18707 0 62.228 0.002 0.003 0.023 0.32%
Conclusion
We looked at kvm_stat, sysstat, blktrace, perf-top, and perf-trace. They provide performance metrics from different layers of the system. Another worthy mention is the bcc collection of eBPF-based tools that offers a huge array of performance monitoring and troubleshooting tools. Let me know which tools you like to use!
