はじめに
ウォッチドグタイマは、もしハングアップしても致命傷にならないようにするのに大変便利な機能です。でも、開発中にウォッチドグタイマによるリセットがかかった時、どこに原因があるのかを特定しておくのは大変重要です。
今回Arduino（ATMEGA1284）でウォッチドグタイマをいじることがあったので、ウォッチドグタイマの発生源を特定する方法をいろいろ試行錯誤したので、そのまとめです。
動作環境
最初はArduino MEGAでざっとの構築を行い、その後Atmega1284を使った基板を起こしそこで最終デバッグを行いました。
開発環境はArduino 1.8.5を使いました。
他のATMEGAを搭載したArduinoやATMEGAでも使える手法だと思いますが、確認していないのでもしこの方法で確認出来たらコメントいただけると皆さんの役に立てるかと思います。
どうやって原因を特定するか？
ウォッチドグタイマは一定時間内にwdt_reset();を呼ばないと割込みがかかり、その割込みでリセットをかけるという仕組みです。ですので、ウォッチドグタイマの割り込みルーチンで、そのリターンアドレスを記録しておけば、どこで割込みがかかったかが特定できます。
探してみたら、per1234/WatchdogLog https://github.com/per1234/WatchdogLogにありました。
ここからWatchDogLog.cpp, WatchDogLog.hを対象のプロジェクトフォルダに入れて
# include "WatchdogLog.h"
const unsigned int EEPROMaddress = 0; // EEPROMのこのアドレスからスタックが書き込まれる
void setup()
{
Serial.begin(115200);
while (!Serial) {};
...何かの処理...
unsigned long programAddress;
EEPROM.get(EEPROMaddress, programAddress);
if (programAddress > 0) {
Serial.println(programAddress, HEX);
programAddress = 0;
EEPROM.put(EEPROMaddress, programAddress); // 記録していたスタックアドレスをゼロクリア
}
...何かの処理...
wdt_enable(WDTO_8S); // 8秒間隔でのwatch dog timer
WatchdogLog.begin(0); // ここでは０だが保存すべきEEPROMのオフセットを指定します。
}
void loop()
{
...何かの処理...
wdt_reset(); // 8秒以上にならないように、必要な場所に入れておきます
}
とすれば、ウォッチドグタイマの発動した場所がprogramAddressとなるので簡単にわかります。
programAddressってどこ？
簡単にわかるといいながら、その場所ってどこなのでしょう。
まず、Arduino IDEのファイル － 環境設定 で設定タブの 「より詳細な情報を表示する」－「コンパイル」にチェックを入れます。その状態でコンパイルをすると、いっぱいメッセージが表示されますが
"C:\Users\(ユーザ名)\AppData\Local\Arduino15\packages\arduino\tools\avr-gcc\4.9.2-atmel3.5.4-arduino2/bin/avr-objcopy" -O ihex -R .eeprom "C:\Users\(ユーザ名)\AppData\Local\Temp\arduino_build_611234/watchdogtest.ino.elf" "C:\Users\(ユーザ名)\AppData\Local\Temp\arduino_build_611234/watchdogtest.ino.hex"
次のフォルダのライブラリSPIバージョン1.0を使用中：C:\Users\(ユーザ名)\AppData\Local\Arduino15\packages\arduino\hardware\avr\1.6.21\libraries\SPI
次のフォルダのライブラリEthernet2バージョン1.0.4を使用中：C:\USR\SRC\Arduino\arduino-1.8.5\Arduino\libraries\Ethernet2
次のフォルダのライブラリNTPClientバージョン3.1.0を使用中：C:\USR\SRC\Arduino\arduino-1.8.5\Arduino\libraries\NTPClient
次のフォルダのライブラリEEPROMバージョン2.0を使用中：C:\Users\(ユーザ名)\AppData\Local\Arduino15\packages\arduino\hardware\avr\1.6.21\libraries\EEPROM
次のフォルダのライブラリWireバージョン1.0を使用中：C:\Users\(ユーザ名)\AppData\Local\Arduino15\packages\arduino\hardware\avr\1.6.21\libraries\Wire
最大131072バイトのフラッシュメモリのうち、スケッチが47978バイト（36%）を使っています。
最大16384バイトのRAMのうち、グローバル変数が1086バイト（6%）を使っていて、ローカル変数で15298バイト使うことができます。
見るべきところは、"C:\Users(ユーザ名)\AppData\Local\Temp\arduino_build_611234/watchdogtest.ino.elf"のところで、まず要はこのelfファイルをコピーしてきます。
そして、次のバッチファイルを作っておいて実行します。
(Arduino IDEのインストールしてある場所)\hardware\tools\avr\bin\avr-objdump.exe -I watchdogtest.ino -d -S -j .text .\watchdogtest.ino.elf > watchdogtest.asm
とすれば、逆アセンブルした watchdogtest.asm が出来上がります。
アセンブラなんかわからないという人もいるでしょうが、大丈夫です。ソースファイルが埋め込まれているので大体わかります。
で表示されたアドレスが4525(16進)だったとして、4525なんてASMファイルの中にないのです！
Atmegaシリーズのアセンブリコードはワード毎に置くようになっているのでそれを1/2して記録されるようになっています。ですので128KBまでのフラッシュメモリのCPUであれば2バイトで表現できてしまいます。（128kB以上のCPUは使ったことがないのでわかりません）
ということで、実際のアドレスは4525x2=8a4aとなります。
この部分のコードがどうなっているかというと
8a28: 08 95 ret
00008a2a <delay>:
8a2a: 8f 92 push r8
8a2c: 9f 92 push r9
8a2e: af 92 push r10
8a30: bf 92 push r11
8a32: cf 92 push r12
8a34: df 92 push r13
8a36: ef 92 push r14
8a38: ff 92 push r15
8a3a: 6b 01 movw r12, r22
8a3c: 7c 01 movw r14, r24
8a3e: 0e 94 f0 44 call 0x89e0 ; 0x89e0 <micros>
8a42: 4b 01 movw r8, r22
8a44: 5c 01 movw r10, r24
8a46: c1 14 cp r12, r1
8a48: d1 04 cpc r13, r1
8a4a: e1 04 cpc r14, r1
8a4c: f1 04 cpc r15, r1
8a4e: 01 f1 breq .+64 ; 0x8a90 <delay+0x66>
8a50: 0e 94 db 4e call 0x9db6 ; 0x9db6 <yield>
8a54: 0e 94 f0 44 call 0x89e0 ; 0x89e0 <micros>
となって、8a4a:の行のところから、さかのぼって ret が出てくる行の次の関数内でタイムアウトしたということがわかります。
めでたし、めでたし。
と言いたいところですが、実はこれでは何も情報を得られません。
何故なら、あちこちからdelayは呼ばれているので有益な情報になっていないのです。
実際、何度かウォッチドグが発生した経験からは、delay,yield,microsの中で最初のアドレスが見つかることがほとんどでした。まあ、実際delayさせているので、その中で見つかる可能性は大でしょう。
ではどうするか？
ならば、さらにさかのぼって調べてやればいいのです。
ということでWatchDogLog.cppの改造です。標準では2バイト分でしたが、32バイト分記録するようにしました。
ISR(WDT_vect, ISR_NAKED) {
register uint8_t *programCounter;
programCounter = (uint8_t*)SP;
// programCounter += programCounterSize;
WatchdogLog.writeLog(programCounter);
}
void WatchdogLogClass::writeLog(uint8_t *programCounter) {
wdt_disable();
uint8_t *_sp = programCounter;
uint16_t p = EEPROMbaseAddress;
for(int i = 0; i < 32; i++) {
uint8_t v = *++_sp;
EEPROM.write(p++, v);
}
wdt_enable(WDTO_15MS);
while (true) {};
}
元のコメントは長くなるので省いています。
# include "WatchdogLog.h"
const unsigned int EEPROMaddress = 0; // EEPROMのこのアドレスからスタックが書き込まれる
void setup()
{
Serial.begin(115200);
while (!Serial) {};
...何かの処理...
unsigned long programAddress;
EEPROM.get(EEPROMaddress, programAddress);
if (programAddress > 0) {
uint8_t c;
for(int i = 0; i < 32; i++) {
c = EEPROM.read(EEPROMaddress + i);
String s = String(c, HEX);
if (s.length() == 1)
s = "0" + s;
Serial.print(s);
Serial.print(" ");
programAddress = 0;
EEPROM.put(EEPROMaddress, programAddress); // 記録していたスタックアドレスをゼロクリア
}
}
...何かの処理...
wdt_enable(WDTO_8S); // 8秒間隔でのwatch dog timer
WatchdogLog.begin(0); // ここでは０だが保存すべきEEPROMのオフセットを指定します。
}
void loop()
{
...何かの処理...
wdt_reset(); // 8秒以上にならないように、必要な場所に入れておきます
}
こうすると、さらに上までさかのぼれます。
実際にさかのぼってみた
実際に出たエラーの例として、
45 25 01 ce 00 50 00 02 00 02 36 86 3f a0 3f d0 40 00 eb 2a 72 5a 02 31 d4 c7 3b fe 96 85 54 f9
の様に出力されるのですが、先ほどと同じように45 25 は4525x2=8a4aとなります。そこから上に進んでいって ret が出てくる行の次が今いる関数です。
8a28: 08 95 ret
00008a2a <delay>:
8a2a: 8f 92 push r8
8a2c: 9f 92 push r9
8a2e: af 92 push r10
8a30: bf 92 push r11
8a32: cf 92 push r12
8a34: df 92 push r13
8a36: ef 92 push r14
8a38: ff 92 push r15
8a3a: 6b 01 movw r12, r22
8a3c: 7c 01 movw r14, r24
8a3e: 0e 94 f0 44 call 0x89e0 ; 0x89e0 <micros>
8a42: 4b 01 movw r8, r22
8a44: 5c 01 movw r10, r24
8a46: c1 14 cp r12, r1
8a48: d1 04 cpc r13, r1
8a4a: e1 04 cpc r14, r1
8a4c: f1 04 cpc r15, r1
8a4e: 01 f1 breq .+64 ; 0x8a90 <delay+0x66>
8a50: 0e 94 db 4e call 0x9db6 ; 0x9db6 <yield>
8a54: 0e 94 f0 44 call 0x89e0 ; 0x89e0 <micros>
で、次のアドレスを計算するのですが、ret の次に push がいっぱい(8個)並んでいます。このpushの数だけ飛ばして次は 36 86 になります。3686x2=6d0c
6d00: 61 e0 ldi r22, 0x01 ; 1
6d02: 70 e0 ldi r23, 0x00 ; 0
6d04: 80 e0 ldi r24, 0x00 ; 0
6d06: 90 e0 ldi r25, 0x00 ; 0
6d08: 0e 94 15 45 call 0x8a2a ; 0x8a2a <delay>
if (status() == SnSR::CLOSED) {
6d0c: ce 01 movw r24, r28
6d0e: 0e 94 24 36 call 0x6c48 ; 0x6c48 <_ZN14EthernetClient6statusEv>
6d12: ea cf rjmp .-44 ; 0x6ce8 <_ZN14EthernetClient7connectE9IPAddressj+0x84>
_sock = MAX_SOCK_NUM;
return 0;
}
6d0c:の前の行に call <delay> とありますね。つまり、delayを呼び出したのがそのcallで戻り先が6d0c:ということなのです。
同じように、ret が出てくるまでさかのぼると。
6c60: 80 e0 ldi r24, 0x00 ; 0
6c62: 08 95 ret
00006c64 <_ZN14EthernetClient7connectE9IPAddressj>:
} else {
return ret;
}
}
int EthernetClient::connect(IPAddress ip, uint16_t port) {
6c64: cf 92 push r12
6c66: df 92 push r13
6c68: ff 92 push r15
6c6a: 0f 93 push r16
6c6c: 1f 93 push r17
6c6e: cf 93 push r28
6c70: df 93 push r29
if (_sock != MAX_SOCK_NUM)
と int EthernetClient::connect(IPAddress ip, uint16_t port) 関数内から呼ばれたとわかります。今回はここまで特定できれば十分だったのですが、さらにさかのぼる必要があれば繰り返せば大丈夫です。
その場合、保存するEEPROMの領域も広げておく必要があります。
※スタックのダンプリストは、実際の物をちょっといじってあります。もし、矛盾があったら、ごめんなさい。