ESP32トラブル The fllowing tasks did not reset the watchdog in time

ESP32をWebサーバ（AsyncWebserver）として動かしてる時にシリアルモニターに下のようなエラーが発生して、システムが強制リセットされて、困ったという話です。

E (38035) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (38035) task_wdt: – async_tcp (CPU 0/1)
E (38035) task_wdt: Tasks currently running:
E (38035) task_wdt: CPU 0: IDLE
E (38035) task_wdt: CPU 1: loopTask
E (38035) task_wdt: Aborting.

abort() was called at PC 0x400ebbf5 on core 0

Backtrace:0x40083575:0x3ffbe9ec |<-CORRUPTED

ELF file SHA256: 0000000000000000

Rebooting…

動かしていたプログラムはWebサーバと同時にアクチュエータなどを制御させていたので、ネットワークサイドの都合で、マイコンにリセットがはいるのは、ちょっと許容できませんでした。ここでは、その原因と対策結果をまとめています。

ウォッチドッグタイマー

エラーを確認すると、ウォッチドッグトリガーが発生したよ的な内容です。ウォッチドッグタイマー(TWDT)とは、各CPUで実行されるタスクを監視しているタイマーで、一定時間以上、特定のタスクがCPUを占有した場合に割り込みを発生させ、システムをリセットさせる機能があります。今回の問題は、どこかのタスクで処理時間がかかり過ぎたため、この機能によりシステムリセットを引き起こしてしまったようです。

ウォッチドッグタイマーの動きを理解する為、下の簡単なコードで動きを確認してみます。

#include <esp_task_wdt.h>
#define TIMEOUT 3

void setup() {
  Serial.begin(115200);
//watchdogタイマーの初期化
//  第一引数:リセット時間
//  第二引数:リセット実施(trueでリセット,falseでlogのみ）
  esp_task_wdt_init(TIMEOUT, true);
//watchdogで監視するタスクの登録
//  第一引数:タスクのハンドル(NULLで現在のタスク)
  esp_task_wdt_add(NULL);
}

int tCur = millis();
int i = 0;

void loop() {
  // 1sec毎にesp_task_wdt_reset()を呼び、タイマーをリセットする
  if (millis() - tCur >= 1000) {
      Serial.println("Reset WDT");
      esp_task_wdt_reset();
      tCur = millis();
      i++;
  }
}

上のコードでTIMEOUTでwatchdog triggerがかかるまでの時間を3秒にしています。main loopで1秒ごとにesp_task_wdt_reset()をコールして、手動でタイマーリセットしています。

この状態なら、問題は発生しませんが、リセット間隔を3秒より大きくすると、シリアルモニター上で下のようなエラーが発生しだします。

E (6101) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (6101) task_wdt: – loopTask (CPU 1)
E (6101) task_wdt: Tasks currently running:
E (6101) task_wdt: CPU 0: IDLE
E (6101) task_wdt: CPU 1: loopTask
E (6101) task_wdt: Aborting.

abort() was called at PC 0x400d7279 on core 0

Backtrace:0x40082e19:0x3ffbe77c |<-CORRUPTED
ELF file SHA256: 0000000000000000

Rebooting…

ちなみに、何もしなければ、main loopに関しては、ウォッチドックタイマーの通常設定は、offになっているので、今回のようにタイマーリセット処理を明示的にやる必要はありません。

負荷のかかる処理の前に

あらかじめ、プログラムで負荷のかかるような場所が分かっている場合、そこの箇所だけウォッチドッグをオフにすることもできます。下のようなサンプルスケッチを書いてみました。

#include <esp_task_wdt.h>
#define TIMEOUT 3

void setup() {
  Serial.begin(115200);
  esp_task_wdt_init(TIMEOUT, false);
  esp_task_wdt_add(NULL);
}

int tCur = millis();
int i = 0;

void loop() {
  esp_task_wdt_delete(NULL);
  tCur = millis();  
  
  Serial.println("wdt is off");  
  //ループ1
  while (millis() - tCur < 10000) {
  }
  esp_task_wdt_add(NULL);

  tCur = millis();  
  Serial.println("wdt is on");
  //ループ2
  while (millis() - tCur < 10000) {
  }
}

下が、実行結果です。一回目のループはesp_task_wdt_delete(NULL)によりウォッチドッグを無効化した為、エラーがでませんが、二回目のループはウォッチドッグを有効化したので、エラーが発生しました。

wdt is off
wdt is on
E (826101) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (826101) task_wdt: – loopTask (CPU 1)
E (826101) task_wdt: Tasks currently running:
E (826101) task_wdt: CPU 0: IDLE
E (826101) task_wdt: CPU 1: loopTask
E (826101) task_wdt: Print CPU 0 (current core) backtrace

HTTPレスポンスでエラー発生

実際に自分のプログラムで上記のようなウォッチドッグエラーがでるタイミングを調べてみたところ、ESP32がクライアント側へデータ送信する箇所で発生してました。

具体的には、ページに使用するWebフォントなどを送る箇所で、たしかに処理が重くなりそうな所だといえます。

void onIconRequest(AsyncWebServerRequest *request) {
  IPAddress remote_ip = request->client()->remoteIP();
  Serial.println("[" + remote_ip.toString() +
                  "] HTTP GET request of " + request->url());
  request->send(SPIFFS, "/iconfont/iconwoff.woff2", "text/plain");
}

ブラウザからのアクセスが数回程度なら問題ありませんが、ブラウザ上で、狂ったようにユーザが更新ボタンを連打するなどしたときにエラーが頻発するようになります。

AsyncWebserverのライブラリではasync_tcpというタスクが動いていますが、このような不具合発生時にどの程度のキューがたまっていたのかを確認してみました。

不具合を確認しやすいように事前にAsyncWebserverのライブラリ(AsyncTCP.cpp)の一部を修正します。通常なら、ライブラリは以下のパスにあります。

C:\Users\<USERNAME>\Documents\Arduino\libraries\AsyncTCP\src

変更箇所は、下の関数でキューで保持するデータサイズを32から16に設定変更します。

static inline bool _init_async_event_queue(){
    if(!_async_queue){
        //_async_queue = xQueueCreate(32, sizeof(lwip_event_packet_t *));
        _async_queue = xQueueCreate(16, sizeof(lwip_event_packet_t *));
        if(!_async_queue){
            return false;
        }
    }
    return true;
}

現在のキューの数を確認するには、以下のようにします。

Serial.printf("uxQueueMessagesWaiting = %d\n", uxQueueMessagesWaiting(_async_queue)); 

下が実行結果です。キューが保持しているデータ数がリミットになった瞬間にリセットがはいってしまうことが分かります。どうやらキューが満タンになると何かしらの原因でウォッチドッグエラーとなってしまうようです。

このため、下のようにデータサイズを256にひろげると、リセット不具合は、一気に解消されました。

       _async_queue = xQueueCreate(256, sizeof(lwip_event_packet_t *));

また、ライブラリを確認すると、CONFIG_ASYNC_TCP_USE_WDTの値を0とした時にwatchdogタイマーを無効化するような関数が実装されてました。

static void _async_service_task(void *pvParameters){
    lwip_event_packet_t * packet = NULL;
    for (;;) {
        if(_get_async_event(&packet)){
#if CONFIG_ASYNC_TCP_USE_WDT
            if(esp_task_wdt_add(NULL) != ESP_OK){
                log_e("Failed to add async task to WDT");
            }
#endif
            _handle_async_event(packet);
#if CONFIG_ASYNC_TCP_USE_WDT
            if(esp_task_wdt_delete(NULL) != ESP_OK){
                log_e("Failed to remove loop task from WDT");
            }
#endif
        }
    }
    vTaskDelete(NULL);
    _async_service_task_handle = NULL;
}

AsyncTCP.hを編集して、CONFIG_ASYNC_TCP_USE_WDTの数値を1から0に変更します。これにより、キューが満タンになった際にもウォッチドッグエラーとならず、システムリセットを避けることができます。

#define CONFIG_ASYNC_TCP_USE_WDT 0 //default 1

以上の修正で、起こっていた問題はめでたく解決できました。ばんざい ウォッチドッグ無効化。