Chapter 12
ログとリングバッファ — 時系列の記録を復元する
この章のゴール.
フラッシュや RAM に残ったログを、リングバッファの巻き戻りを正しく扱って時系列に並べ直せるようになること。 バイナリログ(型付きの記録)とテキストログを見分け、書き込みの途中で切れた最後の記録を扱えること。
この章で使う既出の用語(定義は各リンク先). CRC(03 章 8 節)、ELF(05 章 1 節)、スタック(07 章 7 節)、文字列(07 章 6 節)、ファイルシステム(09 章 1 節)
1. ログはなぜ解析対象になるか
機器が「止まった」「おかしい」とき、何が起きたかを最後に語るのがログである。 組み込みのログは、次のどこかに残る。
- RAM のバッファ: 高速だが電源断で消える。クラッシュ直後のダンプ(04 章)で拾う
- フラッシュのログ領域: 電源を切っても残る。追記型(10 章・11 章の仲間)
- 外付けフラッシュ / SD: ファイルシステム(09 章)上のログファイル
ログの解析は「記録の 1 件(レコード)の形」と「レコードの並べ方」の 2 つを解けば済む。
2. リングバッファ — 巻き戻る記録
フラッシュや RAM は有限なので、ログはリングバッファ(円環バッファ)に書かれることが多い。 決まった大きさの領域を使い、末尾まで書いたら先頭に戻って古い記録を上書きする。常に「直近の N 件」が残る仕組みである。
これが解析を少し面倒にする。メモリ上の並び順 = 時系列ではないからだ。
[領域の物理的な並び]
レコード5 レコード6 レコード7 | レコード3 レコード4
↑書き込み位置(head)
[時系列]
レコード3 → 4 → 5 → 6 → 7書き込み位置(head)の後ろが最古、前が最新である。正しく並べるには head を見つける必要がある。
head を見つける方法
- 明示的なポインタ: 領域の先頭や末尾に「次に書く位置」を示すヘッダがある。まずこれを疑う
- シーケンス番号: 各レコードに連番やタイムスタンプがあれば、それでソートすれば物理位置は無視できる。最も確実
- 消去済みとの境界: 未使用部分が 0xFF なら、「データ → 0xFF に変わる境界」が head(一度も一周していない場合)
- 不連続点: 一周していれば、シーケンス番号やタイムスタンプが急に小さくなる場所が head(新しいものが古いものを上書きした継ぎ目)
# シーケンス番号でソートするのが一番確実
records = parse_all_records(data) # 物理順にすべて読む
records.sort(key=lambda r: r.seq) # 連番(または timestamp)で時系列に3. バイナリログのレコードを読む
省メモリのため、組み込みのログはバイナリ(型付きの記録)が多い。文字列 "Temperature: 21.5 C" ではなく、[timestamp][level][module_id][event_id][args...] のような固定/可変長の記録を書く。
典型的なレコードの形:
| 部分 | 例 |
|---|---|
| マジック / 同期バイト | 各レコードの頭に 0xA5 など。壊れたバッファで境界を再発見するため |
| タイムスタンプ | Unix 秒、または起動からの tick(03 章) |
| シーケンス番号 | 単調増加。並べ替えと欠落検出に |
| レベル / モジュール / イベント ID | どこで何が起きたか(数値。意味は別表) |
| 引数 | 温度、エラーコードなど。型は event ID で決まる |
| 長さ / CRC | 可変長なら長さ、壊れ検出に CRC |
イベント ID の意味は、ファームウェアのソース(ログマクロの定義)か、ビルド時に生成される辞書ファイルにある。 省メモリのため「文字列をフラッシュに置かず、ID だけ記録し、PC 側で辞書と突き合わせる」方式(Zephyr の dictionary logging、SEGGER SystemView、deferred logging)が使われる。この場合、辞書がないとイベント ID の意味が分からない。辞書(ELF に埋まった文字列表、.json)を探す。
4. テキストログを読む
printf をそのまま流し込むテキストログは読みやすいが、リングバッファだと行が途中で切れて巻き戻る。
...sensor init ok\n[00:12:03] wifi conn\x00\xff\xff\xff...[00:11:58] boot\n[00:12:0
↑ここが head- 改行
\nで行に分ける - head(0xFF との境界や
\x00)を見つけ、そこで前後をつなぎ直す - 最後の行は途中で切れていることを前提にする(次項)
strings -n 4 log.bin # まず読める行を全部
tr -c '[:print:]\n' ' ' < log.bin | less # 非表示バイトを空白に置換して眺める5. 最後のレコードは切れている
書き込みの最中に電源が切れると、最後の 1 件は途中までしか書かれていない。
- 長さやマジックが不完全なレコードは破棄する。無理に読むとゴミを解釈してしまう
- CRC があれば照合し、合わないレコードは捨てる
- 「最新の完全なレコード」がどこかを見極めると、いつ止まったかが分かる(それが機器の最後の生存時刻)
これは 18 章(壊れたダンプ)と同じ考え方である。
6. RAM 上のログとクラッシュダンプ
クラッシュ時に RAM ダンプ(04 章)を取ると、そこに直近のログバッファが残る。 さらに、フォールト時のレジスタ退避(スタックに積まれた R0-R3、R12、LR=戻りアドレス、PC=プログラムカウンタ、xPSR=状態レジスタ)や、ウォッチドッグ / HardFault ハンドラが専用領域に書いたクラッシュ情報("coredump"、CORE などのマジック)があることも多い。
- ESP32 は core dump を専用パーティションに書ける(
espcoredump.py info_corefile) - Zephyr は coredump サブシステムがある
- 自作のフォールトハンドラは、決めた RAM 領域に PC・LR・スタックを書く。マジックを手がかりに探す
PC と LR(03 章・07 章)が読めれば、addr2line(ELF があれば)でクラッシュした行が分かる。17 章で詳しく扱う。
7. 手を動かす
リングバッファを時系列に戻す
この章のポイント
- ログは RAM・フラッシュ・ファイルのどこかにあり、多くはリングバッファ(巻き戻って上書き)
- 物理順 ≠ 時系列。head を見つけるか、シーケンス番号 / タイムスタンプでソートする(最も確実)
- バイナリログは
[時刻][ID][引数][CRC]の型付き記録。イベント ID の意味は辞書 / ソースにある - テキストログは head で行をつなぎ直す。最後のレコードは途中で切れている前提で捨てる
- クラッシュ時の RAM ダンプにログとフォールト情報(PC・LR)が残る。
addr2lineで行に戻す