【Arduino】比較演算が極稀に失敗する不具合に遭遇した話
これはここ数年Arduinoでの開発をやっていて、一番不条理だと感じた不具合の話です。
単純な比較演算処理に失敗する――そんなことが起こり得るのか？
順を追って説明していきます。
ちなみに本件ではSparkfun社製Pro Micro（5V/16MHz、チップはAtmega32U4）を利用しています。
ATMega328系のArduinoで同種の不具合が発生するかは未検証です。
顛末
ある案件で「マスタからの命令に応じて、2回のパルスを指定された時間間隔で発信する」*1Arduinoのプログラムを実装していたときのこと。
私はその間隔の計測にタイマ割込みを利用することにしました。
「408usごとに1回割込み処理が走るようにタイマを設定し、割込み回数のカウンタが予め計算しておいた規定回数を上回ったら次のパルスを発信する」というロジックです。
パルスの間隔は最長で120sほど開くためカウンタ変数の型はint*2では全く足りず、unsigned long*3にすることになりました。
1割の確率で想定より短いパルス間隔になってしまった
一通り実装を終えテストを開始してみると、パッと見うまく行っているように見えます。
それならと意気揚々と長時間試験を実施したところ、思いがけない不具合が発生しました。
10回、20回とパルスを発信していると、そのうちの1～2回だけ、指定した間隔よりも実際のパルス間隔が少しだけ短くなってしまっているのです。
調べてみると、ズレ幅は長くても指定した間隔の1割程度*4。指定時間が同じなら、ズレ幅はほぼ一定のようでした。
コレではマズいので、考えられる限りの原因を虱潰しに当たっていきます。
タイマの設定は誤っていない
最初に考えた原因がコレ。
「408usごとに1回呼び出される」はずのタイマ割込みが、実際にはもっと短い間隔で呼び出されているのではないか？
結論から言うとこれはハズレ。デバッグ用にタイマ割込みが発生するごとにパルスが発生するよう改造してオシロスコープで測定してみたところ、パルスは正しく408us間隔で発生していました。
計算した規定回数は誤ってない
次に考えた原因がコレ。
規定回数は指定時間を408usで除算することで得ているが、何かの拍子でこの規定回数が狂ったのではないか？
結論から言うとこれもハズレ。ロジック終了後に規定回数分だけ*5パルスを発信するように改造してオシロスコープで測定してみたところ、正常なパターンと異常なパターンの間で規定回数に変化は見られませんでした。
カウンタの値が誤っている
タイマの設定は合っている。規定回数も合っている。
ならば考えられる原因は「カウンタが規定回数に到達する前にロジックを抜けてしまった」。コレしかない。
そこで、ロジック終了後にカウンタ分だけ*6パルスを発信するように改造してオシロスコープで測定してみました。
すると正常パターンと異常パターンの間でパルス数に違いが見られました。
ズレの原因はここだったのです。
しかしなぜそのような現象が起こるのかわからなければ、修正しようがありません。
カウンタと規定回数の比較条件式自体が間違っているわけではありません*7。
それ以外のなにか偶発的な要因で不具合が生じているわけです。
異常時のカウンタ値には法則性があった
「不正なパターンではカウンタ値に何かしらの法則性があるのではないか？」
そう考え、私はカウンタ値がシリアルモニタに出力されるように改造してカウンタ値をチェックしました。
500msを指定して確認してみると、正常パターン1225回に対して、異常パターンはいずれもカウンタ値が1024回。
「ヤケにキリのいい数字だな」と思い、他の時間指定についても試してみました。
1000msであれば異常パターンはいずれも2304回、2000msであればいずれも4864回。
この3つの数字には共通点があります。
16進数で表記すると、1024=0x0100、2304=0x0900、4864=0x1300。
いずれも上2桁は正常パターンと同じ数値、下2桁が0x00になるのです。
念の為時間が極端に長い場合、60000msについても確認してみます。
すると異常カウンタ値が、131072回と146944回の2種類にわかれました。
これらは16進数で表記するとそれぞれ、0x020000と0x023E00です。
上3パターンと異なり、下2桁だけでなく下4桁が0のパターンも現れるようになりました。
仮説
この不具合、最初は原因がわからず、カウンタ値に追加の条件*8を設けることで場当たり的に対処していました。
しかしふと一つの仮説に思い当たりました。
「条件判定の途中でタイマ割込みが掛かって判定が狂ったのでは？」
パルス発信関連のロジックは概ね下記の通りでした。
volatile unsigned long g_timer_tick; // 408usごとに1増える // （略）タイマ割込み時処理 void sendPulse(int wait_ms){ unsigned long count = wait_ms * 1000 / 408; // （略）前パルス発信処理 timer_start(); // タイマを開始する while(g_timer_tick < count){} // 【これが条件式】 timer_stop(); // タイマを終了する // （略）後パルス発信処理 }
上記の条件式は、一見すると単一の式でありそれ以上には分割できない（途中でタイマ割込みなど起こり得ない）ように見えます。
しかしタイマなどの各種割込み処理はアセンブリレベルで処理されるため、C言語で単一式であってもその途中で割込みは起こり得るのです。
Arduinoのスケッチがどうコンパイルされるのか把握しているわけではないので正確なことは言えませんが、アセンブリの各種比較命令で扱えるのは8bit長のみ（のはず）。
つまり、16bit長のintや32bit長のlongはアセンブリレベルでは8bit毎に分解して比較せざるを得ないわけです。
（あくまで推測ですが）異常パターンは、下記のような流れで発生してしまったものと思われます。
検証
本当に不具合の原因が条件判定中のタイマ割込みであった場合、修正は簡単です。
条件判定中のタイマ割込みを禁止すればよいのです。
タイマ割込みを含む全ての割込みは、cli関数で割込み禁止、sei関数で割込み許可となります。
なので、条件式をcli関数とsei関数で挟んでしまえば修正完了です。
void sendPulse(int wait_ms){ // （略） while(true){ bool is_over; cli(); // 割込みを禁止 is_over = g_timer_tick < count; // 【条件判定を割込み禁止下で行う】 sei(); // 割込みを許可 if(is_over){ break; } } // （略） }
実際に上記の通り修正してみると、異常パターンは全く現れなくなりました。
異常パターンが「条件判定中のタイマ割込み」であることは、ほぼ疑いようがないでしょう。
まぁ、「条件判定中にタイマ割込みが発生したとして、それがそんなに高確率で不具合を引き起こすものなのか？」とか、「この理屈なら、longの比較演算以外のあらゆる処理で同種の不具合が発生しうるのでは？」とか、正直なところまだいくつか疑問点は残ってます。
その辺余裕があれば調べたいところではあるけど、余裕があるかと言われると微妙なところ…。
結論
タイマ割込みが頻繁に発生する中での比較演算（特にunsigned long同士の比較）は、割込み禁止にしてから行うべき。
