2014年7月14日月曜日

NTP時計がフリーズするバグの特定

さて、ここのところあまりブログでは話題にしていなかったNTP時計ですが、全く何もやっていたわけではありません。実は、恐怖の「数日～十数日に1回フリーズするバグ」が起きていました。はい、バグの中では最もタチの悪いやつですね…。

このバグの原因がわかるまでは、いろいろな原因を疑っていました。算術エラー割り込みだとか、A/D変換完了待ちループにおける不具合だとか…。
症状はこんな感じでした。
  • 時計のカウントが止まる（時計の値が進まなくなる）
  • 7セグは正常に表示されている（ダイナミック点灯制御は生きている）
ここからわかることは、メインルーチンがどこかで止まっているであろうってことと、PICのクロックが停止したとかそういうハードウェア寄りの問題ではないことです。
NTPサーバーより取得した時刻はタイマ1でカウントしていますが、 「タイマ1の値を取得して時刻に変換して7セグ表示値として設定する」という作業はメインルーチンでやっています。そして、ダイナミック点灯制御は割り込みでやっています。ダイナミック点灯制御が生きていて時刻が進まないということは、割り込み自体は起こり続けているということなので、CPUが止まっているわけではありませんが、何かしらの理由でメインルーチンが動いていないということです。そのため、何かソフトウェアに由来する問題であろうことが予想されます。

頻度ですが、割とすぐに起こるようなものではなく、止まった日時は
6/26 18:30頃
7/1 7:00頃
7/4 10:00頃
7/14 6:00頃
でした。一部記録が曖昧ですが、まあおおまかな日時はこれであっているはずです。フリーズするバグだけどもダイナミック点灯制御は生きているバグだったので、止まった時刻が容易にわかるのがせめてもの救いです。
しかし、これだけ間隔があいていると、なかなかデバッグも容易ではないですね…。


まずは、算術演算エラーを疑いました。
いわゆる、ゼロ除算エラーです。PIC24Fシリーズはゼロで除算すると無限ループにはまったりするわけでもなく、ちゃんとエラーとして割り込みを起こしてくれるようです。
この割り込みのハンドラは作っていなかったので、何かの拍子にゼロ除算が起こって割り込みが発生した上で、 ハンドラで割り込みフラグをリセットしていないから割り込みから抜け出せず、しかし、PIC24Fは多重割り込みが受け付けられるので、ダイナミック点灯制御の割り込みが算術演算エラーの上で割り込まれて動作していると考えました。
しかし、この予想には、1つ重大な間違いがありました。算術演算エラー割り込みは、割り込みの優先度が11に設定されています（ユーザー変更不可）。しかし、周辺モジュールや外部割込みの優先度は0～7にしか設定できず、すなわち、どんな周辺モジュール割り込みよりも先に算術演算エラー割り込みは起こり、算術演算エラー割り込み中に周辺モジュールが割り込みを起こすことはありえません。
すなわち、この予想は間違っていると言えます。

次に、A/D変換の終了待ちの問題を疑いました。
A/D変換は時間がかかるので、通常、開始の指示を出してからしばらくして終了しているかを確認し、値を読み出します。その終了の認識の方法は、無限ループでフラグをポーリングし続けて確認するだとか、割り込みで確認するだとか、いくらかあります。今回、NTP時計では無限ループの方法を使用していました。

AD1CON1bits.SAMP = 1;
while(!AD1CON1bits.DONE);

これ自体は何もおかしくないコードです。実際、MicrochipのA/D変換のドキュメンテーションにもこのように無限ループでポーリングし続けて変換完了を待つサンプルプログラムが書いてあります。
もしも、これが何かしらの問題で変換が終わってもAD1CON1bits.DONEが1になってくれなかったら、ここでプログラムが止まってしまいます。 要するにハードのバグを疑いました。しかし、そんな記事ググっても無ければ、実際にここで止まっている保証もありません。しかし、原因がわからないと疑心暗鬼になってしまって、特にこういう条件次第では無限ループになりそうなところを疑ってみたくなってしまうんですね…。


フリーズの原因を特定するために、いわゆるprintfデバッグと呼ばれるものの類のコードを実装してみました。
液晶は電源さえ入っていれば表示内容を保持するので、マイコンが何かしらの原因で止まっても、液晶は表示を保ってくれます。なので、特定のコードを通過したときに特定の何かしらの文字列を表示させるプログラムを実行しておけば、何が表示されているかでフリーズ箇所を絞れるというものです。

実際には文字列を出力したわけではなく、点を液晶に打ちました。実際に時計として使いながらのデバッグなので、あまり表示内容を乱したくないですしね。
最初はある一定の処理を終えるごとに点を1つずつずらしていくプログラムにしましたが、いざフリーズしてみると、確かに点が表示されているのはわかるものの、それが何段目のピクセルなのか判別がとてもじゃないですがつきません。それくらい予想してプログラム書けばよかった…。

というわけで、次は線にして、線の長さを順に伸ばしていくようにしました。それなら、一生懸命ドット数を数えればエラー箇所がわかります。
実際は、小型液晶ゆえにドットの個数を肉眼で数えるのは厳しいです。なので、フリーズしたら写真で撮って拡大して見ました。

はい、その写真がこちらになります。


画面の右下にドットを打ってありますが、6つのドットが表示されていることがわかります。

で、6ドット分の線が表示されているときに実行中のプログラムはどこかなと思ってソースコードを見てみたら、A/D変換を終えて7セグの明るさの設定値をセットする関数でした。A/D変換の完了待ちではありません。
で、問題のコードがどうなっていたかというと、こうなっていました。

void LED7SEG_SetBrightness(uint8_t value)
{
    uint32_t buf = value + 1ul;

    buf = (uint64_t)buf * buf * buf * PWM_PERIOD / (256ul * 256 * 256);

    PWMOnStart = PWM_PERIOD - buf;
    PWMOffStart = buf;

    PWMOnStart = min(PWMOnStart, PWM_PERIOD);
    PWMOffStart = min(PWMOffStart, PWM_PERIOD);

    Brightness = value;
}

この中で疑わしいところを探します。
掛け算とか割り算とかキャストとかは実際XC16コンパイラがどんなふうに展開しているかが見えないところなのでそういうところについつい目が行ってしまいますが、そこは信用するとした場合、もう残っているのはPWMOnStart変数等に代入しているところくらいしかありません。

( ˘⊖˘) 。o(待てよ…)

このPWMOnStartやPWMOffStartという変数は、7セグのダイナミック点灯用の割り込み中にも呼び出されるものです。
こういう、メインルーチンと割り込みルーチンの両方から参照される変数には細心の注意を払う必要があります。過去から現在にわたってプログラマーを苦しめ続けているマルチスレッドのトラウマ的存在としてとても有名なものです。 

void _ISR __attribute__((__auto_psv__)) _T2Interrupt(void)
{
    static uint8_t cnt;
    IFS0bits.T2IF = 0;

    if(cnt++ & 0x01) {
        TMR2 = PWMOnStart;

        Show7SEG();
        LED_COLON = Colon;
    } else {
        TMR2 = PWMOffStart;

        LATA &= ~(MASK_7SEG_RA | MASK_7SEGTR_RA);
        LATB &= ~(MASK_7SEG_RB | MASK_7SEGTR_RB);
        LATC &= ~(MASK_7SEG_RC | MASK_7SEGTR_RC);
        LED_COLON = 0;
    }
}

こうやって割り込み中に7セグのON時間やOFF時間を制御するのに使っています。
PWMOnStartとPWMOffStartは0～PWM_PERIODの値になり、TMR2はPWM_PERIODになると割り込みが入るようにコンパレーターをセットしています。PWMOnStartやPWMOffStartが極端にPWM_PERIODに近かった場合、割り込み処理中に次の割り込みが入ってしまい、すなわち、_T2Interrupt関数を抜けた瞬間に再び_T2Interrupt関数に入ってしまいますが、PWMOnStartとPWMOffStartは足してPWM_PERIODになるようにしてありますので、片方が極端にPWM_PERIODに近くてももう片方は近くなくなるので、そっち側でメインルーチンにCPUを割くことができます。

はい、上の表現、めちゃくちゃ強調している意味、わかるひとにはわかりますね。

本当に、常に足してPWM_PERIODになるの？


こういう複数のスレッドにまたがって使われる変数は、一連の変数書き換えシーケンス中に割り込みが起こった場合を想定する必要があります。

もうお分かりでしょう。
LED7SEG_SetBrightness関数の5行目、PWMOnStartの値が代入されてから、次の行でPWMOffStartの値が代入されるまでの間にタイマ2の割り込みが入ったらどうなるでしょう？
しかも、もともとはPWMOffStartが極端にPWM_PERIODに近い値で、 次にPWMOnStartを極端にPWM_PERIODに近い値にしようとしたタイミングでの割り込みだったらどうなるでしょう？

両方とも、極端にPWM_PERIODに近い値で割り込みが入っちゃうんです。

そうなった場合、もうおしまいです。7セグのON表示処理をし終わったら直ちにOFF表示処理がされ、それが終わったら直ちにON表示処理を…といった状態になってしまい、二度と割り込みルーチンから抜けることがなくなってしまいます。

これが今回のバグの原因だったんですね。


さて、ここまででこれがバグの原因だったということで片がつきました。しかしそれは情況証拠であって検証したわけではありません。そもそも、数日経ってやっと発動するかどうかのバグなのに、安定動作してると主張するには一体何日待てば良いのよって話です。
しかし、ラッキーなことに、この変数書き換え中の割り込みがフリーズの原因だった場合、フリーズの状態からそれを裏付けることができます。

それは、7セグの明るさです。

バグがあったとされたのは7セグのON処理時とOFF処理時の時間の長さを変えることで7セグの明るさを調節するプログラムですが、このバグが発動して割り込みルーチンから抜けられていないときは、ON処理とOFF処理の時間がともに最小で終わってしまっているということです。すなわち、デューティー比はおよそ1:1、少なくとも「明るいモード」や「暗いモード」の間の明るさに見えるはずです。

はい、実際に見比べてみましょう。
そのためには、外が真っ暗な時間に部屋の蛍光灯を付けて、同じ位置から同じ露出設定で写真を撮ってみれば、写真として客観的に明るさを見られますね。


上からフリーズ状態、輝度最高、輝度最低のモードです。
本当は三脚使って完全に定点撮影にすればよかったんでしょうが、面倒だったので同じ位置に立って手持ちで撮影しました。

もう一目瞭然ですね。写真でも明るさの違いがよくわかります。

というわけで、原因はこれで確定ってことで良いでしょう。

対策は簡単です。PWMOnStartとPWMOffStartの書き換え中は割り込みを禁止してやればいいだけです。

void LED7SEG_SetBrightness(uint8_t value)
{
    uint32_t buf = value + 1ul;

    buf = (uint64_t)buf * buf * buf * PWM_PERIOD / (256ul * 256 * 256);

    LED7SEG_DisableInterrupt();

    PWMOnStart = PWM_PERIOD - buf;
    PWMOffStart = buf;

    PWMOnStart = min(PWMOnStart, PWM_PERIOD);
    PWMOffStart = min(PWMOffStart, PWM_PERIOD);

    Brightness = value;

    LED7SEG_EnableInterrupt();
}

はい、これでPICを書き換えて完成です。
このように、途中でスレッドが切り替わってはいけない部分のことを、プログラミング用語で「クリティカルセクション」と言います。C言語にはそのような機能はありませんが、言語によってはそれを実現するための機能があるものもあります。
マルチスレッドでは、片っ端から「ここでもし割り込みが起こったらどうなる？」ということを念頭に置いてプログラムを書かなければなりません。すごく大変なことですが、それを怠ると今回みたいなバグを誘発してしまいますし、何しろこの手のバグは再現性がなかなか無いので原因を探るだけでも一苦労です。こういうバグを出さない、もしくは出してもこれが原因だと断定できるようになるまでは結構なプログラミングの習熟度が必要かと思いますが、まあ、この記事を読んでくださった皆さんももしこのような再現性の低いバグに出会った時は、この記事のことを思い出してくれればなと思います。


これで安定して動作してくれ～～～～～～
投稿者 時刻:
ラベル: , , , , , , ,

0 件のコメント:

コメントを投稿

登録: コメントの投稿 (Atom)