この記事は、 NTT Communications Advent Calendar 2024 2 日目の記事です。
perf の Python インタプリタを使って KVM Exit/Entry のレイテンシを計測してみます。
はじめに
こんにちは。 SDPF クラウド・仮想サーバーチームの杉浦 (@Kumassy_) です。 普段は OpenStack の開発・運用をしており、最近は仮想マシンの性能解析やトラブルシューティングなどに取り組んでいます。
perf は Linux のパフォーマンス解析に有用なツールです。 perf を使うことで、パフォーマンスカウンタの値を読んだり、プロファイリング、トレーシングなど様々なデータを取得することができます。
取得したデータを分析するには perf report や perf script が利用できますが、込み入ったデータを解析したいときには python または perl で書かれた独自のスクリプトを使うことができます。
今回は perf の Python インタプリタを使って KVM Exit/Entry のレイテンシを計測してみます。
KVM の仕組み
QEMU/KVM を利用した仮想環境では、ユーザーが作成した仮想マシンは QEMU のユーザープロセスとして実行されます。 算術演算など簡単な命令は、一般的なユーザープロセスと同じようにユーザー空間で処理されますが、 I/O などのセンシティブ命令はハイパーバイザ側で処理する必要があります。
仮想マシンがセンシティブ命令を実行しようとすると、仮想マシンの実行が一時停止し、 KVM Exit というイベントが発生します。 ハイパーバイザは KVM Exit が発生した理由 (Exit Reason) を調べて適切に処理し、仮想マシンの実行を再開します。このとき KVM Entry イベントが発生します。 このサイクルを図示すると次の図のようになります。
KVM Exit が発生してから KVM Entry が完了するまで仮想マシンは一時停止しているので、このレイテンシが長いと問題です。
このような解析には perf kvm サブコマンドも利用できますが、今回は KVM Exit/Entry のレイテンシを題材に、 perf の独自スクリプトを書いて分析してみます。
CPU トレースを取得する
まずは解析する CPU トレースを取得します。 仮想マシンを実行する物理マシンには複数の VM が収容されています。 あとで解析しやすいように、 CPU affinity を調整することで、解析対象 VM の vCPU を特定の物理 CPU コアに pinning しておきます。
$ sudo virsh vcpupin instance-0000xxxx 0 124 $ sudo virsh vcpupin instance-0000xxxx 1 125 $ sudo virsh vcpupin instance-0000xxxx 2 126 $ sudo virsh vcpupin instance-0000xxxx 3 127
以下のようなコマンドで kvm:kvm_exit と kvm:kvm_entry イベントのトレースを取得します。
$ sudo taskset -c 31 perf record -C 124-127 -e kvm:kvm_exit -e kvm:kvm_entry -- sleep 9000
perf script を使えばこのように解析できますが、少々見にくいです。
$ perf script -i /path/to/perf.data
CPU 0/KVM 18292 [124] 151678.240967: kvm:kvm_exit: vcpu 0 reason MSR_WRITE rip 0xffffffff9ae6cf64 info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000
CPU 0/KVM 18292 [124] 151678.240969: kvm:kvm_entry: vcpu 0, rip 0xffffffff9ae6cf66
CPU 0/KVM 18292 [124] 151678.240982: kvm:kvm_exit: vcpu 0 reason MSR_WRITE rip 0xffffffff9ae6cf64 info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000
CPU 0/KVM 18292 [124] 151678.240983: kvm:kvm_entry: vcpu 0, rip 0xffffffff9ae6cf66
CPU 0/KVM 18292 [124] 151678.241044: kvm:kvm_exit: vcpu 0 reason EXTERNAL_INTERRUPT rip 0xffffffff9b0c99be info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x800000ec error_code 0x00000000
そこで、独自スクリプトでは以下の 2 つを目標とします。
- Exit Reason ごとに
KVM Exit/Entryのレイテンシをヒストグラムとして表す - 上記ヒストグラムをコアごとに分けて表示する
perf をビルドする
perf の Python インタプリタを利用するには、 perf の libpython ビルドオプションが有効化されている必要があります。
私のチームで利用できる Ubuntu 22.04 環境では、 linux-tools-common に含まれる perf にはこのオプションが有効化されていませんでした。
$ sudo perf version --build-options
perf version 5.15
dwarf: [ on ] # HAVE_DWARF_SUPPORT
dwarf_getlocations: [ on ] # HAVE_DWARF_GETLOCATIONS_SUPPORT
glibc: [ on ] # HAVE_GLIBC_SUPPORT
syscall_table: [ on ] # HAVE_SYSCALL_TABLE_SUPPORT
libbfd: [ OFF ] # HAVE_LIBBFD_SUPPORT
libelf: [ on ] # HAVE_LIBELF_SUPPORT
libnuma: [ on ] # HAVE_LIBNUMA_SUPPORT
numa_num_possible_cpus: [ on ] # HAVE_LIBNUMA_SUPPORT
libperl: [ OFF ] # HAVE_LIBPERL_SUPPORT
libpython: [ OFF ] # HAVE_LIBPYTHON_SUPPORT
libslang: [ on ] # HAVE_SLANG_SUPPORT
libcrypto: [ on ] # HAVE_LIBCRYPTO_SUPPORT
libunwind: [ on ] # HAVE_LIBUNWIND_SUPPORT
libdw-dwarf-unwind: [ on ] # HAVE_DWARF_SUPPORT
zlib: [ on ] # HAVE_ZLIB_SUPPORT
lzma: [ on ] # HAVE_LZMA_SUPPORT
get_cpuid: [ on ] # HAVE_AUXTRACE_SUPPORT
bpf: [ on ] # HAVE_LIBBPF_SUPPORT
aio: [ on ] # HAVE_AIO_SUPPORT
zstd: [ OFF ] # HAVE_ZSTD_SUPPORT
libpfm4: [ OFF ] # HAVE_LIBPFM
そこで、以下のように Linux カーネルのソースコードをダウンロードし、 tools/perf をビルドします。
$ sudo apt install make gcc flex bison pkg-config $ sudo apt install libzstd1 libdwarf-dev libdw-dev binutils-dev libcap-dev libelf-dev libnuma-dev python3 python3-dev python-setuptools libssl-dev libunwind-dev libdwarf-dev zlib1g-dev liblzma-dev libaio-dev libtraceevent-dev debuginfod libpfm4-dev libslang2-dev systemtap-sdt-dev libperl-dev binutils-dev libbabeltrace-dev libiberty-dev libzstd-dev $ curl -O https://mirrors.edge.kernel.org/pub/linux/kernel/v5.x/linux-5.15.tar.xz $ tar xvf linux-5.15.tar.xz $ cd linux-5.15/tools/perf # python3-config パッケージを利用するために `PYTHON=python3` が必要でした $ make PYTHON=python3
libpython オプションを有効化できました。
$ ./perf version --build-options
perf version 5.15.0
dwarf: [ on ] # HAVE_DWARF_SUPPORT
dwarf_getlocations: [ on ] # HAVE_DWARF_GETLOCATIONS_SUPPORT
glibc: [ on ] # HAVE_GLIBC_SUPPORT
syscall_table: [ on ] # HAVE_SYSCALL_TABLE_SUPPORT
libbfd: [ on ] # HAVE_LIBBFD_SUPPORT
libelf: [ on ] # HAVE_LIBELF_SUPPORT
libnuma: [ on ] # HAVE_LIBNUMA_SUPPORT
numa_num_possible_cpus: [ on ] # HAVE_LIBNUMA_SUPPORT
libperl: [ on ] # HAVE_LIBPERL_SUPPORT
libpython: [ on ] # HAVE_LIBPYTHON_SUPPORT
libslang: [ on ] # HAVE_SLANG_SUPPORT
libcrypto: [ OFF ] # HAVE_LIBCRYPTO_SUPPORT
libunwind: [ on ] # HAVE_LIBUNWIND_SUPPORT
libdw-dwarf-unwind: [ on ] # HAVE_DWARF_SUPPORT
zlib: [ on ] # HAVE_ZLIB_SUPPORT
lzma: [ on ] # HAVE_LZMA_SUPPORT
get_cpuid: [ on ] # HAVE_AUXTRACE_SUPPORT
bpf: [ on ] # HAVE_LIBBPF_SUPPORT
aio: [ on ] # HAVE_AIO_SUPPORT
zstd: [ on ] # HAVE_ZSTD_SUPPORT
libpfm4: [ OFF ] # HAVE_LIBPFM
Python コードを書く
準備が整ったので、いよいよ CPU トレースを解析する Python スクリプトを記述します。
詳しい解説やサンプルコードが perf-script-python(1) にあるので、 man を参考に作業します。
まずはテンプレートを生成します。
テンプレートは perf script -g で生成できますが、 perf record -e で指定したイベントごとに関数を実装するので、 perf.data を渡す必要があります。
$ ~/linux-5.15-build/tools/perf/perf script -i /path/to/perf.data -g python generated Python script: perf-script.py
生成されたファイルをみると、以下のようになっています。
# $ cat perf-script.py # (snip) def trace_begin(): print("in trace_begin") def trace_end(): print("in trace_end") def kvm__kvm_exit(event_name, context, common_cpu, common_secs, common_nsecs, common_pid, common_comm, common_callchain, exit_reason, guest_rip, isa, info1, info2, intr_info, error_code, vcpu_id, perf_sample_dict): print_header(event_name, common_cpu, common_secs, common_nsecs, common_pid, common_comm) print("exit_reason=%s, guest_rip=%u, isa=%u, " \ "info1=%u, info2=%u, intr_info=%u, " \ "error_code=%u, vcpu_id=%u" % \ (flag_str("kvm__kvm_exit", "exit_reason", exit_reason), guest_rip, isa, info1, info2, intr_info, error_code, vcpu_id)) print('Sample: {'+get_dict_as_string(perf_sample_dict['sample'], ', ')+'}') for node in common_callchain: if 'sym' in node: print("\t[%x] %s" % (node['ip'], node['sym']['name'])) else: print(" [%x]" % (node['ip'])) print() def kvm__kvm_entry(event_name, context, common_cpu, common_secs, common_nsecs, common_pid, common_comm, common_callchain, vcpu_id, rip, perf_sample_dict): print_header(event_name, common_cpu, common_secs, common_nsecs, common_pid, common_comm) # (snip) print() def trace_unhandled(event_name, context, event_fields_dict, perf_sample_dict): print(get_dict_as_string(event_fields_dict)) print('Sample: {'+get_dict_as_string(perf_sample_dict['sample'], ', ')+'}') # (snip)
perf record -e で指定したイベント名ごとに関数が定義されていることと、イベントの付加情報が引数として渡されることがわかります。
KVM Exit/Entry のレイテンシを計測するには、グローバルなデータ構造を用意し、 kvm__kvm_exit に渡されたイベント発生時刻から kvm__kvm_entry に渡されたイベント発生時刻を引けばよさそうです。
今回の例では、 vCPU ごとに専用の物理 CPU コアを割り当てているので、 common_cpu を使えば kvm__kvm_exit イベントと kvm__kvm_exit イベントを対応づけることができます。
最後に kvm__kvm_exit が発生したときの時刻を last_kvm_exit_at に、そのときの Reason を last_kvm_exit_reason へ保存するようにします。
これらの情報をコアごとに保存するため、defaultdict を使ってコア番号をキーとする辞書を使います。
kvm__entry イベントの発生時刻から last_kvm_exit_at に保存された時刻を引き、レイテンシとして集計します。
イベントの発生時刻は整数部分 common_secs と小数部分 common_nsecs に分けて渡されることに注意します。
これらを結合してイベントの発生時刻を計算するには Util パッケージの nsecs 関数を使い、次のようにします。
nsecs(common_secs, common_nsecs)
exit_reason は整数で渡されるので、文字列表現に対応づけるには arch/x86/include/uapi/asm/vmx.h を参考にするとよいです。
最終的なコードは以下のようになりました。
# $ cat perf-script-kvm-exit-entry.py # perf script event handlers, generated by perf script -g python # Licensed under the terms of the GNU GPL License version 2 # The common_* event handler fields are the most useful fields common to # all events. They don't necessarily correspond to the 'common_*' fields # in the format files. Those fields not available as handler params can # be retrieved using Python functions of the form common_*(context). # See the perf-script-python Documentation for the list of available functions. from __future__ import print_function import os import sys sys.path.append(os.environ['PERF_EXEC_PATH'] + \ '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') sys.path.append('/home/openstack/work_ksugiura/linux-5.15-build/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace') from perf_trace_context import * from Core import * from Util import nsecs import numpy as np from collections import defaultdict ms = 1000 * 1000 exit_reason = ( "EXCEPTION_NMI", "EXTERNAL_INTERRUPT", "TRIPLE_FAULT", "INIT_SIGNAL", "N/A", "N/A", "N/A", "INTERRUPT_WINDOW", "NMI_WINDOW", "TASK_SWITCH", "CPUID", "N/A", "HLT", "INVD", "INVLPG", "RDPMC", "RDTSC", "N/A", "VMCALL", "VMCLEAR", "VMLAUNCH", "VMPTRLD", "VMPTRST", "VMREAD", "VMRESUME", "VMWRITE", "VMOFF", "VMON", "CR_ACCESS", "DR_ACCESS", "IO_INSTRUCTION", "MSR_READ", "MSR_WRITE", "INVALID_STATE", "MSR_LOAD_FAIL", "N/A", "MWAIT_INSTRUCTION", "MONITOR_TRAP_FLAG", "N/A", "MONITOR_INSTRUCTION", "PAUSE_INSTRUCTION", "MCE_DURING_VMENTRY", "N/A", "TPR_BELOW_THRESHOLD", "APIC_ACCESS", "EOI_INDUCED", "GDTR_IDTR", "LDTR_TR", "EPT_VIOLATION", "EPT_MISCONFIG", "INVEPT", "RDTSCP", "PREEMPTION_TIMER", "INVVPID", "WBINVD", "XSETBV", "APIC_WRITE", "RDRAND", "INVPCID", "VMFUNC", "ENCLS", "RDSEED", "PML_FULL", "XSAVES", "XRSTORS", "N/A", "N/A", "UMWAIT", "TPAUSE" "N/A", "N/A", "N/A", "N/A", "N/A", "BUS_LOCK", "NOTIFY", ) def trace_begin(): global last_kvm_exit_at last_kvm_exit_at = defaultdict(lambda: 0) global last_kvm_exit_reason last_kvm_exit_reason = defaultdict(lambda: -1) global kvm_entry_latencies kvm_entry_latencies = defaultdict(lambda: defaultdict(lambda: [])) print("in trace_begin") def trace_end(): global last_kvm_exit_at global kvm_entry_latencies print("in trace_end") print("kvm_entry_latencies") for core, reason_latencies in kvm_entry_latencies.items(): print("Core: ", core) for reason, latencies in reason_latencies.items(): print("Reason: [%d] %s" %(reason, exit_reason[reason])) max_latency = max(latencies) bins = [2**i for i in range(int(np.log2(max_latency)) + 2)] hist, bins = np.histogram(latencies, bins=bins) for i in range(len(hist)): print("[%16d, %16d) %d" % (bins[i], bins[i+1], hist[i])) def kvm__kvm_exit(event_name, context, common_cpu, common_secs, common_nsecs, common_pid, common_comm, common_callchain, exit_reason, guest_rip, isa, info1, info2, intr_info, error_code, vcpu_id, perf_sample_dict): global last_kvm_exit_at global last_kvm_exit_reason global kvm_entry_latencies last_kvm_exit_at[common_cpu] = nsecs(common_secs, common_nsecs) last_kvm_exit_reason[common_cpu] = exit_reason def kvm__kvm_entry(event_name, context, common_cpu, common_secs, common_nsecs, common_pid, common_comm, common_callchain, vcpu_id, rip, perf_sample_dict): global last_kvm_exit_at global last_kvm_exit_reason global kvm_entry_latencies if last_kvm_exit_at[common_cpu] > 0: latency = nsecs(common_secs, common_nsecs) - last_kvm_exit_at[common_cpu] reason = last_kvm_exit_reason[common_cpu] if latency > 1 * ms and reason != 12: print("exit-entry: [%d]: [%d.%d]: reason: %s, %d" % (common_cpu, common_secs, common_nsecs, exit_reason[reason], latency)) kvm_entry_latencies[common_cpu][reason].append(latency) last_kvm_exit_at[common_cpu] = 0 def trace_unhandled(event_name, context, event_fields_dict, perf_sample_dict): print(get_dict_as_string(event_fields_dict)) print('Sample: {'+get_dict_as_string(perf_sample_dict['sample'], ', ')+'}') def print_header(event_name, cpu, secs, nsecs, pid, comm): print("%-20s %5u %05u.%09u %8u %-20s " % \ (event_name, cpu, secs, nsecs, pid, comm), end="") def get_dict_as_string(a_dict, delimiter=' '): return delimiter.join(['%s=%s'%(k,str(v))for k,v in sorted(a_dict.items())])
独自スクリプトを用いて perf.data を集計する
では、作成したスクリプト perf-script-kvm-exit-entry.py を用いて KVM Exit/Entry のレイテンシを解析してみます。
Exit Reason ごと、コアごとにヒストグラムを作成すると以下のようになりました。
出力は非常に長いので、一部だけ掲載します。
$ perf script -i /path/to/perf.data -s /path/to/perf-script-kvm-exit-entry.py exit-entry: [126]: [151856.170064250]: reason: EXTERNAL_INTERRUPT, 1522602 exit-entry: [125]: [151915.737653830]: reason: EXTERNAL_INTERRUPT, 1282485 exit-entry: [124]: [152201.81772565]: reason: EXTERNAL_INTERRUPT, 2198819 exit-entry: [127]: [152672.999539636]: reason: EXTERNAL_INTERRUPT, 1341486 exit-entry: [124]: [152812.995271815]: reason: EXTERNAL_INTERRUPT, 1475909 Core: 124 Reason: [32] MSR_WRITE [ 1, 2) 0 [ 2, 4) 0 [ 4, 8) 0 [ 8, 16) 0 [ 16, 32) 0 [ 32, 64) 0 [ 64, 128) 0 [ 128, 256) 17842 [ 256, 512) 1884223 [ 512, 1024) 2344850 [ 1024, 2048) 2567959 [ 2048, 4096) 653205 [ 4096, 8192) 81909 [ 8192, 16384) 1771 [ 16384, 32768) 620 [ 32768, 65536) 5 [ 65536, 131072) 0 [ 131072, 262144) 0 [ 262144, 524288) 1 [ 524288, 1048576) 0 [ 1048576, 2097152) 1 Reason: [1] EXTERNAL_INTERRUPT [ 1, 2) 0 [ 2, 4) 0 [ 4, 8) 0 [ 8, 16) 0 [ 16, 32) 0 [ 32, 64) 0 [ 64, 128) 0 [ 128, 256) 0 [ 256, 512) 0 [ 512, 1024) 112 [ 1024, 2048) 390 [ 2048, 4096) 7145 [ 4096, 8192) 13116 [ 8192, 16384) 69835 [ 16384, 32768) 23903 [ 32768, 65536) 44 [ 65536, 131072) 20 [ 131072, 262144) 1 [ 262144, 524288) 1 [ 524288, 1048576) 3 [ 1048576, 2097152) 11 [ 2097152, 4194304) 1 Reason: [48] EPT_VIOLATION [ 1, 2) 0 [ 2, 4) 0 [ 4, 8) 0 [ 8, 16) 0 [ 16, 32) 0 [ 32, 64) 0 [ 64, 128) 0 [ 128, 256) 0 [ 256, 512) 0 [ 512, 1024) 37 [ 1024, 2048) 286 [ 2048, 4096) 940 [ 4096, 8192) 848 [ 8192, 16384) 223 [ 16384, 32768) 785 [ 32768, 65536) 17 [ 65536, 131072) 1 [ 131072, 262144) 6 [ 262144, 524288) 11 [ 524288, 1048576) 4
全体を眺めてみると、 EXTERNAL_INTERRUPT は頻度が高くレイテンシも大きい傾向にあることがわかりました。
EPT_VIOLATION の頻度は低いものの、発生したときのペナルティは大きいようです。
今回の実験のみから何かを導き出すのは難しいですが、ホスト OS の構成や、ゲスト OS の種類、ゲスト OS のワークロードを変更したときの差分に着目すると、有意義な結果が得られるかもしれません。
まとめ
perfには独自の Python スクリプトを用いて CPU トレースを集計できる機能があります。デフォルトの表示を変えたいときや、独自の集計処理を書きたいときに有用です。kvm:kvm_exitとkvm:kvm_entryというトレースポイントを使うことで、 KVM Exit / Entry のレイテンシを集計し、ヒストグラムとして表示しました。
参考文献
- 第5回 x86プロセッサの仮想化支援機能Intel VT ＆ AMD-V | gihyo.jp
- Linux perf Examples
- perf-script-python(1)
