ハイパーバイザ自作中に遭遇したバグたち

先日の記事で書いた通り Writing Hypervisor in Zig に沿ってハイパーバイザを自作した。その際に遭遇したバグの数々についてどんなバグと出会ってどうやって調べて最終的にどう解決したのかをここに残しておく。だいたい自分のミスが原因なので誰の役にも立たないかもしれないけれど、こんなことがあったなあと後で自分で見返したい気持ちもあり。

BOOTX64.EFI が勝手に書き換わる

初期の頃にハマった事象。なにげに全体で一位二位を争うくらい解決に時間かかった気がする。QEMU を使って UEFI アプリであるブートローダ BOOTX64.EFI を実行、ブートローダがカーネルを読み込んでジャンプ、という流れで起動するのだが、ビルド後一度目の実行は成功するのだけれど、なぜか二度目以降の実行はエラーになる、というものだった。

こんなエラー

BdsDxe: loading Boot0001 "UEFI QEMU HARDDISK QM00001 " from PciRoot(0x0)/Pci(0x1,0x1)/Ata(Primary,Master,0x0)
BdsDxe: failed to load Boot0001 "UEFI QEMU HARDDISK QM00001 " from PciRoot(0x0)/Pci(0x1,0x1)/Ata(Primary,Master,0x0): Load Error

>>Start PXE over IPv4.

自分で書いたブートローダでカーネル (ELF) を読み込んでいるので、最初はその際にカーネルファイルを壊してしまっているんじゃないかと疑っていたがそんなこともなく。で、実行前と実行後で BOOTX64.EFI ファイルに差分があることが判明。カーネル側でグローバル変数を使っているとこの事象が発生することにたまたま気づいたので .rodata セクションがある場合とか .data セクションがある場合とかそんな感じで切り分けまくったのだけど特に何かわかるわけでもなく。そんなこんなで的外れな箇所を疑って散々時間を費やした後、ようやく QEMU コマンドに目が向く。使っているコマンドはこちら。

$ qemu-system-x86_64 \
        -m 512M \
        -bios /usr/share/ovmf/OVMF.fd \
        -drive file=fat:rw:../build/img,format=raw \
        -nographic \
        -serial mon:stdio \
        -no-reboot \
        -enable-kvm \
        -cpu host \
        -s

これらのオプションを一部外したりしながら切り分けていくと、詳細な経緯は覚えてないが -drive file=fat:rw:../build/img,format=raw オプション、つまり Virtual Fat 機能があやしいことが判明。とりあえず当時最新版の QEMU v10.0.0 で試してみたところ、なんとエラーが発生しなくなった。もともと使っていた QEMU は Ubuntu 24.04 で apt install したものでバージョンは v8.2.2 だったが、さらに切り分けていったところ v8.2.7 からエラーが発生しなくなることがわかった。v8.2.6 と v8.2.7 の間のコミットを眺めているといかにもなコミットを発見。

• コミット: vvfat: Fix bug in writing to middle of file
• ML: [PATCH v6 0/5] vvfat: Fix write bugs for large files and add iotests

これ以上は特に深追いはしてないが、ファイルサイズが大きい場合、ディスクにファイルを書き戻す際に off-by-one エラーを踏んでしまい別のファイルの内容を一部書き込んでしまう、みたいなものだと理解している (間違ってるかもしれない)。なので先述したグローバル変数を使っていると…みたいな話は単にカーネルのファイルサイズが大きくなりこのエラーにあたるようになってしまっていた、ということだと思われる。この経験から QEMU も信用してはいけないという教訓を得た。 (この後 QEMU 起因の問題は起きなかったのだが)

VMRUN が失敗する

はじめの一歩として HLT 命令を無限ループするだけの関数をゲストに実行させようとして全然うまくいかなかったという話。まあ初めて VMRUN してみたときのことなのですんなりうまくいくほうが逆にこわいというのはある。解決までの経緯は以下の通り。

1. VMCB の必要そうな箇所を埋めて VMRUN してみるも永遠に #GP
2. VMRUN 時のホスト状態格納先アドレスを指定する VM_HSAVE_PA MSR に自分で書き込む必要があることに気づき、やってみたところ #GP は出なくなるも loop に入らずホストに制御が戻ってきてしまう
3. VMCB に格納される VMEXIT 時の EXITCODE を確認したところ -1 (VMEXIT_INVALID) であることが判明
4. 「15.5 VMRUN Instruction」の「Canonicalization and Consistency Checks.」を確認、「The VMRUN intercept bit is clear.」の場合は NG と書いてあったのでセットしたところ今度はおそらくトリプルフォルトが発生して落ちるようになった
5. シャットダウンイベント発生時に VMEXIT するようにしてみたら、ホストに制御が戻ってくるようになった。EXITCODE は当然 0x7F (VMEXIT_SHUTDOWN)。やはりゲスト側で例外が発生しているっぽい
6. さらにゲスト側で例外が発生した際に VMEXIT するようにしてみたら、#GP が発生していることがわかった
7. GDB を使って確認。nexti を使って vmrun 命令を実行すると、アドレス 0x0000000080102cf0 に飛んでいることが判明。VMCB 内の RIP には無限ループする関数のアドレスである 0xffffffff80102cf0 を入れているにもかかわらず。addressing に失敗していそう。
8. ついに原因がわかった！ VMCB 内で segment registers の attr を設定する箇所について、勝手に解釈違いをしていた。領域としては word (2-byte) 分あって、使わない 4-bit は間に挟まると思っていたけど、そうじゃなくて単純に末尾を使わない領域とすべきだった。

最後は VMCB へのセグメントレジスタの attribute のセットの仕方が間違っていたというもの。ちゃんとドキュメントを読みましょうというお話。

Linux kernel のロードがうまくいかない

ブートローダでロードした Linux kernel を確保しておいたゲストメモリに memcpy する際に Page fault が発生。ただ、毎回発生するわけではなく3回に1回くらいの頻度で発生するので非常にやっかいだった。

何が原因かわからずあっちを調べこっちを調べと紆余曲折した挙句、memcpy 関数のアセンブリと事象発生時のレジスタの状態を ChatGPT に見せてスタックが壊れていることが判明。レジスタやスタックの状態など人が見てぱっとわからない部分をいい感じに解析してくれるのでこういう時 AI は便利。

また、タイマー割り込みを有効化させた後から発生していることも判明。ここで割り込みの影響を疑いだして、ようやく原因がわかった。まとめると次の通り。

• memcpy 関数 (自前のもの) がスタックポインタを減算することなくスタックを使用している
• 割り込みハンドラがレジスタの値を退避するためにスタックを使用している
• memcpy の処理中に割り込みが発生した場合、割り込みハンドラによりスタックの中身が上書きされてしまう
• memcpy の処理に戻り、上書きされた値を使ってしまい想定外のアドレスにアクセスしようとして Page fault 発生

スタックポインタを超えた位置にある128バイト領域のことを red zone と呼ぶらしい。memcpy 関数は red zone を使っていたため、その間に割り込みが発生した際に red zone の中身が破壊されていたと。コンパイルオプションに -mno-red-zone を追加することで解決。

シェルが入力を受け付けなくなる

ゲスト Linux が最後まで起動してシェルの操作ができるようになったところまで来て遭遇した事象。たぶんこれが一番解決に時間がかかった。数回に一回、しばらくしてからシェルが入力を受け付けなくなってしまう。

この事象が発生しない場合も問題があって、シェルの文字出力が異常に遅くなってしまっていた。この投稿で貼り付けている実行結果がそれにあたる。ls の結果を出力するのにすごい時間がかかっている。

Writing Hypervisor in Zigを始めて早4ヶ月、ついについにゲストLinuxが起動した！！（なにやら出力が遅かったり何回かに一回ハングしたりはするけど） pic.twitter.com/zMawShkmig

— gingk (@gingk1212) August 10, 2025

つまり、これについては二つの問題が入り混じっていたということになる。

• 文字出力の速度は普通 / 途中で入力を受け付けなくなる (以下、ハングと呼ぶ)
• 文字出力の速度が遅い / 入力はずっと問題なく受け付ける

いろいろ調べた結果、ゲストの Primary PIC の IMR (割り込みマスク) が前者の場合は 11101010 になっていて、後者の場合は 11111010 になっていることがわかった。IRQ の4番はシリアル (8250 UART) による割り込み。試しにホスト側でシリアル割り込みをマスクしたままにした場合、つまりゲストにもシリアル割り込みを注入しないようにした場合、案の定ハングは発生しなくなった。シリアル割り込みが起因となっていることは確定。

Linux の起動ログをじっと眺めていると、前者と後者で起動ログに違いがあることもわかった。やはりシリアルの割り込みが影響していそう。

• 前者

[    0.441940] serial8250: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 8250

• 後者

[    0.392944] serial8250: ttyS0 at I/O 0x3f8 (irq = 0, base_baud = 115200) is a 8250

ここで一つ仮説。上記のログが出る前の処理でシリアル割り込みの IRQ 番号を実際に割り込みを発生させて確認していて、たまたま先にタイマー割り込みが来てしまいシリアル割り込みも IRQ 0 と勘違いされてしまった。で、勘違いされた場合はタイマー割り込みのたびに文字列が出力されることになり遅く見えると。確認時にちゃんと IRQ 4 が来た場合は出力が遅くなることはないけど、何かしらのバグのせいでハングが発生する。

Linux のソースを確認、このあたりの処理をしているのはおそらくこの autoconfig_irq() という関数。なんとなく仮説がだいたい合ってそうにも見える。

• 8250_port.c#L1323

ソースを見る限り、割り込み監視中に複数の割り込みが発生した場合も IRQ 0 になるっぽい。本来は監視時間は短いはずだけど、いまは割り込みのたびに #VMEXIT していろいろ処理してというのをやっているからその間にシリアル割り込みに加えてタイマー割り込みも来てしまうというのはありそう。

どうやって見つけたかは忘れたけれど、kernel configuration に SERIAL_8250_DETECT_IRQ といういかにもな config があるのを発見。こちらを無効にしたところ、上記のログで irq = 0 になる、つまり文字出力が遅くなることはなくなった。auto detect の処理自体が走らなくなり、シリアル割り込みの IRQ 番号としては問答無用で4番と認識されているようだった。

いろいろとググったところ、シリアル割り込み起因でシリアル入出力の処理をする動作モードは interrupt mode、タイマー契機でシリアル入出力の処理をするモードは polling mode と呼ばれていることがわかった (あいまい情報)。上記の通りの動きをするとしたら polling mode に陥ることも多々あるように思えてしまうが、どうなんだろうか。これ以上は深追いしていないので不明であり、今でも SERIAL_8250_DETECT_IRQ を有効にしてビルドした Linux をゲストとして使うと polling mode になることが多々あるので、解決したとは言えないかもしれないけどいったんここまでにしている。

ここからはハングについて調査。いろいろ調べまくった結果、ハングしたときはキー入力をしてもホストのシリアル割り込みハンドラが動いていないことがわかった。
→ QEMU Monitor で I/O ポートの内容を確認できることを知ったので、ハング中に 8250 UART の COM1 ポートを確認してみた。キー入力すると確かに RBR (0x3F8) にその文字が入っていたし、LSR (0x3FD) の Bit 0 (Data Ready) は 1 になっていた。つまり 8250 UART まではちゃんと入力が届いている。ただ、割り込みは届いていないと。

(qemu) i/1xb 0x3fd
portb[0x03fd] = 0x61
(qemu) i/1xb 0x3f8
portb[0x03f8] = 0x31
(qemu) i/1xb 0x3fd
portb[0x03fd] = 0x60

タイマーの頻度を下げたらどうなるか気になったのでやってみたところ、8250 UART の IRQ 検出に失敗しなくなったし、ハングの頻度もだいぶ下がった。まだ発生はするけど。つまりタイマーもやはりハングに関わっているということ。デフォルトでは Linux の kernel configuration として CONFIG_HZ_1000 が設定されているので、これを CONFIG_HZ_100 などに変えると頻度を下げられる。

ここまでは当時のメモをもとに少しは読みやすくなるように手を加えながら書いていたが、ここから先はちょっと大変そうだったのでサボってメモをそのまま貼り付けておく。関数名とか VMCB のフィールド名とかをそのまま書いてしまっておりコンテキスト抜けまくりでよくわからないと思うので読み飛ばしてしまっても構わない。なお、pending_irq とは VMM 側で保持している変数であり、16本の IRQ に対応する 16-bit のビットマップのこと。ビットが立っている場合はそのビットに対応する割り込みをゲストへ注入する予定、という意味となる。

さらに調べた結果、ハング直前は以下の流れで動いていることがわかった。

1. キー入力
2. いろいろ経てホストのシリアル割り込みハンドラが作動。pending_irq の Bit 4 をセットして EOI を通知
3. シリアル割り込みが来た回は観測した限りでは優先度的にタイマー割り込みを inject しがちだが、その後の HLT intercept の際にちゃんとシリアル分も inject する
4. その後、シリアル割り込みが来ることはなくなる。本来であれば次に Tx empty の割り込みが来るはずなのに

ちなみに 8250 UART の各レジスタの状態は以下の通り。 (参考: UART Registers)

• RBR (0x3f8): データは残ったまま
• IIR (0x3fa): Received Data Available Interrupt (0x4)
• LSR (0x3fd): Data Ready (0 Bit) (0x61)

つまり、シリアル割り込みをゲストに inject しているはずなのに、ゲストが RBR を read しにいってくれないと。

よーーーーうやく原因がわかった。inject_ext_intr() でシリアル割り込みを注入するタイミングでブレークを張ってみたところ、ほぼ確実にハングが発生することがわかった。ここからタイマーがやはり関連していることを推測。流れを書き出してみた。

1. ゲスト: HLT 実行
2. #VMEXIT
3. ホスト: 割り込みを許可 → シリアル割り込み発生、割り込みハンドラ作動
4. ホスト: その回ではないかもしれないが、どこかでシリアル割り込みを inject
5. ホスト: VMRUN 実行までの間にタイマー割り込み発生
6. VMRUN
7. ゲスト: どうなる？？？

ここで、シリアル割り込みを inject してから最初の #VMEXIT 後の V_IRQ を確認したところ、セットされたままだった。つまりゲストで処理されていないということ。さらにその #VMEXIT はタイマー割り込みによるものであるため、ここでも inject_ext_intr() が呼ばれて V_INTR_VECTOR が上書きされることに気づく。

APM の「15.21.4 Injecting Virtual (INTR) Interrupts」に以下の記述を発見。physical interrupts のほうが優先されるとのこと。つまり「7. ゲスト」では注入された割り込みをハンドラが処理するのではなく、physical interrupt による #VMEXIT が起こるということ。

Physical interrupts take priority over virtual interrupts, whether they are taken directly or through a #VMEXIT.

ということで、V_IRQ がセットされたままだった時は再度 pending_irq にセットしなおすことで問題解決。長かった・・。

以上。要はシリアル割り込みをゲストに注入しようとした際に VMRUN 実行前にタイマー割り込みが発生した場合、注入された割り込みをゲストが処理する前にタイマー割り込み起因の #VMEXIT が即座に発生して VMM 側でさらにタイマー割り込みを注入しようとするので、その際にシリアル割り込みがなかったことにされてしまっていたという話。注入した割り込みが処理されたかは VMCB の V_IRQ というフィールドを見ればわかるので、処理されていない場合は先述した pending_irq に再度積む、という解決策をとった。これは本当に大変だった・・。

番外編：Linux のデバッグビルドができない

最後にちょっとした小ネタ。もろもろの調査をやりやすくするために Linux をデバッグビルドしたいと思い調べたところ、kernel configuration の DEBUG_INFO という項目を有効化すればよさそうということがわかった。

DEBUG_INFO を有効化するには menuconfig で以下の項目の設定を変える必要がある。しかし、この状態で Enter を押しても何も表示が変わらず設定をいじることができなかった。

いったん諦めて放置していたのだけど、しばらく経ってやり直してみたらなんと今度は Enter を押すと以下の画面に遷移して設定を変更することができた。

もしやと思いターミナルの領域を狭くして再度試してみると今度は最初の時と同じく Enter を押しても何も反応しない。つまりターミナルのサイズが小さすぎると menuconfig がうまく動かないというオチだった。VS Code の下のほうにある小さいターミナルを使って操作していたのでちょうどこの問題にハマってしまっていた。

もし不具合だったら報告してみようと思い軽く調べてみたが、残念ながらどうも想定通りの挙動のように見えた。

• scripts/kconfig/mconf.c#L653

おわりに

当然他にも細々としたバグは大量にあったけれど、特に時間がかかったものを挙げてみた。なお、文章中にはほとんど出てきていないが ChatGPT や Gemini などの AI には頼りまくっている。的外れなことを言ってくることも多いけどヒントとなるようなワードを出してくれたりもしたので非常に助かった。Gemini 2.5 Pro が一番役に立ったという印象。こういう不具合解析みたいな作業はわりと好きなので大変ではあったけど総じて楽しかった。