Yuhei Okazaki Table of Contents
前提知識
ESP32
今回はEspressif Systems社の無線通信モジュール、ESP32-WROOM-32Eの評価基板である ESP32-DevKitC-32E (以下、ESP32)を使用して検証しています。秋月電子で1230円で販売されているので、気軽に購入できるところが良いですね。
ESP32とPCはUSBケーブルで接続します。この接続はシリアル通信と電源供給という2つの役割を担っています。
esp-idf
mruby-esp32/mruby-esp32 も mruby-esp32/mruby-esp32-app-mirb もREADMEに書いてある手順でPC上でビルドして、デバイスにFlashします。
簡単そうに書きましたが、実際には esp-idf と呼ばれるフレームワークを使用する必要があり、ハマりどころの多い作業です。全てを書くと長くなるので、詳細はそのうち別の記事でまとめたいと思います。今回は v4.1.2 を仕様しています。
mirb
今回動かそうとしているmirbについて少しご紹介します。Rubyを使ってプログラミングをしている方であれば誰しも1度は irb を使った経験があると思います。irb はRubyのREPLであり、対話形式でプログラムを入力し、実行結果を即時確認できるので便利ですよね。
mirb は irb のmruby版と思っていただければOKです。 mruby がベースとなっていることで省リソース化されているので、今回のようにリソースの乏しいデバイス上で動作させることができます。
mruby 3.0.0
mruby-esp32/mruby-esp32 では このコミット でmruby 3.0.0に対応するための修正がなされています。
一方、当初 mruby-esp32/mruby-esp32-app-mirb にはこの変更が適用されていなかったので、手元の環境で適用した状態で動作確認を開始しました。現在では 私の出したPull request がマージされているのでこの変更は適用されています。
mruby-esp32-app-mirbで発生した問題
現象
ESP32にFlashし、シリアル通信で接続すると以下のようなpanicが発生しました。
mirb - Embeddable Interactive Ruby Shell
> 1
Guru Meditation Error: Core 1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400d855e PS : 0x00060130 0 : 0x800d3e38 1 : 0x3ffb9ca0
2 : 0x3ffbb358 3 : 0x00000001 4 : 0x000004c0 5 : 0x00000000
6 : 0x000004c0 7 : 0x00000013 8 : 0x800ef5ff 9 : 0x3ffb9400
10 : 0x3ffbb358 11 : 0x00000000 12 : 0x00000003 13 : 0x00000000
14 : 0x00000001 15 : 0x3ffc3d30 SR : 0x0000001f EXCCUSE: 0x0000001c
EXCVDDR: 0x000004c0 LBEG : 0x4000c46c LEND : 0x4000c477 LCOUNT : 0xffffffff
ELF file SH256: 608162a60d98441b
Backtrace: 0x400d855b:0x3ffb9ca0 0x400d3e35:0x3ffb9ce0 0x400d3f00:0x3ffbb130 0x40085159:0x3ffbb160
Rebooting...
mirbの起動自体はうまくいってそうなのですが、プロンプトに対して Enter キーを押すとpanicが発生しています。エラーの内容を見る限り、不正なメモリ領域へアクセスしたものと推測されます。
原因
原因はmrubyで「値」を保持する mrb_value の構造が、 mruby と mruby-esp32-app-mirb で異なっていたことでした。
mruby-esp32-app-mirb をビルドすると、以下の図のように mruby-esp32-app-mirb に含まれるプログラムと、mruby および mrbgems のソースコード一式がコンパイル・リンクされます。
特筆すべき点として、mirbをESP32上で動作させるためには、 mruby に含まれている mirb.c の一部の関数をESP32で動作するよう書き換える必要があります。mruby-esp32-app-mirb ではこれを実現するため、mirb.c をincludeしてマクロを使って別の関数に置き換える、という戦略をとっています。
mruby は上述の「mruby 3.0.0対応」にて、MRB_NO_BOXING を指定しています。このときの mrb_value は以下のようになります。
union mrb_value_union {
#ifndef MRB_NO_FLOAT
mrb_float f;
#endif
void *p;
mrb_int i;
mrb_sym sym;
};
typedef struct mrb_value {
union mrb_value_union value;
enum mrb_vtype tt;
} mrb_value;
一方、 mruby-esp32-app-mirb では MRB_NO_BOXING のような指定はしていません。指定をしていない場合は MRB_WORD_BOXING が適用されます。
#if !defined(MRB_NAN_BOXING) && !defined(MRB_WORD_BOXING) && !defined(MRB_NO_BOXING)
# define MRB_WORD_BOXING
#endif
このときの mrb_value の構造は以下の通りです。 MRB_NO_BOXING を指定したときとは全く異なりますね。
/*
* mrb_value representation:
*
* nil : ...0000 0000 (all bits are 0)
* false : ...0000 0100 (mrb_fixnum(v) != 0)
* true : ...0000 1100
* undef : ...0001 0100
* fixnum: ...IIII III1
* symbol: ...SSSS SS10 (use only upper 32-bit as symbol value on 64-bit CPU)
* object: ...PPPP P000 (any bits are 1)
*/
typedef struct mrb_value {
uintptr_t w;
} mrb_value;
これにより、 mruby-esp32-app-mirb 側でビルドした mirb.c が MRB_WORD_BOXING の mrb_value を渡しているにもかかわらず、mruby 側では渡された mrb_value を MRB_NO_BOXING だと解釈してアクセスし、確保されていないメモリ領域へのアクセス→panicが発生しました。
対策
mruby-esp32-app-mirb のコンパイルオプションに MRB_NO_BOXING を追加し、 mrb_value を同じデータ構造で扱うよう修正しました。具体的な方法は Pull request を参照ください。
どうやって原因を見つけ出したか？
原因がわかってしまえば対策自体は簡単だったのですが、今回の現象は「デバイス上でしか再現しない」「パッと見でどこが原因なのかわからない」といった現象だったので、調査に苦戦しました。一本道で原因を特定できたわけでもありませんし、実際には数日を要して原因に辿り着いています。
そんな状況から以下にして原因に辿り着いたのか、まとめていきます。
panicのログから問題の発生箇所を特定する
最初は「パッと見でどこが原因なのかわからない」という問題の対処からはじめました。しかし、PCで動作するRubyアプリケーションとは異なり、デバイス上で動作するプログラムをステップ実行したり中断したりするのはなかなか大変です。本格的に実践するためには JTAG と呼ばれる専用の機器を接続して、デバッグ環境を準備する必要があります。
そこで今回はpanicが発生したときのログから発生箇所の特定を試みました。ポイントは PC および Backtrace と記載されている以下の部分です。
PC : 0x400d855e
(省略)
Backtrace: 0x400d855b:0x3ffb9ca0 0x400d3e35:0x3ffb9ce0 0x400d3f00:0x3ffbb130 0x40085159:0x3ffbb160
PC とは Program Counter の略で、panicした時点で実行していた命令のメモリ番地を指しています。このままだと単なるアドレスですが、GDBの list コマンドを使うことでソースコード上のどの行を指しているのか特定することが可能です。
問題が発生したのはデバイス上ですが、クロスコンパイラに付属するGDBに対して、デバイスに書き込んだバイナリを渡せば同様の操作が可能です。
❯ xtensa-esp32-elf-gdb build/mruby-esp32-app-mirb.elf
(gdb) list *0x400d855e
0x400d855e is in mrb_respond_to (/Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49).
44 case MRB_TT_CPTR:
45 return mrb->object_class;
46 case MRB_TT_ENV:
47 return NULL;
48 default:
49 return mrb_obj_ptr(v)->c;
50 }
51 }
52
53 /* flags:
領域外アクセスが発生したのは mruby の class.h の 49行目 ということがわかりました。こちら ですね。
加えて Backtrace に列挙されているアドレスも順番に list で出力していきます。
(gdb) list *0x400d855e
0x400d855e is in mrb_respond_to (/Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49).
44 case MRB_TT_CPTR:
45 return mrb->object_class;
46 case MRB_TT_ENV:
47 return NULL;
48 default:
49 return mrb_obj_ptr(v)->c;
50 }
51 }
52
53 /* flags:
(gdb) list *0x400d855b
0x400d855b is in mrb_respond_to (/Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:45).
40 #ifndef MRB_NO_FLOAT
41 case MRB_TT_FLOAT:
42 return mrb->float_class;
43 #endif
44 case MRB_TT_CPTR:
45 return mrb->object_class;
46 case MRB_TT_ENV:
47 return NULL;
48 default:
49 return mrb_obj_ptr(v)->c;
(gdb) list *0x400d3e35
0x400d3e35 is in mirb_main (/Users/yuhei/esp/mruby-esp32-app-mirb/main/../components/mruby/mruby/mrbgems/mruby-bin-mirb/tools/mirb/mirb.c:672).
667 p(mrb, mrb_obj_value(mrb->exc), 0);
668 mrb->exc = 0;
669 }
670 else {
671 /* no */
672 if (!mrb_respond_to(mrb, result, MRB_SYM(inspect))){
673 result = mrb_any_to_s(mrb, result);
674 }
675 p(mrb, result, 1);
676 #ifndef DISABLE_MIRB_UNDERSCORE
(gdb) list *0x400d3f00
0x400d3f00 is in mirb_task (/Users/yuhei/esp/mruby-esp32-app-mirb/main/main.c:134).
129 static void
130 mirb_task(void *pvParameter)
131 {
132 char *argv[] = {"mirb", NULL};
133
134 mirb_main(1, argv);
135
136 esp_restart();
137 }
138
(gdb) list *0x40085159
0x40085159 is in vPortTaskWrapper (/Users/yuhei/esp/esp-idf/components/freertos/port.c:143).
138
139 #if CONFIG_FREERTOS_TASK_FUNCTION_WRAPPER
140 // Wrapper to allow task functions to return (increases stack overhead by 16 bytes)
141 static void vPortTaskWrapper(TaskFunction_t pxCode, void *pvParameters)
142 {
143 pxCode(pvParameters);
144 //FreeRTOS tasks should not return. Log the task name and abort.
145 char * pcTaskName = pcTaskGetTaskName(NULL);
146 ESP_LOGE("FreeRTOS", "FreeRTOS Task \"%s\" should not return, Aborting now!", pcTaskName);
147 abort();
mirb_main タスクを起動してからエラーが発生するまでの流れがわかりましたが、ところどころ(おそらくインライン展開されているメソッド)が省略されてしまっています。また、呼び出し経路が特に異常な経路ではないので、何が原因でメモリ外アクセスが発生しているのかはまだわからないままです。
IDF monitorを接続しもっと楽にBacktraceを確認する
panicのログを追っての調査に苦戦しているとき、mruby-esp32/mruby-esp32-app-mirb の作者である @pandax381 さんの記事を見つけました。
どういった過程で今のような実装に辿り着いたのかが理解できたことも多かったですが、「 make monitor でシリアルモニタを接続できる」という点が個人的には大きな収穫でした。それまではプログラムを実機に書き込んでから、screen を使ってシリアル接続し直す、という面倒な手順を踏んでいたので、手数が減るのはありがたかったです。
さらに嬉しかったのは、 make monitor でシリアル接続すると、panicが発生したときにbacktraceが表示されたことです。
mirb - Embeddable Interactive Ruby Shell
>
Guru Meditation Error: Core 1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC : 0x400d855e PS : 0x00060130 A0 : 0x800d3e38 A1 : 0x3ffb9ca0
0x400d855e: mrb_class at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49
(inlined by) mrb_respond_to at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/src/class.c:1989
A2 : 0x3ffbb358 A3 : 0x00000000 A4 : 0x000004c0 A5 : 0x00000000
A6 : 0x000004c0 A7 : 0x00000013 A8 : 0x800ef5ff A9 : 0x3ffb9400
A10 : 0x3ffbb358 A11 : 0x00000000 A12 : 0x00000000 A13 : 0x00000000
A14 : 0x00000000 A15 : 0x3ffbd154 SAR : 0x0000001f EXCCAUSE: 0x0000001c
EXCVADDR: 0x000004c0 LBEG : 0x4000c46c LEND : 0x4000c477 LCOUNT : 0xffffffff
ELF file SHA256: 608162a60d98441b
Backtrace: 0x400d855b:0x3ffb9ca0 0x400d3e35:0x3ffb9ce0 0x400d3f00:0x3ffbb130 0x40085159:0x3ffbb160
0x400d855b: mrb_class at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:45
(inlined by) mrb_respond_to at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/src/class.c:1989
0x400d3e35: mirb_main at /Users/yuhei/esp/mruby-esp32-app-mirb/main/../components/mruby/mruby/mrbgems/mruby-bin-mirb/tools/mirb/mirb.c:672
0x400d3f00: mirb_task at /Users/yuhei/esp/mruby-esp32-app-mirb/main/main.c:134
0x40085159: vPortTaskWrapper at /Users/yuhei/esp/esp-idf/components/freertos/port.c:143
Rebooting...
これは後で調べてわかったのですが、make monitor を実行したとき内部的には IDF Monitor を利用して接続しています。IDF Monitorには Automatic Address Decoding と呼ばれる機能があり、出力されたアドレスを自動的にダンプしてファイル名やシンボル名を表示してくれるそうです。
これにより手作業でアドレスの変換をしなくて良くなったので、調査効率が上がりました。
panic後にGDBを起動してデータの流れを確認する
IDF Monitorの存在に気づいたことで、「他にも便利なデバッグの仕組みが用意されているのでは？」と思いドキュメントを読み漁ったところ、 GDB Stub というページを発見しました。
make menuconfig にて CONFIG_ESP_SYSTEM_PANIC_GDBSTUB を enable にしておくとpanicが発生したときにGDBが自動起動する、という素晴らしい機能です。
実際に試したところ、本当にGDBが起動しました。
mirb - Embeddable Interactive Ruby Shell
>
Guru Meditation Error: Core 1 panic'ed (LoadProhibited). Exception was unhandled.
(省略)
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "--host=x86_64-host_apple-darwin12 --target=xtensa-esp32-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /Users/yuhei/esp/mruby-esp32-app-mirb/build/mruby-esp32-app-mirb.elf...done.
Remote debugging using /dev/cu.usbserial-110
0x400d8eea in mrb_class (v=..., mrb=0x3ffbb918) at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49
49 return mrb_obj_ptr(v)->c;
(gdb)
あらためてスタックトレースを確認し、各フレームでの変数の値を確認します。
(gdb) backtrace
#0 0x400d8eea in mrb_class (v=..., mrb=0x3ffbb918) at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/include/mruby/class.h:49
#1 mrb_respond_to (mrb=0x3ffbb918, obj=..., mid=10) at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/src/class.c:1989
#2 0x400d47c4 in mirb_main (argc=<optimized out>, argv=<optimized out>) at /Users/yuhei/esp/mruby-esp32-app-mirb/main/../components/mruby/mruby/mrbgems/mruby-bin-mirb/tools/mirb/mirb.c:672
#3 0x400d488f in mirb_task (pvParameter=0x0) at /Users/yuhei/esp/mruby-esp32-app-mirb/main/main.c:134
#4 0x4008516c in vPortTaskWrapper (pxCode=0x400d487c <mirb_task>, pvParameters=0x0) at /Users/yuhei/esp/esp-idf/components/freertos/port.c:143
(gdb) f 2
#2 0x400d47c4 in mirb_main (argc=<optimized out>, argv=<optimized out>) at /Users/yuhei/esp/mruby-esp32-app-mirb/main/../components/mruby/mruby/mrbgems/mruby-bin-mirb/tools/mirb/mirb.c:672
672 if (!mrb_respond_to(mrb, result, MRB_SYM(inspect))){
(gdb) print result
$7 = 0
(gdb) f 1
#1 mrb_respond_to (mrb=0x3ffbb918, obj=..., mid=10) at /Users/yuhei/esp/mruby-esp32-app-mirb/components/mruby/mruby/src/class.c:1989
1989 return mrb_obj_respond_to(mrb, mrb_class(mrb, obj), mid);
(gdb) print obj
$8 = {value = {f = 6.007838253429558e-321, p = 0x4c0, i = 1216, sym = 1216}, tt = 4278190080}
mrb_respond_to の第2引数を呼び出し元( result )と呼び出し先( obj )でそれぞれ print したのですが、呼び出し元では 0 、呼び出し先では {value = {f = 6.007838253429558e-321, p = 0x4c0, i = 1216, sym = 1216}, tt = 4278190080} が出力されました。
同じ変数なのに値も構造も変わってしまっているのはなぜか？を追求した結果、呼び出し元には MRB_NO_BOXING が適用されていないという根本原因にたどり着くことができました。
今回の調査で得られた教訓
「開発環境のドキュメントをしっかり読みましょう」という点に尽きますね。Backtraceのログだけでは原因特定に至らなかったと思いますし、仮に特定できたとしても膨大な時間がかかっていたと思います。
ESP32がJTAG無しでここまでデバッグできるということに正直驚きました。私自身普段からIoTシステムの開発に携わっていて、実証実験フェーズではデバイス側のプログラムを書くこともあるので、ESP32を積極的に利用したいと思いました。
おわりに
書く前から予想はしていましたが、Rubyの話はあまり出てきませんでしたね。ただ、「形は違えど普段使っているRubyも中身はこういったC言語で実装されていること」、「小さなデバイスでも動作するmrubyというOSSがあること」だけでも、覚えていてもらえると執筆者としては嬉しいです。
mrubyがMicroPythonに負けないよう、個人的には何かしら貢献を続けていきたいところです。
Yuhei Okazaki
2018年の年明けに組込み畑からやってきた、2児の父 兼 Webエンジニアです。 mockmockの開発・運用を担当しており、組込みエンジニア時代の経験を活かしてデバイスをプログラミングしたり、簡易的なIoTシステムを作ったりしています。主な開発言語はRuby、時々Go。
Related Posts
kakudaisuke
2021/11/26
Yuhei Okazaki
2021/10/27