この記事は、 NTT Communications Advent Calendar 2024 2 日目の記事です。 perf の Python インタプリタを使って KVM Exit/Entry のレイテンシを計測してみます。 はじめに KVM の仕組み CPU トレースを取得する perf をビルドする Python コードを書く 独自スクリプトを用いて perf.data を集計する まとめ 参考文献 はじめに こんにちは。 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)