ファームウェアエンジニアの中林 (id:tomo-wait-for-it-yuki) です。以前、ESP-IDF v4.3でヒープ残量が10KB減る問題の調査内容について書きました。
そして舌の根も乾かぬうちにESP-IDF v4.4で再びヒープ残量が4KBも減ることに気づき、その調査を行いました。
結論だけ最初に書いておくと、BluetoothがHigh Level Interruptを使うようになり、そのスタックとして静的に4KBを割り当てるようになっています。High Level Interruptを使うかどうかはコンフィグで切り替え可能なのですが、Bluetoothのバグフィックスやパフォーマンス向上をしているため、Bluetoothを使用する場合は甘んじて4KBのメモリをESP-IDFに捧げるのが良さそうです。
発端
先週 (2022/04/20) にESP-IDF v4.4.1がリリースされました。リリースノートを眺めていると、ちょうど最近困っている問題のバグフィックスが入っている様子でした。
そうとわかれば試さない理由はありません！いつもどおり環境を構築して、ファームウェアをビルドします。
v4.3.2のときのようにヒープ残量を10KBも減らされてはたまりません。今回も優先的にヒープ残量を評価します (ヒープ残量の評価方法は前回のエントリを参照) 。比較対象はESP-IDF v4.3.2です。するとどうでしょう！たちまち、ヒープ残量が4KBも減っていることがわかりました！これはたまらん！
なぜヒープ残量が4KBも減るのか？その謎を追って我々はバイナリの世界へと踏み込むのであった！
v4.4から4KB減る！
ヒープ残量を評価したのは、v4.3.2 vs v4.4.1でした。いつの時点からヒープ残量が減っているのか明確にするために、v4.4でもファームウェアをビルドしました。その結果。v4.4でもヒープ残量が現象していることが判明しました。 ということでここから先はv4.3.2とv4.4を比較していきます。
静的か動的か
上記のヒープ残量比較では、アプリケーションレベルでヒープ残量を出力し、比較しています。まず最初の一手として、静的に使用するRAMが増えているのか、動的に増えているのか切り分けます。
ESP-IDFではシステム起動後、ヒープアロケータを初期化するときにRAM残量を出力してくれます。まずここで、静的なRAM使用量を比較できます。4個目のDRAMセグメントで3KiBヒープアロケーションに使えるRAMが減っていることがわかりますね。
I (2593) cpu_start: ESP-IDF: v4.3.2 I (2598) heap_init: Initializing. RAM available for dynamic allocation: I (2605) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (2611) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (2617) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (2624) heap_init: At 3FFC89D0 len 00017630 (93 KiB): DRAM // ★ I (2630) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (2636) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (2643) heap_init: At 4009D630 len 000029D0 (10 KiB): IRAM
I (2606) cpu_start: ESP-IDF: v4.4 I (2611) heap_init: Initializing. RAM available for dynamic allocation: I (2618) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (2625) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (2631) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (2637) heap_init: At 3FFC9620 len 000169E0 (90 KiB): DRAM // ★ I (2643) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (2650) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (2656) heap_init: At 4009D508 len 00002AF8 (10 KiB): IRAM
今回の問題は静的なメモリ利用量の増大が原因とわかりました。そうとわかれば！
楽しいバイナリ解析の時間です！
Let's バイナリ解析
まず小手調べとしてreadelfでセクション情報を比較してみます。お？どうやらdram0.dataセクションが顕著で、0xB80 = 2,944バイト *1 増えています。リンカ関連で.dataを中心に調べて行けば辿り着けそうです。
$ xtensa-esp32-elf-readelf -S v4.3.2/sample.elf There are 72 section headers, starting at offset 0xbf4918: Section Headers: [Nr] Name Type Addr Off Size ES Flg Lk Inf Al [ 0] NULL 00000000 000000 000000 00 0 0 0 // ... [ 9] .dram0.data PROGBITS 3ffbdb60 02ab60 004b8c 00 WA 0 0 16
$ xtensa-esp32-elf-readelf -S v4.4/sample.elf There are 96 section headers, starting at offset 0xc07a14: Section Headers: [Nr] Name Type Addr Off Size ES Flg Lk Inf Al [ 0] NULL 00000000 000000 000000 00 0 0 0 // ... [ 9] .dram0.data PROGBITS 3ffbdb60 02ab60 00570c 00 WA 0 0 16
mapファイルから大きなオブジェクトを抽出
同じソースコードかつ、同じコンフィギュレーションでビルドして静的なRAM利用量が増えているので、小さなオブジェクトがたくさん増えたのではなく、何か大きなオブジェクトが置かれるようになったのでは？という推測 (もしくは祈り) を立てました。
ビルド (リンク) 時に生成されるオブジェクトの配置情報 (.mapファイル) のうち、.dataセクションに含まれる大きなオブジェクトを抽出します。mapファイルは次のようにオブジェクトがメモリ上のどこに、どの大きさで配置されるか、がずらーっと書いてあります。
.data 0x000000003ffbdcb4 0x14 /opt/esp/idf/components/bt/controller/lib_esp32/esp32/libbtdm_app.a(arch_main.o)
ちらっと見た感じ、.dataもしくは.dram1から始まる行を見ていけば良さそうです。雑なワンライナーを実行してみます*2。このワンライナーには色々抜け漏れがあることがエントリ書いていてわかりました。だが…マヌケは見つかったようだな！
$ rg '(\s\.data|\.dram1\.\d+)\s+0x' 4.3.2/sample.map | awk '{ if(strtonum($3) >= 1024) {print $4,$3} }'
/root/work/build/freertos/libfreertos.a(portasm.o) 0xc0c
/root/work/build/xtensa/libxtensa.a(xtensa_intr_asm.o) 0x400
$ rg '(\s\.data|\.dram1\.\d+)\s+0x' 4.4/sample.map | awk '{ if(strtonum($3) >= 1024) {print $4,$3} }'
/root/work/build/freertos/libfreertos.a(portasm.o) 0xc0c
/root/work/build/xtensa/libxtensa.a(xtensa_intr_asm.o) 0x400
/root/work/build/bt/libbt.a(hli_vectors.o) 0x111c # こいつ
ESP-IDF v4.4でビルドしたバイナリにしかいない、0x111c = 4,380バイトのオブジェクト！唆るぜ、これは！
hli_vectors.oとは？
さて、問題のこれ libbt.a(hli_vectors.o) 0x111c ですが、どこのどなたでしょう？名前からするとBluetooth stack libraryなので、最悪、真相はバイナリの中になりそうです*3。とりあえず、ESP-IDFの中を漁ってみます。
$ find . -name hli_vectors.* ./components/bt/controller/esp32/hli_vectors.S
何かアセンブリのソースコードが居ますね。中身を見てみます。おわかりいただけるだろうか…？
#if CONFIG_BTDM_CTRL_HLI /* Interrupt stack size, for C code. * TODO: reduce and make configurable. */ #define L4_INTR_STACK_SIZE 4096 /* Save area for the CPU state: * - 64 words for the general purpose registers * - 7 words for some of the special registers: * - WINDOWBASE, WINDOWSTART — only WINDOWSTART is truly needed * - SAR, LBEG, LEND, LCOUNT — since the C code might use these * - EPC1 — since the C code might cause window overflow exceptions * This is not laid out as standard exception frame structure * for simplicity of the save/restore code. */ #define REG_FILE_SIZE (64 * 4) #define SPECREG_OFFSET REG_FILE_SIZE #define SPECREG_SIZE (7 * 4) #define REG_SAVE_AREA_SIZE (SPECREG_OFFSET + SPECREG_SIZE) .data _l4_intr_stack: .space L4_INTR_STACK_SIZE _l4_save_ctx: .space REG_SAVE_AREA_SIZE
うへぇ。.space 4096 *4 してるぅ…。
High Level Interrupt
hliはHigh Level Interruptを意味しているようです。ESP-IDF v4.4のRelease Noteを見直すと、Bluetooth ControllerにHigh Level Interruptを追加した、としれっと書いてあります。
https://github.com/espressif/esp-idf/releases/tag/v4.4
Added high level interrupt for Bluetooth
最新のESP-IDFドキュメントを見ると、High Level Interruptの説明があります。Xtensaのアーキテクチャでは、割り込みが7レベルあるようですね (1がlowest) 。Bluetoothが優先度の高いレベル4割り込みを使うようになった、というのが変更のポイントみたいです。
ただ、HLIがBluetoothに導入された経緯がわかりません。引き続き、ESP-IDF GitHub Repositoryのissueを漁ってみて、下のissueにたどり着きました。
いわく、この追加はBluetoothのバグフィックスとパフォーマンス向上のために実施されているので、Bluetoothを使うのであれば有効にすることをおすすめする、とのことです。
CONFIG_BTDM_CTRL_HLI is used for fixing some Bluetooth bugs and improving it's performance. If you use Bluetooth in your project, suggest to enable this.
さすがにこれを見た後に無効にする勇気もないので、4KBは年貢と考えてESP-IDFに納めます (ちょっと前に10KB納めたばっかりなんだけどなぁ！
Natureでは楽しくバイナリ解析できるエンジニアを積極採用中です。
カジュアル面談も実施していますので、興味がある方はお気軽にご応募ください！
