【第1回】ddのbs=4k動作のデバッグ

メディアラボ株式会社

2023年11月14日 18:00

本文中に記載のある＃で始まるコマンド例はroot権限で実行することを示しています。自分の環境で実行する際に間違えてしまうとシステムを壊してしまう危険があります。引数などを良く確認してから実行して下さい。

第1回はddコマンドのデバッグを例にLinuxカーネルのデバッグ環境について解説します。今回はデバイスマップによるエラーインジェクションとtracepointを中心に説明します。

Linux環境としてはDebian12を使っています。できるだけ具体例を含めて説明していきます。

bs=4kの現在の動作がバグとは言えないので(仕様と呼ぶべきでしょう)、正しくは調査かも知れません。バグではなくても調査を行う時にはソースコードを追いかけるという意味で「デバッグ」という用語をここでは使っています。

まずは、現在動作しているカーネルをそのまま使ったデバッグを中心に解説します。

kgdbなどカーネルのリビルドが必要なデバッグ環境については次回以降で解説します。

1. 調査の内容

ddコマンドでSDカードなどのraw deviceへ直接データをコピーする時に、bs=4kをつけるとddコマンドは正常終了しているにもかかわらず。カーネル内ではI/Oエラーが起きていることがあります。

例えば以下のようなコマンドです。

# dd if=/xxx/disk.img of=/dev/sdx bs=4k

これに気づいた時は正直驚きました。

昔のカーネルではディスクのI/Oエラーが発生すると、半永久的にリトライを繰り返すので、気づくというより、作業が先に進めなくなるので否応なしにディスクの障害への対策を迫られていたと記憶しています。

2. エラーインジェクション

ディスクのI/Oエラーはめったなことでは起きません。

そこで、カーネルのエラーインジェクションの機能を使って実際にI/Oエラーは起きていませんが、I/Oエラーが発生したかのようにドライバがエラーを擬似的に返すことができます。

もちろん、実際にI/Oエラーが発生するHDDなりSSDを所持していればそれを使ってデバッグすれば良いでしょう。ただし、その場合でもエラーと同時にカーネルがハングしてしまう等、デバッグの効率が悪い時は敢えてエラーインジェクションを使う場合もあります。

3. ddの書き込みはキャッシュされる？

組込みLinuxの開発ではSDカードに作成したバイナリイメージをddで書き込むことがよくあります。ddコマンドでメディアに書き込んだ時、ddコマンドが完了してプロンプトへ戻ってきた時にデータは全てメディアへ書き込まれていて、メディアを取り出しても良いのでしょうか？

これが今回の課題でもあります。

ext4等のファイルシステム上のファイルへddで書き込んだ時は当然キャッシュされていますのでメディアを取り出すことはできません。そのファイルシステムをumountしてからでないと、ファイルシステムは破損する場合があります。今回はファイルシステム上のファイルへのdd書き込みは対象としません。書き込み先が/dev/sdaなどのようにデバイスそのものの場合はどうでしょう。

実際に調べていきます。

4. device mapper

device mapperを使って特定のセクターで擬似的にエラーが発生するブロックデバイスを作成します。

実際にSD上に作成してみます。
以下の例ではUSB接続のカードリーダーにSDカードをセットし、/dev/sdcとして認識されている例になります。

コマンドはroot権限で実行します。

# dmsetup create baddisk << EOF
    0 6050 linear /dev/sdc 0
    6050 155 error
    6205 2090947 linear /dev/sdc 6205 
EOF

これで /dev/mapper/baddisk が作成されます。
このデバイスはSDカード上の先頭のセクタから1GBが割り当てられていますが、セクタ6050から155セクタはI/Oエラーでアクセスできないように設定されています。

このデバイスを読み出してI/Oエラーが発生することを確認します。

# dd if=/dev/mapper/baddisk of=/dev/null skip=6050 count=1
dd: error reading '/dev/mapper/baddisk': Input/output error
0+0 records in
0+0 records out
0 bytes copied, 0.00737571 s, 0.0 kB/s

dmesgには以下のログが表示されます。

[ 566.548464] Buffer I/O error on dev dm-0, logical block 756, async page read

logical blockのサイズをblockdevで確認します。以下の結果から4KBとわかります。

# blockdev --report /dev/mapper/baddisk 
RO    RA   SSZ   BSZ        StartSec            Size   Device
rw   256   512  4096               0      1073741824   /dev/mapper/baddisk

dmesgのログからエラーの起きているバイトオフセットを計算します。
756 x 4K = 3096576
6050 x 512 = 3097600
3097600 - 3096576 = 1024
となり、6050sectorは4K blockで756blockのオフセット1024byteに位置しているので、設定と合っています。

5. ddコマンドで実験

ddコマンドで4MBの書き込みを試します。

# dd if=/dev/zero of=/dev/mapper/baddisk bs=4k count=1k
1024+0 records in
1024+0 records out
4194304 bytes (4.2 MB, 4.0 MiB) copied, 0.168789 s, 24.8 MB/s

書き込みは正常に終了します。

dmesgを見ると、

[18241.271713] Buffer I/O error on dev dm-0, logical block 757, lost async page write

これが766 blockまで10block続きます。エラーセクタは155個設定しているので、本来もっとエラーが続くはずですが、同様のメッセージなので途中から省略されているのだと思います。

次にbs=4kを設定せずデフォルトのbs=512で4MBの書き込みを実行してみます。

# dd if=/dev/zero of=/dev/mapper/baddisk count=8k
dd: writing to '/dev/mapper/baddisk': Input/output error
6049+0 records in
6048+0 records out
3096576 bytes (3.1 MB, 3.0 MiB) copied, 0.462726 s, 6.7 MB/s

3MBの所(6050sector)でIOエラーでddコマンドが停止しています。
dmesgにはエラーは表示されていません。

bs=512の場合は書き込み中にI/Oエラーが発生すると、ddコマンドが異常終了してユーザーにI/Oエラーの発生を知らせています。

この様に少なくともbsが512/4096でddの動きが違っています。

bs=512ではwriteシステムコールで既にIOエラーとなっていると思われます。

何故なのでしょうか？
ここからはその原因を探って行きます。

ここから先は

7,726字

¥ 300

ログイン