僕的BitVisor デバッグ法

# はじめに
普段やっているデバッグの方法というか方針というか，そういうものを書いてみたいと思います．
といっても，結論は地道に根気よくバグを探す，といった感じなのですが...

# なにでデバッグするか?
基本的にはBitVisor のprintf() 関数でログを出してのデバッグです．

ログはネットワーク越しに出力します．

ただ，あまりにも起動初期の段階(ネットワークドライバの初期化前とか)にpanic すると，ネットワーク越しからはログが見れません．
なので，そういうときはVGA出力でみます．
(ちなみに，vmm.driver.pci の設定を間違えたりすると，ドライバ初期化前に死んでしまい，こういう状態になります．)

また，いつもいつでもBitVisor がpanic するとは限りません．
時々ゲストOSだけがpanic したり謎のログを吐いて死ぬことがあります．
ファイルにログを書き出せるような死に方をしてくれれば，いいのですが，そうじゃないことも多いです．
こういう時にログが残せないと困るので，僕はゲストOSであるLinux はシリアルコンソールで操作するようにしています．
シリアルコンソールなら，クライアント側である程度バッファリングでき，それをコピペして残しておくことである程度対処できます．



## printf()を入れる方針
何かが思った通りに動かなくて困ったら，printf()でいろいろ情報を表示してみることになります．
どこにprintf()を入れて何を表示するかはデバッグの上で大事なことかと思います．

僕の方針は基本的に「数うちゃ当たる」です．
printf()を入れるとなったら，最初から思いつく場所すべてにprintf()をいれます．

なぜかというと，BitVisor のデバッグではリブートに時間がかかるため，あとで「あ，やっぱりこの情報も表示してみたいな」と思ったときにまたビルドしてリブートしてという作業が必要になり，時間がかかるからです．
それなら，最初から思いつくところすべて書くほうが結果的に速い，ということはよくあります．

ただ，気をつけないといけないこともあります．
printf()はとても重たい処理です．
入れすぎると処理がとても重くなります．
それによって，別の不具合が起きたり，逆に不具合が隠ぺいされてしまったりします．
そのことは念頭に置いておきましょう．

# panic() が出力する情報から落ちた場所を察するには
Tips 的なことも紹介してみましょう．
例えばこんなpanic の出力が出たとして

```
[1444023243.205559] Error: An exception in VMM!
[1444023243.207124] Interrupt number: 0x06 Invalid Opcode Exception (#UD)
[1444023243.208955] CR0: 0x8000003B  CR2: 0x00789C08  CR3: 0xB63E8000  CR4: 0x000026E8
[1444023243.210997] RAX: 0x00000000  RCX: 0x00000000  RDX: 0x00000000  RBX: 0x203F80000
[1444023243.212930] RSP: 0x413FF870  RBP: 0xFFFFFFFF  RSI: 0x413FFD28  RDI: 0x413FF898
[1444023243.214871] R8:  0x00000000  R9:  0x413FFD52  R10: 0x10000000000  R11: 0x00000002
[1444023243.216914] R12: 0xFFFFFFFFFFFFFFFF  R13: 0x00000000  R14: 0x00000000  R15: 0x00000000
[1444023243.218912] ES: 0x0058  CS: 0x0050  SS: 0x0058  DS: 0x0058  FS: 0x0058  GS: 0x0078
[1444023243.220894] CPU0  RSP on interrupt: 0x413FF8C8  Stack information:
[1444023243.222731] +00 RIP     000000004013ADF5  +20 SS  0000000000000058  +40 0000000040126BD0
[1444023243.224819] +08 CS      0000000000000050  +28     000000004013ADF0  +48 0000008128879C00
[1444023243.226880] +10 RFLAGS  0000000000010012  +30     0000000000000400  +50 0000000128879C00
[1444023243.228938] +18 RSP     00000000413FF8F8  +38     00070000401231BC  +58 0000000128879C00
[1444023243.231003] panic(CPU0): int_fatal 0x06 Invalid Opcode Exception (#UD)
[1444023243.232841] CR0 8000003B    CR2 00789C08    CR3 B63E8000    CR4 000026E8
[1444023243.234777] RFLAGS 00000006  GDTR 40347428+0000FFFF  IDTR 401F1580+0000FFFF
[1444023243.236730] stackdump: 0 40347778 0 40124F26 0 40135E1A 40135E38 0 0 D 0 0 40347778 4011EA04 1860 401257F2 0 40125D7C 0 0 0 18 413FF720 413FF6C0 CD62E428B6BC1395 6 4015A998 70F 1860 10E0 4015F440 6
[1444023243.242499] backtrace: 40124F26 40135E1A 40135E38 4011EA04 401257F2 40125D7C 4011E9F2 40126BD0 4013ADF0 4012F3CA 40135DFC 4013ADF5 4013ADF0 40126BD0 40126B55 4013C13B 4013AA40 4013B2A0
[1444023243.248129] Guest state and registers of cpu 0 ------------
[1444023243.249901] RAX 00000000    RCX 00000000    RDX 00000000    RBX FFFFFFFF81600000
[1444023243.251848] RSP FFFFFFFF81601F18    RBP FFFFFFFF8168F160    RSI 00000003    RDI FFFFFFFF81600000
[1444023243.255328] R8  00000000    R9  00000000    R10 FFFFFFED    R11 FFFFFFFF81600000
[1444023243.257306] R12 FFFF88012FDAFBC0    R13 FFFFFFFFFFFFFFFF    R14 000862FA    R15 00000000
[1444023243.259385] CR0 8005003B    CR2 00789C08    CR3 129F99000    CR4 001006F0
[1444023243.261241] ACR   ES 0001C000 CS 0000A09B SS 0000C093 DS 0001C000 FS 0001C000 GS 0001C000
[1444023243.263315] LIMIT ES (2^64-1) CS (2^64-1) SS (2^64-1) DS (2^64-1) FS (2^64-1) GS (2^64-1)
[1444023243.265389] BASE  ES 00000000 CS 00000000 SS 00000000 DS 00000000 FS 00000000 GS FFFF88012FA00000
[1444023243.268878] SEL   ES 00000000 CS 00000010 SS 00000018 DS 00000000 FS 00000000 GS 00000000
[1444023243.270972] RIP FFFFFFFF81014AD3  RFLAGS 00000246  GDTR FFFF88012FA04000+0000007F  IDTR FFFFFFFF8172E000+00000FFF
[1444023243.274562] EFER 00000D01
[1444023243.275993] Exit reason: 52=0x34 (unknown error)
[1444023243.277677] Exit qualification 00000000  VM exit interrupt information 00000000
[1444023243.279652] VM exit errcode 00000000  VMCS IDTR FFFFFFFF8172E000+00000FFF   VMCS RFLAGS 00000246
[1444023243.283063] re=0 pg=1 sw:en=0x0 es=0x0 cs=0x0 ss=0x0 ds=0x0 fs=0x0 gs=0x0
[1444023243.284986] ------------------------------------------------
```

ご丁寧に`Error: An exception in VMM!` と言っているので，これはBitVisor の中でメモリ操作をミスってるという感じのバグでしょう．
その時に， `backtrace: 40124F26 40135E1A 40135E38 4011EA04 401257F2 40125D7C 4011E9F2 40126BD0 4013ADF0 4012F3CA 40135DFC 4013ADF5 4013ADF0 40126BD0 40126B55 4013C13B 4013AA40 4013B2A0
`という行を見てみましょう．

これは，panic寸前に実行されたコードのアドレスです．
なので，これがソースコードのどの部分に対応するかわかれば，多少はデバッグの参考になるかもしれません．
このアドレスからソースコードを特定する簡単な方法があります．
以下のコマンドを叩いてみましょう

```
addr2line -e bitvisor.elf -a 40124F26 40135E1A 40135E38 4011EA04 401257F2 40125D7C 4011E9F2 40126BD0 4013ADF0 4012F3CA 40135DFC 4013ADF5 4013ADF0 40126BD0 40126B55 4013C13B 4013AA40 4013B2A0
```

addr2line がインストールされてないときは `binutils` というパッケージをインストールするとよいみたいです(僕がインストールしたときの記憶がもうないので，google 先生に聞いてみたらそう答えてくれました).
bitvisor.elf は実行したのと同じbitvisor.elfを指定します．別のものだと違う結果になってしまいます．
-a の後ろに書いているアドレスは1つでもいいですし，複数でもいいです．
これを実行すると，ずらずらとソースコードのファイル名と行数がでてきます．

### 追記

@hdk_2 さんからいただいたコメントによると

>stackdumpとbacktraceが出ている場合のbacktraceは、単にスタックからコードのアドレスっぽい範囲のものを抽出しているだけの胡散臭いバックトレースです。スタックに残るゴミを拾ってしまうこともあります。コンパイル時にCONFIG_BACKTRACE=1にしておくとよりまともなバックトレースが見られます。(が、64ビットコンパイルであってもフレームポインターが使用されるようになるぶん、パフォーマンスへの影響があります。)

とのこと．
今度試してみよう(まだ試してない).
@hdk_2 さん，コメントありがとうございます．
# メモリダンプする方法
BitVisor はpanic するとdbgsh に入れます．
dbgsh ではデバッグをサポートするための機能がいくつかあります．
例えば，メモリダンプを表示することができるので，RSP(スタックポインタ)やCR3が指す先のメモリダンプを表示してみると何か役に立つことがあるかもしれません．
僕も細かい使い方を忘れてしまったのです，以下のようにして使えるはずです
(以下はゲストOSから./dbgshを実行していますが，panic時でも同じだと思います)．

```
# ./dbgsh
> debug
guest state not found
debug> help
dp guest-physical-address(hex) : dump memory
dv guest-virtual-address(hex) : dump memory
Dp vmm-physical-address(hex) : dump memory
Dv vmm-virtual-address(hex) : dump memory
h value1(hex) value2(hex) : add/sub
r [register-name register-value(hex)]: print/set guest registers
n : get next guest state from log
! command : call external command
q : quit
```

# おわりに
僕がデバッグするときにやっていることなどを書いてみました．
革新的だったり斬新だったりする内容ではないですが，デバッグするときの参考になればよいなと思います．