はじめに
普段やっているデバッグの方法というか方針というか,そういうものを書いてみたいと思います.
といっても,結論は地道に根気よくバグを探す,といった感じなのですが...
なにでデバッグするか?
基本的には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
おわりに
僕がデバッグするときにやっていることなどを書いてみました.
革新的だったり斬新だったりする内容ではないですが,デバッグするときの参考になればよいなと思います.