英語版で読む
技術約11分で読めます

StackChanの顔が半目で固まる原因を調べた

M5StackESP32Arduino電子工作TailscaleWireGuard実験
いけさん目次

前回はAIエージェントの作業完了をStackChanに読み上げさせた。
そのまま机の上でつけっぱなしにしていたら、2026年10月17日の夜に顔が半目のまま動かなくなっていた。

まばたきの途中の絵で止まっていて、USBシリアル（USB経由の通信）からコマンドを送っても反応しなかった。再起動すると元に戻ったものの、そのあとも通信が止まったり、まばたきが半目のところで一瞬引っかかったりしたので、何が起きているのか順番に調べてみた。

検証環境

項目使用した環境
実機M5Stack CoreS3（ESP32-S3、外付けのPSRAM 8MB）、StackChanのボディ
ファームウェアESP-IDF 5.5.4（ESP32向けの公式開発環境）、arduino-esp32 3.3.10
音声サーバー別PCで動かしている音声チャット用のサーバー（構成記事）
ログの記録USBシリアルをPCのPythonスクリプト（以降ロガー）で読み取り、時刻付きで保存

CoreS3の仕様はM5Stackの公式ページにある。arduino-esp32はESP-IDFのコンポーネント（機能単位のモジュール）として組み込んでいて、音声サーバーへはTailscaleで直結し、切れたときは中継サーバー経由に切り替わる。

待ち受け中に半目で固まった

起動から2時間40分後に、最初に固まった。Arduinoの loop() では顔の描画やまばたきのほか、1分おきにCO2センサーの読み取りとログ出力を回しているが、そのCO2のログが止まった一方で、ESP-IDF側のタスクが出すTailscaleのエラーログはシリアルに出力され続けていた。マイコン全体が落ちたわけではなく、loop() だけが止まったため、まばたきの途中の絵が画面に残ったまま半目で固まっていた。

裏で動き続けていたTailscaleでは、接続先や鍵を送る制御サーバーへ10秒おきにつなぎ直そうとして失敗していた。エラーは mbedtls_ssl_setup -0x7F00 で、暗号化通信を扱うmbedTLSライブラリの MBEDTLS_ERR_SSL_ALLOC_FAILED、メモリ確保の失敗だった。ただ、これだけでは loop() 自体がどこで止まっているのかは分からない。

CoreS3にJTAGでつないでみた

ファームウェアには、loop() が20秒以上止まったら全タスクのバックトレース（どの関数の中で止まっているかの記録）をシリアルに出す監視用のタスクを入れていた。ただ、止まったときに1回出すだけだったので、あとからシリアルをつないだときにはその出力が残っておらず、止まった場所が分からなかった。
CoreS3はチップを外から止めてメモリなどを調べるJTAGデバッグ機能をUSBに内蔵しているので、固まった状態のままつないでみた。

WindowsからJTAGを操作するOpenOCDを実行すると、libusb_open() failed LIBUSB_ERROR_NOT_FOUND になって開けなかった。JTAG用のUSBインターフェースにWinUSBドライバは割り当てられていたが、レジストリに DeviceInterfaceGUIDs の値が無かったので、管理者権限で追加したところ開けるようになった。

ところが、デバッガーのGDBをつないだ瞬間に実機がリセットされた。ファームウェアでメモリ保護（CONFIG_ESP_SYSTEM_MEMPROT_FEATURE）が有効だと、OpenOCDはGDBの接続時に Memory protection is enabled. Reset target to disable it... と出してリセットをかけてしまうため、どこで固まっていたかも分からなくなった。
次に固まったときに備えて、監視用のタスクは止まっているあいだ60秒おきにバックトレースを出し直すように変えた。

mbedTLSのバッファをPSRAMに移す

再起動したあと、今度は40分で音声サーバーとの直結が切れた。Tailscaleは中継サーバーのDERPに切り替えようとしたが、そのTLS接続も同じ -0x7F00 のエラーでつなげなくて、音声の送信も通知の確認もつながらないときの HTTP -1 になった。PCから音声サーバーが動いているか確かめると正常の200が返ってきたので、サーバー側は普通に動いていた。

ESP32-S3には8MBの外付けPSRAMがあるが、ESP-IDFの初期設定では、Wi-FiやmbedTLSのような通信まわりのメモリはCPU内の速いが小さい内部RAMから確保される。このファームウェアの設定では、TLSは接続1本ごとにデータを一時的にためるバッファを受信16KB・送信4KB確保するため、Tailscaleのつなぎ直しが続いて内部RAMが足りなくなっていたようだ。実は起動時にも毎回、公開IPを調べる ts_pubip タスクのTLS接続が同じエラーで失敗していた。

そこで、設定ファイルの sdkconfig に CONFIG_MBEDTLS_EXTERNAL_MEM_ALLOC=y を入れて、mbedTLSのバッファを外付けのPSRAMから確保するようにした。変更後の内部RAMの空きは約96KB、起動してからの最小値は54KBになり、起動時の ts_pubip の接続エラーも出なくなった。

会話中と待ち受け中のHTTP待ちを別タスクに移した

そのあと話しかけてみると、返事を待つあいだに顔の動きがカクつくようになった。会話中の loop() の各処理の時間を測ってみると、返事ができたかをサーバーに一定間隔で問い合わせるHTTPのポーリングに1回0.3〜1秒かかっていて、そのあいだ loop() が止まっていた。
ESP32のArduino環境はマイコン向けOSのFreeRTOSの上で動いており、loop() も1つのタスクとして実行されている。そこで別のFreeRTOSタスクを作ってポーリングをそちらに移し、loop() はキューに問い合わせを入れるだけにして、結果は次の1周で受け取るようにしたところ、会話中のカクつきはなくなった。

ただ、話しかけていない待ち受け中でも、まだまばたきが一瞬止まることがあった。loop() の各処理に0.3秒以上かかったらログに出すようにしていたので記録を確認すると、作業完了の通知を7秒おきにサーバーから取得する notify_tick が何件も出ていた。

16:14:05.156 slow: notify_tick 321 ms (chat=0 play=0)
16:14:12.890 slow: notify_tick 304 ms (chat=0 play=0)
16:14:41.538 slow: notify_tick 415 ms (chat=0 play=0)

括弧内の chat=0 play=0 は会話中でも再生中でもない待ち受け状態を表している。前回の記事で接続待ちの上限を1.5秒に短くしていたが、正常に返ってくる場合でも1回0.3〜0.4秒かかっていて、まばたきの途中にこれが走ると半目のまま0.3秒ほど止まっていた。
会話のポーリング用に作ったタスクで通知も取得するようにしたところ、notify_tick に0.3秒以上かかることはなくなった。

タッチやボタン処理の内訳を測ってみる

通知を別タスクに移しても、ほかの処理で0.3〜1.6秒止まることがときどきあった。それまでのログ全体を調べると、M5Stack共通ライブラリのM5Unifiedの M5.update()（画面タッチ・ボタン・電源チップの更新）と頭上タッチセンサーの読み取りをまとめた power_tick がいちばん多く記録されていた。

どこに時間がかかっているのか、処理ごとに分けて測ってみた。

21:13:16.954 power_tick: m5upd=104 head=352 btn=0 pow=0 ms
21:13:23.167 power_tick: m5upd=281 head=178 btn=0 pow=0 ms
21:15:05.225 power_tick: m5upd=328 head=2 btn=0 pow=0 ms

m5upd（M5.update()）や head（頭上タッチ）など、回によって止まる場所が違っていて、電源ボタンや電池表示の btn・pow は0msだった。m5upd も head も、チップ同士をつなぐ内部のI2C通信でセンサーの値を読み取っている。センサー自体の処理が遅いのではなく、I2Cの応答を待つあいだにほかのタスクにCPUを奪われているのかもしれない。

loop()が止まった間にCPUを使っていたタスク

ESP32-S3にはCPUのコアが2つあり、FreeRTOSがタスクをどちらかのコアで動かしている（loop() はコア1で動く）。sdkconfig でFreeRTOSの実行時間の統計を有効にして、タスクごとの合計の実行時間を uxTaskGetSystemState() で取るようにした。

CONFIG_FREERTOS_USE_TRACE_FACILITY=y
CONFIG_FREERTOS_VTASKLIST_INCLUDE_COREID=y
CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS=y

loop() の最初で全タスクの実行時間を記録しておき、0.3秒以上かかったら差を取って、長かった順に5つ出すようにした。

21:31:19.752 slow: power_tick 489 ms (chat=0 play=0)
21:31:19.752 cpu: 491 ms: tiT(c-1 p18)=480 IDLE0(c0 p0)=456 ts_derp_rx(c-1 p5)=13 wifi(c0 p23)=13 motion_task(c0 p10)=12

括弧内の c は固定されているコア（-1 は指定なし）、p は優先度（数字が大きいほど優先される）で、= のあとがそのあいだに動いたミリ秒。止まっていた491msのうち480msを、ESP-IDFのTCP/IPを処理するlwIPの tiT タスクが使っていた。優先度は18と高く、暗号化通信プロトコルのWireGuardもlwIPの仮想ネットワークインターフェースとして組み込まれているため、暗号化や復号もこのタスクの中で行われている。

統計からはコアごとの内訳は分からないので、どちらのコアで動いたかは引き算で求めた。同じ491msのあいだ、コア0の空き時間に動く待機用の IDLE0 が456ms、コア0固定の wifi と首振り用の motion_task が合わせて25ms動いていた。差し引くとコア0で tiT が動けたのは10msほどなので、480msのほとんどは loop() と同じコア1で動いていたようだ。

ESP-IDFの初期設定では、lwIPのタスクはコアを固定しない CONFIG_LWIP_TCPIP_TASK_AFFINITY_NO_AFFINITY になっていて、どちらのコアでも動く。loop() の優先度は1なので、優先度18の tiT がコア1で動いているあいだは loop() が動けなかった。

15分のログで、power_tick に0.3秒以上かかったことが18回あった。止まっていたあいだにいちばんCPUを使っていたタスクの内訳はこんな感じ。

タスク回数止まった時間
tiT（lwIP）170.30〜0.57秒
ts_pubip（Tailscaleの公開IPの確認）10.61秒

ほとんど power_tick で止まっていたのは、I2Cの応答待ちでコア1が空いた瞬間に、tiT がそこで動き出していたからだと思う。なお、この15分のうちに起動直後のCO2センサーの読み取りと通知の音声のダウンロードでも1回ずつ0.3秒以上かかったが、こちらは止まっていたあいだほとんど待機用の IDLE0 が動いていて、CPU自体は空いていた。

lwIPのタスクをコア0に固定した

sdkconfig で CONFIG_LWIP_TCPIP_TASK_AFFINITY_CPU0=y にして tiT をコア0に固定したところ、tiT で止まることはなくなった。
ところが、そのまま動かしているとまだ1.0秒と1.5秒止まることが2回あった。

21:49:26.657 cpu: 1002 ms: ts_pubip(c-1 p4)=994 IDLE0(c0 p0)=653 tiT(c0 p18)=254 ...
21:50:19.641 cpu: 1462 ms: ts_ctrl(c-1 p5)=1450 IDLE0(c0 p0)=979 tiT(c0 p18)=328 ...

出ていたのはTailscaleの ts_pubip と、制御サーバーとやり取りする ts_ctrl で、どちらも暗号化や復号の処理を含んでいる。優先度は4〜5で loop() より高く、コアの指定もない。1回目は IDLE0 が653msを占めているため、ts_pubip の994msの大半もコア1で動いていた。

今度はloop()が22秒止まった

Tailscaleのタスクもコア0に寄せようとしていたところで、その1分後に今度は1回だけ約22秒固まった。ロガーの記録が約22秒途切れていて、そのあいだ loop() の1周に21.5秒かかっていた。20秒を超えたので、60秒おきに出すように変えておいた監視用のタスクがバックトレースを出していた。

バックトレースに出た loop() のタスク（loopTask）のアドレスを、そこから関数名や行番号を引く addr2line で変換した。

prvSendAcquireGeneric  esp_ringbuf/ringbuf.c:823
xRingbufferSend        esp_ringbuf/ringbuf.c:1058
HWCDC::write           arduino-esp32/cores/esp32/HWCDC.cpp:590
Print::printf          arduino-esp32/cores/esp32/Print.cpp:85
loop()                 main.cpp（CO2の値を1分おきにログへ出す行）

loop() はCO2の値を出力する Serial.printf の先の HWCDC::write で止まっていた。CoreS3の Serial はESP32-S3に内蔵されているUSBシリアルで、送る文字はいったん送信バッファにためてPCが読み取るとUSBで送られる仕組みになっていて、PCが読み取らなければバッファが詰まり、HWCDC::write は空きができるまで1回100msの待ちを最大20回、合計で約2秒まで繰り返す。

loop() は1周の中で何度もログを出すため、そのたびに2秒近く待たされて1周に21.5秒かかっていた。このときもロガーは動かしていたが、PC側の読み取りがなぜ22秒止まったのかは不明のまま。

シリアルの送信待ち解除とTailscaleのコア固定

Serial.begin() の前に、送信の待ち時間を0にした。

Serial.setTxTimeoutMs(0);
Serial.begin(115200);

バッファが詰まっていれば待たずにその分のログを捨てるので、PC側が読み取っていないあいだのログは残らない。USBケーブルがPCにつながったままロガーを止めているときも、PC側でシリアルポートを開いていないので、変更前のままなら同じように待たされていたはず。

あわせて、Tailscaleのコンポーネントで ts_ctrl や中継通信、ts_pubip のタスクを作っている tailscale_esp32.c、tailscale_derp.c、tailscale_pubip.c の3ファイルも直した。lwIPのように sdkconfig でコアを指定する設定項目がなく、コード内でコア指定なしの xTaskCreate が直接呼ばれていたので、各ファイルの先頭で #define のマクロを使ってコア0固定の xTaskCreatePinnedToCore にまとめて置き換えた。

#define xTaskCreate(fn, name, stack, arg, prio, handle) \
    xTaskCreatePinnedToCore(fn, name, stack, arg, prio, handle, 0)

修正後にまばたきが止まった回数

power_tick は loop() の最初のほか、音声のダウンロード中や録音中にも、まばたきや口の動きの更新と一緒に呼ばれるため、呼ばれる間隔がほぼそのまま顔の絵が更新されない時間になる。
ロガーを止めているあいだはシリアルのログが捨てられるので、1分おきのCO2のログに、その1分間で power_tick の間隔が0.3秒以上空いた回数と、起動してからの間隔の最大値を追加した。起動中の待ち時間を含めないよう、起動時に1回だけ動く setup() の終わりでリセットしてからは最大値を持ち越すようにしたので、ロガーを止めていたあいだの最大値も、ロガーを動かし直したあとのログに出る。

表の1行目の修正前は power_tick 1回の処理時間で、修正後の2行は power_tick が呼ばれる間隔を測っている。

状態0.3秒以上止まった回数最大値
修正前（tiT 固定前の15分）18回0.61秒
修正後、ロガーを止めていた約5分1回以上0.68秒
修正後、ロガーを動かしていた8分0回0.23秒

ロガーを止めていた約5分の行の0.68秒は、起動してからの最大値として残っていた値だったので回数は1回以上とした。ロガーを動かしていた8分のうちに通知の音声のダウンロードが1回あり、処理全体には1.6秒かかったが、ダウンロード中もまばたきと power_tick は動くので、0.3秒以上空いた回数には含まれていない。

修正後の確認中にも、約5分半にわたってPC側の読み取りが止まり、ログに途中で切れた行が残る現象自体は起きたが、送信待ちを0にしたのでそのあいだも最大値は0.68秒のまま変わらず、StackChanの顔は止まらずに動いていた。