時折飛んでくる原因不明な#GPをgdbで原因究明した備忘録

OS開発をしていると、謎な例外が飛んできたり、謎なクラッシュが起きたりして、辛いですよね。普通のソフトウェアだと、プログラムのロジックを丁寧に追えば原因究明できる事が多いのですが、OS開発ではハードウェア側のエラーによって落ちる事があって、そうなるとハードウェアの中がどうなっているかわからない以上、お手上げになってしまうわけです。もちろんハードウェア側のエラーといっても、実際はカーネル側の実装上の些細なミスだったりする事が多いわけですが、たとえそうであっても、それをハードウェアエラーが起きている状態から特定するのは、かなり難しいわけです。

こういう場合に取る方法はいくつかあって、まあ一番簡単なのは第六感によるデバッグですね。「なんとなくここら辺が怪しいから修正してみよう」みたいな。しかし、これはデバッガーの経験値に大きく依存するので、あまり褒められた方法ではありません。

2つ目は、仕様書をとにかく舐めるように読んで、レジスタの値が間違ってないか、初期化シークエンスをきちんと踏んでいるかを確認する、という方法があります。これはとにかく時間が掛かる上に、多くの場合、一回見落とした箇所というのは次も往々にして見落とすので、確実に原因究明できるとは言い難い方法です。

3つ目は、既存のOSのソースコードを読む事です。特にデバドラをデバッグする時とかだとこの方法が役立つ事が多い気がします。既存のOSのコードと、今自分が書いているコードとの差異がどこなのかを徹底的に洗い出すと、問題点が見つかるかもしれないです。この場合、動くコードという模範回答があるので、精神的にはだいぶ楽になります。

さて実機でエラーが発生した場合は、上記のような手法で頑張って解析しなければいけないのですが、ことエミュレータ上でエラーが発生した場合は、もう一つ、とても強力なデバッグ方法があります。それはOSをエミュレーションしているqemuの実行プロセスをデバッグするというもので、QEMUがエミュレーションしているハードウェアをデバッグする事により、本来はブラックボックスなはずのハードウェアの内部状態を丸裸にする事ができます。

この方法は、根気さえあれば確実にバグを特定できるので、デバッグ手法としてはかなり優良な部類に入ります。ま、面倒ですけどね。

 

前置きが長くなりましたが、今回、自作Toy OS上の初期化シークエンスで時々#GP(一般保護例外)が発生していたため、qemuにgdbをつなぐ事で問題を特定した一連のあらましを備忘録的な何かとして書いてみます。

※この記事は自作OS Advent Calender 2016に空きがあったので、ちょうどいいやというノリで書いたものです。

 

例外の発生状況

発生した例外のvector番号:13(#GP)

例外発生時のrip:割り込みの初期化がすべて終わり、以後の割り込みを許可しようとsti命令を発行した直後

発生タイミング:不定期

 

毎回起動時に発生するわけではなく、発生する場合と発生しない場合がありました。

 

とりあえずsti命令で落ちているっぽいので、Intelのマニュアルを元にsti命令でGPを発生する状況について調べます。レジスタのフラグによってGPが発生する可能性があるので、関連する全てのレジスタの値を表示してみますが、どうやら問題なさそうです。

というわけで、ここからqemuをgdbデバッグしていきます。具体的なやり方についてはこちら。また、ここではqemuの内部を追う事に主眼を置いているので、gdbの基本的な使い方については割愛します。

 

sti命令をトレースする

sti命令で落ちているようなので、sti命令をトレースします。qemu/target-i386/translate.c内のsti命令を実行するコード内で例外を発生する部分があるので、そこにブレークポイントを仕掛けます。

    case 0xfb: /* sti */

        if (!s->vm86) {

            if (s->cpl <= s->iopl) {

            gen_sti:

                gen_helper_sti(cpu_env);

                /* interruptions are enabled only the first insn after sti */

                /* If several instructions disable interrupts, only the                                                                                                                                     

                   _first_ does it */

                if (!(s->tb->flags & HF_INHIBIT_IRQ_MASK))

                    gen_helper_set_inhibit_irq(cpu_env);

                /* give a chance to handle pending irqs */

                gen_jmp_im(s->pc - s->cs_base);

                gen_eob(s);

            } else {

                gen_exception(s, EXCP0D_GPF, pc_start - s->cs_base);

            }

        } else {

            if (s->iopl == 3) {

                goto gen_sti;

            } else {

                gen_exception(s, EXCP0D_GPF, pc_start - s->cs_base);

            }

        }

        break;

2箇所ある、gen_exception(s, EXCP0D_GPF, pc_start – s->cs_base)って所ですね。

しかしながら、この2箇所でブレークする事はありませんでした。

つまり、sti命令を実行した事によって#GPが発生したわけではない、という事がわかります。

何が起こっているかというと、sti命令を有効化した事によって、ハードウェア割り込みが有効化され、それに起因して何らかの処理がなされた(例えば実際に割り込みが飛んだ、とか)結果、その処理の中で#GPが発生した、という事になります。でも、そうわかった所で原因が皆目検討もつかないので、もう少し調べてみましょう。

例外発生関数から例外発生要因を特定する

qemu-2.4.1/target-i386/excp_helper.c内にraise_interrupt2という関数があります。(先程のgen_exceptionを掘り下げていて見つけました)

このraise_interrupt2に例外を仕掛ければ、backtraceにより発生要因を特定できます。(gen_exceptionに仕掛けなかったのは、gen_exceptionを経由しない例外があるため。実際に一度仕掛けて上手くいかない事を確認済み)

例外を仕掛ける時は変数intnoが13の場合のみブレークするよう、フィルタリングしておいた方が良いです。他の割り込みも拾われたらデバッグが面倒になるので。

#0  raise_interrupt2 (env=0x2ab57782a6c0, intno=13, is_int=0, error_code=-14,

    next_eip_addend=0)

    at /home/vagrant/qemu-2.4.1/target-i386/excp_helper.c:97

#1  0x00002ab577324506 in raise_exception_err (env=0x2ab57782a6c0,

    exception_index=13, error_code=-14)

    at /home/vagrant/qemu-2.4.1/target-i386/excp_helper.c:125

#2  0x00002ab57734cc56 in do_interrupt64 (env=0x2ab57782a6c0, intno=-1,

    is_int=0, error_code=0, next_eip=0, is_hw=1)

    at /home/vagrant/qemu-2.4.1/target-i386/seg_helper.c:849

#3  0x00002ab57734da93 in do_interrupt_all (cpu=0x2ab577822470, intno=-1,

    is_int=0, error_code=0, next_eip=0, is_hw=1)

    at /home/vagrant/qemu-2.4.1/target-i386/seg_helper.c:1224

#4  0x00002ab57734dc96 in do_interrupt_x86_hardirq (env=0x2ab57782a6c0,

    intno=-1, is_hw=1)

    at /home/vagrant/qemu-2.4.1/target-i386/seg_helper.c:1284

#5  0x00002ab57734df62 in x86_cpu_exec_interrupt (cs=0x2ab577822470,

    interrupt_request=2)

    at /home/vagrant/qemu-2.4.1/target-i386/seg_helper.c:1331

#6  0x00002ab577220675 in cpu_x86_exec (cpu=0x2ab577822470)

    at /home/vagrant/qemu-2.4.1/cpu-exec.c:465

#7  0x00002ab5772503d0 in tcg_cpu_exec (cpu=0x2ab577822470)

    at /home/vagrant/qemu-2.4.1/cpus.c:1402

#8  0x00002ab5772504d6 in tcg_exec_all ()

    at /home/vagrant/qemu-2.4.1/cpus.c:1434

#9  0x00002ab57724f7bf in qemu_tcg_cpu_thread_fn (arg=0x2ab577822470)

    at /home/vagrant/qemu-2.4.1/cpus.c:1068

#10 0x00002ab57945c184 in start_thread (arg=0x2ab57df68700)

    at pthread_create.c:312

#11 0x00002ab57976c37d in clone ()

    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

なんだかんだ頑張った結果、得られたバックトレースがこちら。

スタックフレームを辿っていけば、どこかにqemu側が意図的に一般保護例外を発生させている状況があるはずです。

パッと見た感じ、割り込み周りの処理をしている中で一般保護例外を発生させたようですね。これが割り込み周りの処理ではなく、例えばデバイスのエミュレーション処理とかであれば、途中までデバイス関連の関数だった所からexceptionとかいう名前がついた関数を呼び出すようになるので、原因部分がはっきりするのですが、これでは具体的にどこで一般保護例外が生じたのかわかりません。

そこで、intno=13という例外番号がどこででてくるのか、調べてみましょう。とりあえず、フレーム#1ではexception_index=13になっていますね。であれば、フレーム#2、つまりqemu-2.4.1/target-i386/seg_helper.cのdo_interrupt64()実行中に一般保護例外が発生している、と考えるのが妥当です。で、呼び出し元を見てみると、たしかに一般保護例外を呼び出している、と。

    if (intno * 16 + 15 > dt->limit) {

        raise_exception_err(env, EXCP0D_GPF, intno * 16 + 2);

    }

このif文、なかなかふざけていて、調べてみるとintnoが-1でdt->limitが255なんです。-1 * 16 + 15 > 255はどう考えてもfalseなわけですよ。仕方ないからdt->limitの型を調べると、unsignedっていうね。これ、意図してやってるんでしょうけど、どうなのよ、って思ってしまいましたとさ。

さて、intnoが-1である事が一般保護例外の発生要因である事がわかりました。であれば、次はどこでintnoが-1にされたのかをバックトレースで辿ります。バックトレースを睨むと、どうやらqemu-2.4.1/target-i386/seg_helper.cのx86_cpu_exec_interrupt()の中っぽいなぁ、という事が分かるので、ここのコードもまた表示してみましょう。

            int intno;

            cpu_svm_check_intercept_param(env, SVM_EXIT_INTR, 0);

            cs->interrupt_request &= ~(CPU_INTERRUPT_HARD |

                                       CPU_INTERRUPT_VIRQ);

            intno = cpu_get_pic_interrupt(env);

            qemu_log_mask(CPU_LOG_TB_IN_ASM,

                          "Servicing hardware INT=0x%02x\n", intno);

            do_interrupt_x86_hardirq(env, intno, 1);

            /* ensure that no TB jump will be modified as                                                                                                                                                   

               the program flow was changed */

            ret = true;

do_interrupt_x86_hardirqの引数にintnoを渡していますが、このintnoはcpu_get_pic_interrupt()の実行結果であることが分かります。ならば次はcpu_get_pic_interrupt()の中を見てみるしかないですね。qemu-2.4.1/hw/i386/pc.cの中を読みます。

/* IRQ handling */

int cpu_get_pic_interrupt(CPUX86State *env)

{

    X86CPU *cpu = x86_env_get_cpu(env);

    int intno;

    intno = apic_get_interrupt(cpu->apic_state);

    if (intno >= 0) {

        return intno;

    }

    /* read the irq from the PIC */

    if (!apic_accept_pic_intr(cpu->apic_state)) {

        return -1;

    }

    intno = pic_read_irq(isa_pic);

    return intno;

}

ここで-1を返すケースとなると、apic_accept_pic_intr()が0を返したか、pic_read_irq()が-1を返したか、のどちらかになります。とりあえず両方にブレークポイントを仕掛けた結果、前者である事が分かりました。次はqemu-2.4.1/hw/intc/apic.cにあるapic_accept_pic_intr()の中を読みましょう。

int apic_accept_pic_intr(DeviceState *dev)

{

    APICCommonState *s = APIC_COMMON(dev);

    uint32_t lvt0;

    if (!s)

        return -1;

    lvt0 = s->lvt[APIC_LVT_LINT0];

    if ((s->apicbase & MSR_IA32_APICBASE_ENABLE) == 0 ||

        (lvt0 & APIC_LVT_MASKED) == 0)

        return 1;

    return 0;

}

0を返してるケースなので、(s->apicbase & MSR_IA32_APICBASE_ENABLE) == 0 || (lvt0 & APIC_LVT_MASKED) == 0 がfalseになっている、という事です。まあ有り体に言えば、APICが有効でかつLVT0がUnmaskedになっている、という状況です。自分が書いているカーネルのAPIC初期化コードを見直してみると、APICを有効にしてからLVT0のMaskedフラグを立てているので、たしかにそういう状況は起こりえます。そこで、LVT0のMaskedフラグを立ててからAPICを有効にした所、何回再起動しても不可解な#GPは生じなくなりました。めでたしめでたし。

とは書いたものの、いくつか懸念点はありまして。

まず何回再起動しても#GPが生じなくなった、と書いたものの、バグ自体が不定期に起きるので(途中から起動中にキーボードを叩きまくると発生しやすくなる、という事を見つけたのですが)もしかするとバグはまだ残っているのかもしれません。

次に、そもそもstiはAPIC初期化コードとは全く関係ない(APIC初期化のはるか後でsti命令を実行する)のですが、なんでstiを実行したタイミングで例外が飛ぶのかは謎です。キューにでも溜め込まれていたんですかね。

最後に

デバッグログを垂れ流すような記事になってしまいました。

まあ実際はもっと右往左往して無関係な所を調べたりしているので、そこら辺が綺麗になっている分、多少有意義な内容になっている事でしょう。

とりあえず何が書きたかったかというと、QEMU上で変な例外とか、想定外の事態とか起きても恐れる必要はないよ!って事です。

5年前の僕であれば、意味不明な#GPが飛んでくると完全にお手上げで、カーネルを最初から作り直すという選択肢しか取れなかったのですが、(そういえば、QEMUをデバッグする事でカーネル側のバグを治す、というやり方をhigeponさんから教わったのが丁度5年前)今ではこの程度であれば、本腰を入れて調査を始めてから数時間で原因特定からのバグ修正までできるようになりました。成長を感じますね。

皆さんも、QEMUのソースコードって難しそうで読めなさそう、とか思わずにどんどんデバッグに活用しましょう。

広告

コメントを残す

以下に詳細を記入するか、アイコンをクリックしてログインしてください。

WordPress.com ロゴ

WordPress.com アカウントを使ってコメントしています。 ログアウト / 変更 )

Twitter 画像

Twitter アカウントを使ってコメントしています。 ログアウト / 変更 )

Facebook の写真

Facebook アカウントを使ってコメントしています。 ログアウト / 変更 )

Google+ フォト

Google+ アカウントを使ってコメントしています。 ログアウト / 変更 )

%s と連携中