せっかくなのでもう一つ記事を書いてみる。

この前の記事に、**「Hyper-Threading Technologyを有効にした状態で起動した時にpanicを起こして起動しない」**ということを書いた。
これがすごくモヤモヤするので原因を調べて解決してみた。
今回は、その解決までの原因調査方法について書いておく。

なお、この記事で扱う方法はBitVisorがpanicするときのみ有効な手段である。BitVisorがpanicせずに静かな死を遂げる場合は工夫が必要となるのであまり役に立たないと思う。

BitVisorが起動する環境を用意する

BitVisorが起動しないことには何もできない。

小さなBitVisorを作る

最新のBitVisorには高級な機能が沢山付いている。
贅沢はエラーの原因なので、最小構成のBitVisorを作って起動確認をする。

設定ファイルは、2種類ある。

.config
- ビルドするモジュールを決める設定ファイル
- make config でインタラクティブに設定可能
- ./configure のオプションや /boot/config* と同等のもの
defconfig
- モジュールの動作を決める設定ファイル
- 初回ビルド時に defconfig.tmpl からコピーされる
- /etc 以下にある設定ファイルのようなもの

テストに使うには、小さいがちょっとリッチぐらいがちょうど良いので、自分は以下を有効している。

64
TTY_SERIAL (デバッグ用)
CPU_MMU_SPT_3
CPU_MMU_SPT_USE_PAE
DBGSH (デバッグ用)
ACPI_DSDT
ENABLE_ASSERT
NET_DRIVER
NET_PRO1000
ACPI_TIME_SOURCE
BACKTRACE (デバッグ用)
IP

この設定で動かなければ、IP や ACPI_DSDT などを削ってビルド&ブートを繰り返す。

もう一方の defconfig は実際の使用場面で設定するので、このタイミングで変更する必要は無い。

BitVisor用のBIOS設定を整える

いろいろ .config を弄った結果、今回のHT有効時のエラーはBitVisorの設定を変更しても起動しなかった。

こんな時は、BIOS設定をBitVisorの機嫌が良くなるように調整する。

Hyper-threading technologyを無効にする
ATA modeをAHCIにする
不要なデバイスを無効にする

設定できる項目は一通り変更してみるのが良い。ただし、オーバークロックや動作電圧等の項目は触らない方が良い (というか下手すると故障する)。

これを行っても一向に改善しない場合は一旦諦める。H/Wを変え、比較しつつ試すしかない。

動くことが確認できたら、1箇所設定を変えてBitVisorを困らせてみる。今回は、HTをONにするだけ。

このPCでは Logical Processor を Enabled にする。

BitVisorがpanicすることを確認したら原因を探っていく。

ログを回収する

ログを取らないことには始まらない。そのログの取り方は色々。

シリアルポートで出力
UDPパケットで流す
syslogで送信
VGAに出力、動画撮影・コマ送り確認

今回は、シリアルポートを使ってログを取得する。
UDPパケットやsyslogで送信する方法は、ネットワークドライバが初期化された後しか使用できないので用途が限定される。特に今回のような例では、ドライバ初期化前にpanicしているので使えない。一方でシリアルポートの場合は、起動早期に初期化されるので問題にならない。

このPCはSerial-over-LANが使用できるので物理結線をする必要が無く、IPMI　(ネットワーク) 経由でログ取得ができて便利。

SOLは Serial Device2 で有効になっているので、Serial Device2 を COM1 としてマップするように変更する。

これで、COM1に書き込まれたデータは、以下のようにIPMIのSOLで出力されるようになる。

次のコマンドを使って出力をファイルにリダイレクトさせておく。

$ ipmitool -I lanplus -H ${host} -U ${user} sol activate | tee log

ログ取得はこれにて完了。

ログを解析する

最後のエラーメッセージを見ると、ASSERTで失敗していることがわかる。

panic(CPU8): Assertion failed!(n < NUM_OF_ALLOCSIZE) function mm_page_alloc file core/mm.c line 546

(恐らくBitVisor Proは、この時点で原因が分かるんだろうな。・・・とにかく続けます)

backtraceを見る

普通の人ならASSERTに至るまでの経緯が当然知りたくなるはず。そんなときは .config で有効にしておいたBACKTRACEが役に立つ。

備考: BACKTRACE無効時でもバックトレースは行われる。ただし、無効時はスタックを1つずつ掘り下げ、コード領域内のアドレスかどうかで判断する仕組みになっているので精度が良くない。一方、有効時は、ちゃんとフレームポインタ (%ebp or %rbp) を追いかけるようになる。

grepしてトレース結果を取り出す。

$ cat log | grep -a backtrace
backtrace<-0x401256A6<-0x40137B0A<-0x40125F73<-0x40126369<-0x4010E9FB<-0x40120542<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x40120A3C<-0x40120A6D<-0x401315A3<-0x40135573<-0x401328B1<-0x4011FB88<-0x4011C972<-0x4011F9E0<-0x4010E3D2.
backtrace<-0x401256A6<-0x40137B0A<-0x40125F73<-0x40126369<-0x4010E9FB<-0x40120542<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x401205FB<-0x40120A3C<-0x40120A6D<-0x401315A3<-0x40135573<-0x401328B1<-0x4011FB88<-0x4011C972<-0x4011F9E0<-0x4010E3D2.
...

リターンアドレスが表示されるが、これだけでは識別できないのでaddr2lineでソースコードとの対応付けを行う。
今回は、すべてのコアが同じ箇所で死亡しているので、1つ取り出して調べてみる。

$ cat sol.log3 | grep -a backtrace | head -1 | \
> sed 's/backtrace<-//;s/<-/ /g;s/\.//' | xargs addr2line -e bitvisor.elf 
/home/dev/bitvisor/core/panic.c:440
/home/dev/bitvisor/core/int_handler.s:103
/home/dev/bitvisor/core/panic.c:449
/home/dev/bitvisor/core/panic.c:526
??:?
/home/dev/bitvisor/core/mm.c:547
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:551
/home/dev/bitvisor/core/mm.c:899
/home/dev/bitvisor/core/mm.c:911
/home/dev/bitvisor/core/vt_ept.c:77 (discriminator 2)
/home/dev/bitvisor/core/vt_paging.c:96
/home/dev/bitvisor/core/vt_init.c:490
/home/dev/bitvisor/core/main.c:361
/home/dev/bitvisor/core/initfunc.c:70
/home/dev/bitvisor/core/main.c:469
/home/dev/bitvisor/core/ap.c:101

これで何処から呼び出されているかは特定できた。

ソースを読む

後はソースコードをひたすら読む。

mm_pages_allocがなんとなく怪しそうなので見てみる。

mm.c

 538 static struct page *
 539 mm_page_alloc (int n)
 540 {
 541         int s;
 542         virt_t virt;
 543         struct page *p, *q;
 544         enum page_type old_type;
 545 
 546         ASSERT (n < NUM_OF_ALLOCSIZE);
 547         s = allocsize[n];
 548         spinlock_lock (&mm_lock);
 549         while ((p = LIST1_POP (list1_freepage[n])) == NULL) {
 550                 spinlock_unlock (&mm_lock);
 551                 p = mm_page_alloc (n + 1);
 552                 spinlock_lock (&mm_lock);
 553                 virt = page_to_virt (p);
 554                 q = virt_to_page (virt ^ s);
 555                 p->allocsize = n;
 556                 p->type = PAGE_TYPE_FREE;
 557                 q->type = PAGE_TYPE_FREE;
 558                 LIST1_ADD (list1_freepage[n], p);
 559                 LIST1_ADD (list1_freepage[n], q);
 560         }
 561         /* p->type must be set before unlock, because the
 562          * mm_page_free() function may merge blocks if the type is
 563          * PAGE_TYPE_FREE. */
 564         old_type = p->type;
 565         p->type = PAGE_TYPE_ALLOCATED;
 566         spinlock_unlock (&mm_lock);
 567         /* The old_type must be PAGE_TYPE_FREE, or the memory will be
 568          * corrupted.  The ASSERT is called after unlock to avoid
 569          * deadlocks during panic. */
 570         ASSERT (old_type == PAGE_TYPE_FREE);
 571         return p;
 572 }

ここで以下のようなことが読み取れる。

関数名
- mm (memory management) 関連である
- ページを新規で割り当てるような機能である
引数n
- 547: allocsizeで使われている
whileの中身
- 551: 再帰呼出しされていて＋1した値で繰り返し実行している
- 558-559: 何やらリストに追加する処理が書かれている
list1_freepage
- 名前からして空きページを管理するリストっぽい
- 添え字は呼び出された時の引数nで指定されている

さらに、list1_freepageとallocsizeを追いかけると以下のコードが見つかる。

mm.c

 830         for (i = 0; i < NUM_OF_ALLOCSIZE; i++) {
 831                 allocsize[i] = 4096 << i;
 832                 LIST1_HEAD_INIT (list1_freepage[i]);
 833         }

forループ
- NUM_OF_ALLOCSIZE個の配列を初期化している
- ↑止まったASSERTの評価式で使われているので怪しい
allocsize
- 4096をシフトした値が入っている
- [ 4096, 8192, 16384, ...] みたいな感じ
- 見た目と名前からして、メモリサイズっぽい
list1_freepage
- リストヘッドが配列

と、OSを弄ったことがある人なら、Buddy Systemのような機能だと推測できる (Buddy Systemの説明は省略します)。
551行目の再帰呼出しは1つ大きなページ (呼出し元の2倍のサイズ) を要求する処理であり、558-559行目は大きなページを2つに分割したページとして空き領域を記録している処理だと思われる。

ここまで理解できると、ページの割当て処理、かつ、大きなページの割り当てに失敗している可能性が高いと考えられるはず。
では次に、なぜ大きなページの割り当てに失敗しているのかを考えてみる。

NUM_OF_ALLOCSIZEよりも大きなページを必要とするということは、初期化時に用意されたページを使い切っている可能性が考えられる。

メモリの未利用時はどうなってるのか
- 恐らく、list1_freepage[NUM_OF_ALLOCSIZE - 1]に全ての空きメモリが管理されているはずである
- コードを追いかけていないので推測だが、私ならそのように作る
リストが空になった場合はどうなるのか
- whileループを抜けなくなる
whileを抜けなくなるとどうなるのか
- mm_page_alloc(NUM_OF_ALLOCSIZE)で呼び出される
- n < NUM_OF_ALLOCSIZEを満たさない
- すなわち、今回のASSERTで止まる

要は、メモリ不足でOut of memory状態に陥っているということ。メモリを増せば解決するかもしれない。

怪しいところを修正する

メモリを増やすといっても、PCの搭載メモリを増やすわけではない。
BitVisorのメモリ領域は、起動段階で固定的に物理メモリを確保する仕組みになっている。
そのサイズはVMMSIZE_ALLで指定され、デフォルトは128MiBとなっている。
今回は単純に倍の256MiBに変更してみる。

mm.c.patch

diff -r 76db0ae4260b core/mm.c
--- a/core/mm.c	Mon Sep 12 20:01:54 2016 +0900
+++ b/core/mm.c	Sat Dec 17 11:40:10 2016 +0900
@@ -48,7 +48,7 @@
 #include "string.h"
 #include "uefi.h"
 
-#define VMMSIZE_ALL		(128 * 1024 * 1024)
+#define VMMSIZE_ALL		(256 * 1024 * 1024)
 #define NUM_OF_PAGES		(VMMSIZE_ALL >> PAGESIZE_SHIFT)
 #define NUM_OF_ALLOCSIZE	13
 #define MAPMEM_ADDR_START	0xF0000000

起動を確認する

変更したソースをビルドし、ブートさせる。
結果は、無事に起動した。

試しにlscpuを実行してみたが、CPU(s)を見ると24個すべて認識していることがわかる。

まとめ

ということで、原因はVMMに割り当てるメモリの不足だった。
より正確に言うと、Hyper-Threading Technologyによって倍増した論理コアがBitVisorのCPU毎に割り当てる必要のある管理領域を確保できなくさせたことが原因。なので、直接HTTが関係する問題では無かった。

ちなみに、あともう少しbacktraceを追いかけると、EPTを作成する時に落ちていることがわかる。
EPTは4MiB (NUM_OF_EPTBL * 1 page = 1024 * 4 KB)+α ぐらい(?)なので、コア毎に作るとなると24 logical cores * 4 MiB = 96 MiB。確かに足りなさそう。
もっと辿っていくと、この初期化処理はcreate_pass_vmから呼び出され、pcpu5で呼び出されることも分かる。これならすべてのコアで同じ箇所でpanicした理由も納得がいく。
だが、EPTってコア数分用意するんやっけ?という疑問が残るが、動作したので細かいことは気にしない (全コアで同時にTLB Flushしなくてもいいように、とか?)。

mm_page_allocのチェック処理で詰まったが、これをASSERTで落とすのは良いのだろうかとも思ったりする。というのも、もしASSERTを無効にした時にメモリ不足を起こすと、この部分でpanicしないようになるのでバッファオーバーランが発生してしまうから。

今回は、panicをスタート地点として辿る方法を書いた。そのため、panicせずに静かに死ぬ場合は適用できない。また、OSやブートローダが絡んでくると原因の切分けが困難になる。そいういう時は地道にprintfとかでモニタリングするしかない、と思う。

以上、我流のBitVisorデバッグ方法でした。何かの参考になればと。