方言を話すおしゃべり猫型ロボット『ミーア』をリリースしました（こちらをクリック）

【ESP32】ESP-IDFへの移行後に発生したMQTT通信後のスタックオーバーフローエラー対処法

mqtt-stack-oveflow
2024.06.02
この記事は約19分で読めます。

はじめに

現在、方言を話すおしゃべり猫型ロボット「ミーア」を開発中。

https://mia-cat.com

以前、こちらの記事で、VS Code上のPlatformIO IDEでArduinoだけではなくESP-IDFフレームワークに対応した。

【ESP32 × PlatformIO】フレームワークをArduinoとESP-IDFで併存する方法
PlatformIOでArduinoとESP-IDFのフレームワークを併用することができる。platform.iniにframework = arduino, espidf と設定することで既存の多くのArduinoライブラリを直接利用できるため、コードのポーティングや書き直しの手間を省くことができる。
kazulog.fun
2024.07.01

ようやくビルドできるようになって、ホッとしたのも束の間、SmartConfig経由でWifi接続後にMQTT通信を確立したら、下記エラーが出て、延々と再起動するようになった。

ShellScript
SyncShadow is already started
MQTTPubSubClient::onMessage: $aws/things/XXXXXXX
***ERROR*** A stack overflow in task loopTask has been detected.
Backtrace: 0x400829fa:0x3ffbdec0 0x401684e5:0x3ffbdee0 0x4008a3d2:0x3ffbdf00 0x4008c622:0x3ffbdf80 0x4008a548:0x3ffbdfa0 0x4008a4fa:0x3ffbe020 0x4008a548:0x0000523a |<-CORRUPTED

ELF file SHA256: a98d6ccbac74aac1
Rebooting...

今回は、上記エラー対応を記載。

loopTaskとは何か

loopTaskはESP32プログラムのメインループタスクを指す。これは、Arduinoフレームワークでのloop()関数に対応しており、ESP32上で実行される無限ループのタスク。なので、main.cppに記載されているvoid loop()内の再帰処理に原因がある可能性が高い。

スタックオーバーフローの原因

スタックオーバーフローは、タスクが割り当てられたスタックメモリを使い果たしてしまう現象。これには以下のような原因がある。

  1. 過度の再帰呼び出し: 関数が再帰的に呼び出され、スタックを使い果たす。
  2. 大きなローカル変数: 一時的なローカル変数が多すぎる、または大きすぎる。
  3. 無限ループ: 無限ループの中でスタックを消費する処理が行われている。

スタックに関しては、下記参照

【オブジェクト指向でなぜつくるのか？】OOP, クラス, 型付け, 継承, ポリモーフィズム, パッケージ, 例外, ガベージコレクション, コンパイラ, インタプリタ, 中間コード, メモリ領域
2022年に購入して積読だった「オブジェクト指向でなぜつくるのか 第３版　知っておきたいOOP、設計、アジャイル開発の基礎知識」を最近読んだので、まとめ記載。プログラミング言語の歴史の部分が、とてもわかりやすかった。OOPでは新しく3つの要素（クラス・ポリモーフィズム・継承）を導入した。
kazulog.fun
2024.07.01

MQTTメッセージの受信処理やパース処理が原因でスタックオーバーフローが発生することがある。特に大きなメッセージを処理する際には注意が必要。

Arduinoでは生じていなかったのに、なぜESP-IDFでは生じるのか？

ArduinoとESP-IDFフレームワークの違いによって、スタックサイズやタスクのメモリ管理に違いが生じ、スタックオーバーフローが発生する可能性がある。

デフォルトのスタックサイズ:

  • Arduino: タスクのスタックサイズは比較的多めに設定されているため、スタックオーバーフローが発生しにくい。
  • ESP-IDF: デフォルトではタスクのスタックサイズが小さいことがあり、Arduinoフレームワークと同じコードでスタックオーバーフローが発生する可能性がある

タスク管理:

  • Arduinoフレームワーク: 高レベルの抽象化が行われており、タスク管理がシンプル。
  • ESP-IDFフレームワーク: より低レベルのタスク管理が行われており、細かな設定が可能だが、その分、設定の不備が問題を引き起こすことがある。

デバックメッセージの追加

原因特定のため、void loop()関数内の原因がありそうなところに、デバッグメッセージを追加する

現在のvoid loop()関数とloop()内で呼び出している関数は下記。

C++

// Wi-Fi接続中の処理を実行
void executeWiFiConnectedRoutines() {
  static unsigned long lastOneMinutesEventUnixTime = getNowUnixTime(); // 1分ごとのイベント実行時刻を記録

  // デバイスシャドウの状態監視
  SyncShadow::getInstance().loop();

  // デバイス設定の変更を適用する
  applyAndReportConfigUpdates();

  // 1分に1回実行
  if ((getNowUnixTime() - lastOneMinutesEventUnixTime) > 60) {
    executeOneMinutesAction();
    lastOneMinutesEventUnixTime = getNowUnixTime();
  }
}

void loop() {
  if (inSafeMode) {
    safeModeLoop();
    return;
  }

  monitorWiFiConnectionChange();

  if (isWiFiConnected()) {
    executeWiFiConnectedRoutines();
  }

  buttonManager.handleButtonPress();

  ExpressionService::getInstance().render();

  delay(10);
}

uxTaskGetStackHighWaterMark(NULL)関数を使って、現在のタスクがどれだけのスタック領域を使用していないか（未使用スタック量）を取得し、その値をシリアルポートに出力する。

uxTaskGetStackHighWaterMark(NULL)

  • この関数は、指定されたタスクのスタックの「高水位マーク」（High Water Mark）を取得する。「高水位マーク」とは、タスクがこれまでに使用したスタックの最大値を示す。つまり、スタックが一番少なくなった時の残りのスタック量を返す。これを使うことで、タスクが実際にどれだけのスタックを使用しているのかを知ることができる。
  • 引数としてNULLを渡すと、現在実行中のタスクの高水位マークを取得する

といわけで、未使用スタック量が少なくなりそうな各処理の前後に上記デバッグメッセージを追加する。

C++

// Wi-Fi接続中の処理を実行
void executeWiFiConnectedRoutines() {
  static unsigned long lastOneMinutesEventUnixTime = getNowUnixTime(); // 1分ごとのイベント実行時刻を記録
  // デバッグメッセージを追加
  uint32_t freeStack = uxTaskGetStackHighWaterMark(NULL);
  Serial.print("Free stack at executeWiFiConnectedRoutines start: ");
  Serial.println(freeStack);
  // デバイスシャドウの状態監視
  SyncShadow::getInstance().loop();
  // デバッグメッセージを追加
  freeStack = uxTaskGetStackHighWaterMark(NULL);
  Serial.print("Free stack after SyncShadow loop: ");
  Serial.println(freeStack);


  // デバイス設定の変更を適用する
  applyAndReportConfigUpdates();
  // デバッグメッセージを追加
  freeStack = uxTaskGetStackHighWaterMark(NULL);
  Serial.print("Free stack after applyAndReportConfigUpdates: ");
  Serial.println(freeStack);

  // 1分に1回実行
  if ((getNowUnixTime() - lastOneMinutesEventUnixTime) > 60) {
    executeOneMinutesAction();
    lastOneMinutesEventUnixTime = getNowUnixTime();
  }
  // デバッグメッセージを追加
  freeStack = uxTaskGetStackHighWaterMark(NULL);
  Serial.print("Free stack at executeWiFiConnectedRoutines end: ");
  Serial.println(freeStack);
}

void loop() {
  // デバッグメッセージを追加してスタック使用状況を確認
  uint32_t freeStack = uxTaskGetStackHighWaterMark(NULL);
  Serial.print("Free stack at loop start: ");
  Serial.println(freeStack);

  if (inSafeMode) {
    safeModeLoop();
    return;
  }

  monitorWiFiConnectionChange();

  if (isWiFiConnected()) {
    // デバッグメッセージを追加
    freeStack = uxTaskGetStackHighWaterMark(NULL);
    Serial.print("Free stack before executeWiFiConnectedRoutines: ");
    Serial.println(freeStack);

    executeWiFiConnectedRoutines();

    // デバッグメッセージを追加
    freeStack = uxTaskGetStackHighWaterMark(NULL);
    Serial.print("Free stack after executeWiFiConnectedRoutines: ");
    Serial.println(freeStack);
  }

  buttonManager.handleButtonPress();

  // デバッグメッセージを追加
  freeStack = uxTaskGetStackHighWaterMark(NULL);
  Serial.print("Free stack before ExpressionService: ");
  Serial.println(freeStack);

  ExpressionService::getInstance().render();

  // デバッグメッセージを追加
  freeStack = uxTaskGetStackHighWaterMark(NULL);
  Serial.print("Free stack after ExpressionService: ");
  Serial.println(freeStack);

  delay(10);

  // デバッグメッセージを追加
  freeStack = uxTaskGetStackHighWaterMark(NULL);
  Serial.print("Free stack at loop end: ");
  Serial.println(freeStack);
}

再度ビルドしてログを見る。

デバッグメッセージの結果

デバッグメッセージから、スタックが1916バイトしか残っていないことがわかる。おそらく、MQTTPubSubClient::onMessage関数が利用された時点で、スタックがなくなったのだろう。

MQTTメッセージのサブスクライブやパブリッシュ操作、及びメッセージの処理（onMessage関数）でのスタック使用量が大きかったことが、スタックオーバーフローの直接的な原因であると考えられる。

ShellScript
MQTTPubSubClient::subscribe: $aws/things/XXXXXXXXXXXXX/shadow/get/accepted
[  6987][V][ssl_client.cpp:369] send_ssl_data(): Writing HTTP request with 71 bytes...
MQTTPubSubClient::subscribe: $aws/things/XXXXXXXXXXXXX/shadow/update/delta
[  7064][V][ssl_client.cpp:369] send_ssl_data(): Writing HTTP request with 71 bytes...
MQTTPubSubClient::publish: $aws/things/XXXXXXXXXXXXX/shadow/get 
[  7135][V][ssl_client.cpp:369] send_ssl_data(): Writing HTTP request with 59 bytes...
setup done
Free stack at loop start: 1916
start initialize service after wifi setup
SyncShadow is already started
Free stack before executeWiFiConnectedRoutines: 1916
Free stack at executeWiFiConnectedRoutines start: 1916
Free stack after SyncShadow loop: 1916
Free stack after applyAndReportConfigUpdates: 1916
Free stack at executeWiFiConnectedRoutines end: 1916
Free stack after executeWiFiConnectedRoutines: 1916
Free stack before ExpressionService: 1916
Free stack after ExpressionService: 1916
Free stack at loop end: 1916
Free stack at loop start: 1916
Free stack before executeWiFiConnectedRoutines: 1916
Free stack at executeWiFiConnectedRoutines start: 1916
MQTTPubSubClient::onMessage: $aws/things/XXXXXXXXXXXXX/shadow/get/accepted 

***ERROR*** A stack overflow in task loopTask has been detected.


Backtrace: 0x400829fe:0x3ffbf190 0x40168fb5:0x3ffbf1b0 0x4008a3d6:0x3ffbf1d0 0x4008c626:0x3ffbf250 0x4008a54c:0x3ffbf270 0x4008a4fe:0x000000ff |<-CORRUPTED

sdkconfigファイルでスタックサイズの設定変更

というわけで、解決策としてスタックサイズの増加を試してみる。ESP-IDFのプロジェクトルートにあるsdkconfigファイルを開き、以下の設定を探してスタックサイズを8192→16384に増加する。

C++
// sdkconfig.default
// before
CONFIG_ARDUINO_LOOP_STACK_SIZE=8192
// after
CONFIG_ARDUINO_LOOP_STACK_SIZE=16384

ちなみに、同じようにMQTTを有効にした後のスタックオーバーフローに遭遇している人いた

https://esp32.com/viewtopic.php?t=17104

上記URLの回答では、Main Task Size (CONFIG_MAIN_TASK_STACK_SIZE)を増加しているが、今回はCONFIG_ARDUINO_LOOP_STACK_SIZEを変更する。

なぜなら、今回は下記platform.iniの設定で、ArduinoとESP-IDFの両方のライブラリと機能を利用するようにしており、かつ、CONFIG_AUTOSTART_ARDUINO を定義して、Arduino 環境が自動的に起動され、setup() と loop() 関数が自動的に呼び出されるようにしている。なので、Arduinoのメインループタスク（loop()関数）がESP-IDFのメインタスクとは別に実行されている。そして、今回はArduinoのloop()関数でスタックオーバーフローが発生している

C++
[env]
platform = espressif32 @ 6.7.0
framework = arduino, espidf

再度ビルドした結果、、、

無事、MQTT通信後のスタックオーバーフローエラーが解消された！

ログを見ると下記のように、loop()関数の終了時にも、スタックの残りが7356バイトに増加しており、十分な余裕があることが確認できた。元の8192バイトだと、16384-7356=9028 > 8192なので、スタックオーバーフローしていたことが分かる。

ShellScript
Free stack at loop start: 7356
Free stack before executeWiFiConnectedRoutines: 7356
Free stack at executeWiFiConnectedRoutines start: 7356
Free stack after SyncShadow loop: 7356
Free stack after applyAndReportConfigUpdates: 7356
Free stack at executeWiFiConnectedRoutines end: 7356
Free stack after executeWiFiConnectedRoutines: 7356
Free stack before ExpressionService: 7356
Free stack after ExpressionService: 7356
Free stack at loop end: 7356

これで無事解決はできたが、原因確定の確認のため、MQTTのonMessage関数でのスタック使用量を確認するデバッグコードを追加する。

C++
void MqttClient::onMessage(const std::function<void(const String &topic, const String &payload)> &callback) {
  client->onMessage([callback](const String &topic, const String &payload) {
    // 呼び出し前のスタックの高水位マークを取得
    uint32_t freeStackBefore = uxTaskGetStackHighWaterMark(NULL);
    Serial.print("Free stack before onMessage: ");
    Serial.println(freeStackBefore);

    Serial.println("MQTTPubSubClient::onMessage: " + topic + " " + payload);

    // コールバック関数を実行
    callback(topic, payload);

    // 呼び出し後のスタックの高水位マークを取得
    uint32_t freeStackAfter = uxTaskGetStackHighWaterMark(NULL);
    Serial.print("Free stack after onMessage: ");
    Serial.println(freeStackAfter);

    // 消費されたスタックサイズを計算
    uint32_t stackUsed = freeStackBefore - freeStackAfter;
    Serial.print("Stack used by onMessage: ");
    Serial.println(stackUsed);
  });
}

ビルドしたところ、下記の結果に。MQTT通信のonMessage関数で2736バイトが消費されていたことがわかる。

なので、やはり、CONFIG_ARDUINO_LOOP_STACK_SIZE=8192では不十分だった。

ShellScript
Free stack before onMessage: 10100
MQTTPubSubClient::onMessage: $aws/things/XXXXXXXX/shadow/get/accepted
preload phrases after initial sync
SELECT * FROM phrase WHERE phrase_type = ? AND kind = 'other' ORDER BY talk_count, RANDOM() LIMIT ?;, Args: natural, 10, 
Matched: 10, Time taken:276963

Free stack after onMessage: 7364
Stack used by onMessage: 2736
MQTTPubSubClient::publish: $aws/things/XXXXXXXX/shadow/update {"state":{"reported":{"config":{"talk_frequency":60,"weather_announcement_time":{"hour":8,"minute":0},"birth_date":{},"phrase_type":"natural","talk_start_time":{"hour":7,"minute":0},"talk_end_time":{"hour":22,"minute":0},"work_start_time":{},"work_end_time":{},"volume":50,"firmware_version":"1.0.0"},"wakeup_time":25,"last_action_time":1717276989,"downloading":{"status":"NORMAL","progress":0,"start_time":1717234673,"end_time":1717235067,"type":"voice"},"connected":true,"last_periodic_talk_time":1716968737}}}
[ 59654][V][ssl_client.cpp:369] send_ssl_data(): Writing HTTP request with 63 bytes...
[ 59667][V][ssl_client.cpp:369] send_ssl_data(): Writing HTTP request with 512 bytes...
Free stack at loop end: 7364

原因わかって解決もできてよかった。

スポンサーリンク
タイトルとURLをコピーしました