under construction. 書きかけ。
linux の、SSD キャッシュ機能、bcache の内部構造の kanda.motohiro@gmail.com による説明です。bcache の使い方や、sysfs に見えるものの説明は、ユーザドキュメント、bcache.txt を参照。bcache.h の先頭の、コード全般にわたるコメントを訳しました。それも参照。
ソースは drivers/md/bcache にあります。
ブロック層から呼ばれるエントリーポイントは、cached_dev_make_request request.c です。ライトなら、cached_dev_write/request_write へ、リードなら、cached_dev_read/request_read へ行きます。ソースのバージョンにより、関数名は変わることがあります。なお、flash_dev_make_reques は、背後のデバイスを持たない、フラッシュだけのデバイスの関数で、ここで説明するものとは別です。
bch_generic_make_request, は、SSD あるいはディスクへの IO 開始です。
bch_submit_bbio は、SSD の btree の読み書きです。？ btree リーフを引数として、SSD のデータブロックを読み書きする？
bcache は、ようするにキャッシュなので、
リード処理
１ 目的のブロックが SSD にあるか、btree を見る。キーはオフセット。
２ あれば、btree のリーフに書いてある、 SSD のデバイス番号と SSD 内のオフセットを対象とする bio を作って、submit する。
３ なければ、もとの bio をデバイス番号だけ変えて、背後のデバイスに submit する。
４ もとの bio が完了したら、読んだデータを SSD にコピーして、btree に記録する。
ライト処理
１ btree の参照。リードと同じく。
２ あったとき。XXX
のように動きます。と、思うよ。
btree 自身も、 SSD に書かれます。ダーティ、つまり、最新データが SSD だけにあって、背後のデバイスに書かれてない状態もあります。
消去ブロック長うんぬんと言ってますが、生のフラッシュデバイスのウェアレベリングをするわけではなくて、scsi 経由のディスクとして見えるものを使うだけです。バケツ長はフォーマットの時に手で与えます。ハードウエア固有の情報を自分で取るわけではありません。
クロージャ
closure.h の先頭に長いコメントがあります。
ようするに、closure_call も continue_at も、ワークキューへの登録です。make_request は割り込みコンテキストで呼ばれることがあるため、スレッドコンテキストでやるべきことはこれを使って遅延実行します。いや、すぐに動くことが多いみたいだけど。
使用カーネルとコマンド
$ uname -a
Linux kanda 3.12.6-200.fc19.i686 #1 SMP Mon Dec 23 17:12:10 UTC 2013 i686 i686 i386 GNU/Linux
http://lisas.de/~adrian/bcache-tools/bcache-tools-0.0-0.1.20130815git0b57e1.fc19.src.rpm
# make-bcache -C /dev/sdc -B /dev/sdd
$ cat /proc/partitions
major minor #blocks name
8 32 250879 sdc
8 48 8257032 sdd
252 0 8257024 bcache0
# bcache-super-show /dev/sdc
sb.magic ok
sb.first_sector 8 [match]
sb.csum 3459AAF6B56014AE [match]
sb.version 3 [cache device]
dev.uuid 91d910af-d7d2-4433-b29f-2187d21c0190
dev.sectors_per_block 1
dev.sectors_per_bucket 1024
dev.cache.first_sector 1024
dev.cache.cache_sectors 499712
dev.cache.total_sectors 500736
dev.cache.discard no
dev.cache.pos 0
cset.uuid 243f7556-9a22-4abe-9ab3-3ab28b9656af
# bcache-super-show /dev/sdd
sb.magic ok
sb.first_sector 8 [match]
sb.csum BE350DD9DBD6E993 [match]
sb.version 1 [backing device]
dev.uuid 6bc57e61-0ec1-489b-abc8-460379b74a7b
dev.sectors_per_block 1
dev.sectors_per_bucket 1024
dev.data.first_sector 16
dev.data.cache_mode 1 [writeback]
dev.data.cache_state 0 [detached]
cset.uuid 00000000-0000-0000-0000-000000000000
# echo 1 > /sys/kernel/debug/tracing/events/bcache/enable
リード
# dd if=/dev/bcache0 bs=1024 count=1
# cat /sys/kernel/debug/tracing/trace
# tracer: nop
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
dd-2196 [000] .... 404.362106: bcache_request_start: 8,48 R 16 + 8 (from 252,0 @ 0)
dd-2196 [000] .... 404.362155: bcache_request_start: 8,48 R 24 + 8 (from 252,0 @ 8)
dd-2196 [000] .... 404.362162: bcache_request_start: 8,48 R 32 + 8 (from 252,0 @ 16)
dd-2196 [000] .... 404.362168: bcache_request_start: 8,48 R 40 + 8 (from 252,0 @ 24)
ksoftirqd/0-3 [000] ..s. 404.363216: bcache_read: 8,48 R 16 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 404.363219: bcache_request_end: 8,48 R 16 + 8 (from 252,0 @ 0)
ksoftirqd/0-3 [000] ..s. 404.363226: bcache_read: 8,48 R 24 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 404.363227: bcache_request_end: 8,48 R 24 + 8 (from 252,0 @ 8)
ksoftirqd/0-3 [000] ..s. 404.363965: bcache_read: 8,48 R 32 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 404.363970: bcache_request_end: 8,48 R 32 + 8 (from 252,0 @ 16)
ksoftirqd/0-3 [000] ..s. 404.364709: bcache_read: 8,48 R 40 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 404.364710: bcache_request_end: 8,48 R 40 + 8 (from 252,0 @ 24)
kworker/u2:4-46 [000] .... 413.554606: bcache_btree_write: bucket 6
dd-2199 [000] .... 424.404883: bcache_request_start: 8,48 R 16 + 8 (from 252,0 @ 0)
dd-2199 [000] .... 424.404928: bcache_request_start: 8,48 R 24 + 8 (from 252,0 @ 8)
dd-2199 [000] .... 424.404937: bcache_request_start: 8,48 R 32 + 8 (from 252,0 @ 16)
dd-2199 [000] .... 424.404943: bcache_request_start: 8,48 R 40 + 8 (from 252,0 @ 24)
ksoftirqd/0-3 [000] ..s. 424.406081: bcache_read: 8,48 R 16 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 424.406086: bcache_request_end: 8,48 R 16 + 8 (from 252,0 @ 0)
ksoftirqd/0-3 [000] ..s. 424.406094: bcache_read: 8,48 R 24 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 424.406095: bcache_request_end: 8,48 R 24 + 8 (from 252,0 @ 8)
ksoftirqd/0-3 [000] ..s. 424.406816: bcache_read: 8,48 R 32 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 424.406819: bcache_request_end: 8,48 R 32 + 8 (from 252,0 @ 16)
ksoftirqd/0-3 [000] ..s. 424.407569: bcache_read: 8,48 R 40 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 424.407570: bcache_request_end: 8,48 R 40 + 8 (from 252,0 @ 24)
ライト
# dd if=/dev/zero of=/dev/bcache0 bs=1024 count=1
# cat trace
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
dd-2233 [000] .... 732.227053: bcache_request_start: 8,48 R 16 + 8 (from 252,0 @ 0)
ksoftirqd/0-3 [000] ..s. 732.228813: bcache_read: 8,48 R 16 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 732.228819: bcache_request_end: 8,48 R 16 + 8 (from 252,0 @ 0)
dd-2233 [000] .... 732.228933: bcache_request_start: 8,48 WS 16 + 8 (from 252,0 @ 0)
dd-2233 [000] .... 732.228939: bcache_write: 8,48 WS 16 + 8 hit 0 bypass 0
dd-2233 [000] .N.. 732.228954: bcache_cache_insert: 0:24 len 8 dirty 0
kworker/0:3-2125 [000] .... 732.333724: bcache_journal_write: 8,32 FWFSM 3073 + 1
kworker/0:3-2125 [000] .... 732.333789: bcache_btree_insert_key: 3 for 0 at 6(0): 0:24 len 8 dirty 0
kworker/0:3-2125 [000] .... 732.333796: bcache_request_end: 8,48 WS 16 + 8 (from 252,0 @ 0)
systemd-udevd-2234 [000] .... 732.335941: bcache_request_start: 8,48 R 16513936 + 8 (from 252,0 @ 16513920)
systemd-udevd-2234 [000] .... 732.335952: bcache_bypass_congested: 8,48 R 16513936 + 8
ksoftirqd/0-3 [000] ..s. 732.405779: bcache_read: 8,48 R 16513936 + 8 hit 1 bypass 1
ksoftirqd/0-3 [000] ..s. 732.405785: bcache_request_end: 8,48 R 16513936 + 8 (from 252,0 @ 16513920)
systemd-udevd-2234 [000] .... 732.405867: bcache_request_start: 8,48 R 16514048 + 8 (from 252,0 @ 16514032)
systemd-udevd-2234 [000] .... 732.405874: bcache_bypass_congested: 8,48 R 16514048 + 8
ksoftirqd/0-3 [000] ..s. 732.406653: bcache_read: 8,48 R 16514048 + 8 hit 1 bypass 1
ksoftirqd/0-3 [000] ..s. 732.406655: bcache_request_end: 8,48 R 16514048 + 8 (from 252,0 @ 16514032)
この途中、リードの繰り返し。何をやっているのか不明。先頭セクターをこわしたからかと思って、書き込み位置を変えても同じ。
probe-bcache-2236 [000] .... 732.581004: bcache_request_start: 8,48 R 24 + 8 (from 252,0 @ 8)
probe-bcache-2236 [000] .... 732.581014: bcache_bypass_congested: 8,48 R 24 + 8
ksoftirqd/0-3 [000] ..s. 732.581780: bcache_read: 8,48 R 24 + 8 hit 1 bypass 1
ksoftirqd/0-3 [000] ..s. 732.581784: bcache_request_end: 8,48 R 24 + 8 (from 252,0 @ 8)
udisks-part-id-2237 [000] .... 732.585908: bcache_request_start: 8,48 R 16 + 8 (from 252,0 @ 0)
udisks-part-id-2237 [000] .... 732.585919: bcache_bypass_congested: 8,48 R 16 + 8
ksoftirqd/0-3 [000] ..s. 732.586656: bcache_read: 8,48 R 16 + 8 hit 1 bypass 1
ksoftirqd/0-3 [000] ..s. 732.586659: bcache_request_end: 8,48 R 16 + 8 (from 252,0 @ 0)
ファイルシステムを作って、ファイルの読み書きをしてみようか
# mkfs.xfs /dev/bcache0
# mount /dev/bcache0 /media/
# date > /media/hello
アンマウント、マウント
# cat /media/hello
2014年 1月 12日 日曜日 16:07:40 JST
cat-2527 [000] .... 1197.428426: bcache_request_start: 8,48 R 112 + 8 (from 252,0 @ 96)
ksoftirqd/0-3 [000] ..s. 1197.430197: bcache_read: 8,48 R 112 + 8 hit 1 bypass 0
ksoftirqd/0-3 [000] ..s. 1197.430204: bcache_request_end: 8,48 R 112 + 8 (from 252,0 @ 96)
# date >> /media/hello; sync
kworker/0:1-1978 [000] .... 1205.050565: bcache_request_start: 8,48 FWFSM 8257084 + 2 (from 252,0 @ 8257068)
kworker/0:1-1978 [000] .... 1205.050573: bcache_write: 8,48 FWFSM 8257084 + 2 hit 1 bypass 0
kworker/0:1-1978 [000] .... 1205.050583: bcache_cache_insert: 0:8257086 len 2 dirty 1
kworker/0:1-1978 [000] .... 1205.148263: bcache_journal_write: 8,32 FWFSM 1082 + 1
kworker/0:1-1978 [000] .... 1205.148307: bcache_btree_insert_key: 3 for 0 at 6(0): 0:8257086 len 2 dirty 1
ksoftirqd/0-3 [000] ..s. 1205.241711: bcache_request_end: 8,48 FWFSM 8257084 + 2 (from 252,0 @ 8257068)
kworker/0:0-1177 [000] .... 1215.803969: bcache_writeback: 0:19 len 2 dirty 1
kworker/0:0-1177 [000] .... 1215.804012: bcache_writeback: 0:48 len 24 dirty 1
kworker/0:0-1177 [000] .... 1215.804022: bcache_writeback: 0:96 len 16 dirty 1
kworker/u2:0-2420 [000] .... 1215.804045: bcache_btree_write: bucket 6
kworker/0:0-1177 [000] .... 1215.805170: bcache_btree_insert_key: 3 for 1 at 6(0): 0:19 len 2 dirty 0
kworker/0:0-1177 [000] .... 1215.807778: bcache_btree_insert_key: 3 for 1 at 6(0): 0:48 len 24 dirty 0
kworker/0:0-1177 [000] .... 1215.808773: bcache_btree_insert_key: 3 for 1 at 6(0): 0:96 len 16 dirty 0
kworker/0:1-1978 [000] .... 1235.134581: bcache_request_start: 8,48 FWFSM 8257086 + 2 (from 252,0 @ 8257070)
kworker/0:1-1978 [000] .... 1235.134590: bcache_write: 8,48 FWFSM 8257086 + 2 hit 1 bypass 0
kworker/0:1-1978 [000] .... 1235.134601: bcache_cache_insert: 0:8257088 len 2 dirty 1
kworker/0:0-1177 [000] .... 1235.135856: bcache_journal_write: 8,32 FWFSM 1083 + 1
kworker/0:0-1177 [000] .... 1235.135920: bcache_btree_insert_key: 3 for 0 at 6(0): 0:8257088 len 2 dirty 1
ksoftirqd/0-3 [000] ..s. 1235.136895: bcache_request_end: 8,48 FWFSM 8257086 + 2 (from 252,0 @ 8257070)
xfsaild/bcache0-2526 [000] .... 1235.136990: bcache_request_start: 8,48 WM 16 + 1 (from 252,0 @ 0)
xfsaild/bcache0-2526 [000] .... 1235.136997: bcache_write: 8,48 WM 16 + 1 hit 1 bypass 0
xfsaild/bcache0-2526 [000] .... 1235.137003: bcache_cache_insert: 0:17 len 1 dirty 1
xfsaild/bcache0-2526 [000] .... 1235.137023: bcache_request_start: 8,48 WM 80 + 16 (from 252,0 @ 64)
xfsaild/bcache0-2526 [000] .... 1235.137030: bcache_write: 8,48 WM 80 + 16 hit 1 bypass 0
xfsaild/bcache0-2526 [000] .... 1235.137031: bcache_cache_insert: 0:96 len 16 dirty 1
kworker/0:1-1978 [000] .... 1235.242168: bcache_journal_write: 8,32 FWFSM 1084 + 1
kworker/0:1-1978 [000] .... 1235.242222: bcache_btree_insert_key: 3 for 0 at 6(0): 0:17 len 1 dirty 1
kworker/0:1-1978 [000] .... 1235.242225: bcache_request_end: 8,48 WM 16 + 1 (from 252,0 @ 0)
kworker/0:1-1978 [000] .... 1235.242247: bcache_btree_insert_key: 3 for 0 at 6(0): 0:96 len 16 dirty 1
kworker/0:1-1978 [000] .... 1235.242248: bcache_request_end: 8,48 WM 80 + 16 (from 252,0 @ 64)
kworker/0:1-1978 [000] .... 1235.342561: bcache_journal_write: 8,32 FWFSM 1085 + 1
kworker/u2:0-2420 [000] .... 1245.887966: bcache_btree_write: bucket 6
kworker/0:1-1978 [000] .... 1245.888138: bcache_writeback: 0:8257086 len 2 dirty 1
kworker/0:1-1978 [000] .... 1245.989824: bcache_writeback_collision: 0:8257086 len 2 dirty 0
kworker/0:0-1177 [000] .... 1265.218607: bcache_request_start: 8,48 FWFSM 8257088 + 2 (from 252,0 @ 8257072)
kworker/0:0-1177 [000] .... 1265.218616: bcache_write: 8,48 FWFSM 8257088 + 2 hit 1 bypass 0
kworker/0:0-1177 [000] .... 1265.218625: bcache_cache_insert: 0:8257090 len 2 dirty 1
kworker/0:1-1978 [000] .... 1265.317562: bcache_journal_write: 8,32 FWFSM 1086 + 1
kworker/0:1-1978 [000] .... 1265.317637: bcache_btree_insert_key: 3 for 0 at 6(0): 0:8257090 len 2 dirty 1
ksoftirqd/0-3 [000] ..s. 1265.318913: bcache_request_end: 8,48 FWFSM 8257088 + 2 (from 252,0 @ 8257072)
xfsaild/bcache0-2526 [000] .... 1265.318970: bcache_request_start: 8,48 WM 16 + 1 (from 252,0 @ 0)
xfsaild/bcache0-2526 [000] .... 1265.318978: bcache_bypass_congested: 8,48 WM 16 + 1
kworker/0:0-1177 [000] .... 1265.319028: bcache_btree_insert_key: 3 for 0 at 6(0): 0:17 len 1 dirty 0
ksoftirqd/0-3 [000] ..s. 1265.319408: bcache_request_end: 8,48 WM 17 + 0 (from 252,0 @ 1)
kworker/0:0-1177 [000] .... 1265.418564: bcache_journal_write: 8,32 FWFSM 1087 + 1
kworker/0:1-1978 [000] .... 1276.099998: bcache_writeback: 0:96 len 16 dirty 1
kworker/0:1-1978 [000] .... 1276.100034: bcache_writeback: 0:8257088 len 4 dirty 1
kworker/0:1-1978 [000] .... 1276.102875: bcache_btree_insert_key: 3 for 1 at 6(0): 0:96 len 16 dirty 0
kworker/0:1-1978 [000] .... 1276.103355: bcache_btree_insert_key: 3 for 1 at 6(0): 0:8257088 len 4 dirty 0
kworker/u2:0-2420 [000] .... 1295.430585: bcache_btree_write: bucket 6
kworker/0:1-1978 [000] .... 1295.430822: bcache_request_start: 8,48 FWFSM 8257090 + 2 (from 252,0 @ 8257074)
kworker/0:1-1978 [000] .... 1295.430827: bcache_write: 8,48 FWFSM 8257090 + 2 hit 1 bypass 0
kworker/0:1-1978 [000] .... 1295.430835: bcache_cache_insert: 0:8257092 len 2 dirty 1
kworker/0:0-1177 [000] .... 1295.433276: bcache_journal_write: 8,32 FWFSM 1088 + 1
kworker/0:0-1177 [000] .... 1295.433342: bcache_btree_insert_key: 3 for 0 at 6(0): 0:8257092 len 2 dirty 1
ksoftirqd/0-3 [000] ..s. 1295.434217: bcache_request_end: 8,48 FWFSM 8257090 + 2 (from 252,0 @ 8257074)
xfsaild/bcache0-2526 [000] .... 1295.434298: bcache_request_start: 8,48 WM 16 + 1 (from 252,0 @ 0)
xfsaild/bcache0-2526 [000] .... 1295.434304: bcache_write: 8,48 WM 16 + 1 hit 1 bypass 0
xfsaild/bcache0-2526 [000] .... 1295.434309: bcache_cache_insert: 0:17 len 1 dirty 1
kworker/0:1-1978 [000] .... 1295.537622: bcache_journal_write: 8,32 FWFSM 1089 + 1
kworker/0:1-1978 [000] .... 1295.537705: bcache_btree_insert_key: 3 for 0 at 6(0): 0:17 len 1 dirty 1
kworker/0:1-1978 [000] .... 1295.537710: bcache_request_end: 8,48 WM 16 + 1 (from 252,0 @ 0)
kworker/0:0-1177 [000] .... 1306.184023: bcache_writeback: 0:8257090 len 2 dirty 1
kworker/0:0-1177 [000] .... 1306.185288: bcache_btree_insert_key: 3 for 1 at 6(0): 0:8257090 len 2 dirty 0
kworker/u2:0-2420 [000] .... 1325.514630: bcache_btree_write: bucket 6
kworker/0:1-1978 [000] .... 1336.268051: bcache_writeback: 0:17 len 1 dirty 1
kworker/0:1-1978 [000] .... 1336.268114: bcache_writeback: 0:8257092 len 2 dirty 1
kworker/0:1-1978 [000] .... 1336.269216: bcache_btree_insert_key: 3 for 1 at 6(0): 0:17 len 1 dirty 0
kworker/0:1-1978 [000] .... 1336.271724: bcache_btree_insert_key: 3 for 1 at 6(0): 0:8257092 len 2 dirty 0
kworker/u2:1-2532 [000] .... 1366.352050: bcache_btree_write: bucket 6
kworker/u2:1-2532 [000] .... 1574.593766: bcache_request_start: 8,48 W 112 + 8 (from 252,0 @ 96)
kworker/u2:1-2532 [000] .... 1574.593777: bcache_write: 8,48 W 112 + 8 hit 1 bypass 0
kworker/u2:1-2532 [000] .... 1574.593798: bcache_cache_insert: 0:120 len 8 dirty 1
kworker/0:0-1177 [000] .... 1574.697220: bcache_journal_write: 8,32 FWFSM 1090 + 1
kworker/0:0-1177 [000] .... 1574.697290: bcache_btree_insert_key: 3 for 0 at 6(0): 0:120 len 8 dirty 1
kworker/0:0-1177 [000] .... 1574.697297: bcache_request_end: 8,48 W 112 + 8 (from 252,0 @ 96)
sync-2545 [000] .... 1574.732170: bcache_request_start: 8,48 FWFSM 8257092 + 2 (from 252,0 @ 8257076)
sync-2545 [000] .... 1574.732181: bcache_bypass_congested: 8,48 FWFSM 8257092 + 2
kworker/0:0-1177 [000] .... 1574.732253: bcache_btree_insert_key: 3 for 0 at 6(0): 0:8257094 len 2 dirty 0
kworker/0:0-1177 [000] .... 1574.899601: bcache_journal_write: 8,32 FWFSM 1091 + 1
ksoftirqd/0-3 [000] ..s. 1574.900642: bcache_request_end: 8,48 FWFSM 8257094 + 0 (from 252,0 @ 8257078)
見たい関数の多くが static で、フックできない。
# stap -v -e 'probe module("bcache").function("cached_dev_*") { print_backtrace() }'
0xf8564ed0 : cached_dev_read_complete+0x0/0x90 [bcache]
0xf8572373 : closure_queue+0x33/0x40 [bcache]
0xf8565aba : request_read_done_bh+0x16a/0x190 [bcache]
0xf8572373 : closure_queue+0x33/0x40 [bcache]
0xf857254e : closure_put+0xbe/0xd0 [bcache]
0xf855f7cd : bch_bbio_endio+0x2d/0x40 [bcache]
0xf8566286 : bch_cache_read_endio+0xb6/0xd0 [bcache]
0xf8563fb0 : cached_dev_cache_miss+0x0/0x240 [bcache]
0xf8553b5b : submit_partial_cache_miss+0xab/0xc0 [bcache]
0xf855a3e6 : bch_btree_search_recurse+0x376/0x390 [bcache]
0xf8565b81 : btree_read_async+0xa1/0x140 [bcache]
0xf8572373 : closure_queue+0x33/0x40 [bcache]
0xf8566f74 : cached_dev_make_request+0x2b4/0x390 [bcache]
0xf8564db9 : cached_dev_write_complete+0x19/0x50 [bcache]
0xf8572373 : closure_queue+0x33/0x40 [bcache]
0xf857254e : closure_put+0xbe/0xd0 [bcache]
0xf856421a : request_endio+0x2a/0x30 [bcache]
0xf8564dc3 : cached_dev_write_complete+0x23/0x50 [bcache]
0xf8572373 : closure_queue+0x33/0x40 [bcache]
0xf857254e : closure_put+0xbe/0xd0 [bcache]
0xf8572609 : closure_sub+0xa9/0xd0 [bcache]
0xf856617f : bch_btree_insert_async+0x5f/0xb0 [bcache]
0xf8561432 : bch_journal+0x32/0x270 [bcache]
# stap -v -e 'probe module("bcache").function("bch_*") { print_backtrace() }'
0xf855cae0 : bch_btree_iter_push+0x0/0x440 [bcache]
0xf855cf7a : __bch_btree_iter_init+0x5a/0x90 [bcache]
0xf8554d3d : btree_insert_key+0xfd/0x450 [bcache]
0xf8555157 : bch_btree_insert_keys+0xc7/0xf0 [bcache]
0xf85590ed : bch_btree_insert_recurse+0xbd/0xcd0 [bcache]
0xf8559e48 : bch_btree_insert+0x148/0x370 [bcache]
0xf8566133 : bch_btree_insert_async+0x13/0xb0 [bcache]
0xf8561432 : bch_journal+0x32/0x270 [bcache]
0xf855cae0 : bch_btree_iter_push+0x0/0x440 [bcache]
0xf855cf7a : __bch_btree_iter_init+0x5a/0x90 [bcache]
0xf8554d3d : btree_insert_key+0xfd/0x450 [bcache]
0xf8555157 : bch_btree_insert_keys+0xc7/0xf0 [bcache]
0xf85590ed : bch_btree_insert_recurse+0xbd/0xcd0 [bcache]
0xf8559e48 : bch_btree_insert+0x148/0x370 [bcache]
0xf8566133 : bch_btree_insert_async+0x13/0xb0 [bcache]
0xf8561432 : bch_journal+0x32/0x270 [bcache]
関数名と実行プロセス名を出す。
# stap -v -e 'probe module("bcache").function("cached_dev_*") { printf("%s %s\n", execname(), ppfunc()) }'
# dd if=/dev/bcache0 bs=1024 count=1
dd cached_dev_make_request
dd cached_dev_get
dd cached_dev_cache_miss
dd cached_dev_make_request
dd cached_dev_get
dd cached_dev_make_request
dd cached_dev_get
dd cached_dev_make_request
dd cached_dev_get
ksoftirqd/0 cached_dev_read_complete
ksoftirqd/0 cached_dev_bio_complete
ksoftirqd/0 cached_dev_put
ksoftirqd/0 cached_dev_read_complete
ksoftirqd/0 cached_dev_bio_complete
ksoftirqd/0 cached_dev_put
ksoftirqd/0 cached_dev_read_complete
ksoftirqd/0 cached_dev_bio_complete
ksoftirqd/0 cached_dev_put
kworker/0:0 cached_dev_read_complete
kworker/0:0 cached_dev_bio_complete
kworker/0:0 cached_dev_put
# dd if=/dev/zero of=/dev/bcache0 bs=1024 count=1
dd cached_dev_make_request
dd cached_dev_get
ksoftirqd/0 cached_dev_read_complete
ksoftirqd/0 cached_dev_bio_complete
ksoftirqd/0 cached_dev_put
dd cached_dev_make_request
dd cached_dev_get
kworker/0:0 cached_dev_write_complete
kworker/0:0 cached_dev_bio_complete
kworker/0:0 cached_dev_put
systemd-udevd cached_dev_ioctl
systemd-udevd cached_dev_make_request
systemd-udevd cached_dev_get
ksoftirqd/0 cached_dev_read_complete
ksoftirqd/0 cached_dev_bio_complete
ksoftirqd/0 cached_dev_put
systemd-udevd cached_dev_make_request
systemd-udevd cached_dev_get
ksoftirqd/0 cached_dev_read_complete
ksoftirqd/0 cached_dev_bio_complete
ksoftirqd/0 cached_dev_put
何をしているのかよくわからんが、やたらに動く。
トレースは編集してあります。どう動いているのかよくわからないので、とりあえず、as is で置きます。ライトバック指定で、デバイス先頭１K に SYNC 書き込み。同じ所をリード。結果から、cached_dev, bch_, closure の含まれる行だけを抜き出した。
ライトバック
ftrace.py-584 [000] .... 1126.405040: cached_dev_make_request <-generic_make_request
ftrace.py-584 [000] .... 1126.405041: search_alloc <-cached_dev_make_request
ftrace.py-584 [000] .... 1126.405045: request_write <-cached_dev_make_request
ftrace.py-584 [000] .... 1126.405046: bch_keybuf_check_overlapping <-request_write
ftrace.py-584 [000] .... 1126.405047: bch_get_congested <-check_should_skip
ftrace.py-584 [000] .... 1126.405049: bch_rescale_priorities <-check_should_skip
ftrace.py-584 [000] .... 1126.405049: mutex_lock <-bch_rescale_priorities
ftrace.py-584 [000] .... 1126.405057: mutex_unlock <-bch_rescale_priorities
ftrace.py-584 [000] .... 1126.405058: bch_keybuf_check_overlapping <-request_write
ftrace.py-584 [000] .... 1126.405060: bch_writeback_add <-request_write
ftrace.py-584 [000] .... 1126.405060: bch_write_bdev_super <-bch_writeback_add
ftrace.py-584 [000] .... 1126.405061: __closure_lock <-bch_write_bdev_super
ftrace.py-584 [000] .... 1126.405061: closure_trylock <-__closure_lock
ftrace.py-584 [000] .... 1126.405062: bio_reset <-bch_write_bdev_super
ftrace.py-584 [000] .... 1126.405063: __write_super <-bch_write_bdev_super
ftrace.py-584 [000] .... 1126.405064: bch_bio_map <-__write_super
ftrace.py-584 [000] .... 1126.405065: bch_crc64 <-__write_super
ftrace.py-584 [000] .... 1126.405076: closure_sub <-bch_write_bdev_super
ftrace.py-584 [000] .... 1126.405076: bch_writeback_queue <-bch_writeback_add
ftrace.py-584 [000] .... 1126.405077: closure_trylock <-bch_writeback_queue
ftrace.py-584 [000] .... 1126.405077: __closure_delay <-bch_writeback_queue
ftrace.py-584 [000] .... 1126.405077: add_timer <-__closure_delay
ftrace.py-584 [000] .... 1126.405081: closure_sub <-bch_writeback_queue
ftrace.py-584 [000] .... 1126.405081: queue_delayed_work_on <-bch_writeback_add
ftrace.py-584 [000] .... 1126.405085: closure_queue <-request_write
ftrace.py-584 [000] .... 1126.405086: bch_insert_data <-closure_queue
ftrace.py-584 [000] .... 1126.405086: bch_insert_data_loop <-bch_insert_data
ftrace.py-584 [000] .... 1126.405087: bch_keylist_realloc <-bch_insert_data_loop
ftrace.py-584 [000] .... 1126.405087: bch_alloc_sectors <-bch_insert_data_loop
ftrace.py-584 [000] .... 1126.405088: _raw_spin_lock <-bch_alloc_sectors
ftrace.py-584 [000] .... 1126.405090: bch_bucket_alloc_set <-bch_alloc_sectors
ftrace.py-584 [000] .... 1126.405090: mutex_lock <-bch_bucket_alloc_set
ftrace.py-584 [000] .... 1126.405091: __bch_bucket_alloc_set <-bch_bucket_alloc_set
ftrace.py-584 [000] .... 1126.405092: bch_bucket_alloc <-__bch_bucket_alloc_set
ftrace.py-584 [000] .... 1126.405093: wake_up_process <-bch_bucket_alloc
ftrace.py-584 [000] .N.. 1126.405105: mutex_unlock <-bch_bucket_alloc_set
ftrace.py-584 [000] .N.. 1126.405105: _raw_spin_lock <-bch_alloc_sectors
ftrace.py-584 [000] .N.. 1126.405106: memcpy <-bch_alloc_sectors
ftrace.py-584 [000] .N.. 1126.405108: bch_bio_split <-bch_insert_data_loop
ftrace.py-584 [000] .N.. 1126.405109: bch_submit_bbio <-bch_insert_data_loop
ftrace.py-584 [000] .N.. 1126.405109: bch_bkey_copy_single_ptr <-bch_submit_bbio
ftrace.py-584 [000] .N.. 1126.405110: __bch_submit_bbio <-bch_submit_bbio
ftrace.py-584 [000] .N.. 1126.405111: bch_generic_make_request <-__bch_submit_bbio
ftrace.py-584 [000] .N.. 1126.405111: bch_bio_max_sectors <-bch_generic_make_request
ftrace.py-584 [000] .N.. 1126.405112: bch_generic_make_request_hack <-bch_generic_make_request
ftrace.py-584 [000] .N.. 1126.405113: generic_make_request <-bch_generic_make_request_hack
bcache_allocato-424 [000] .... 1126.405123: mutex_lock <-bch_allocator_thread
bcache_allocato-424 [000] .... 1126.405124: __closure_wake_up <-bch_allocator_thread
bcache_allocato-424 [000] .... 1126.405125: mutex_unlock <-bch_allocator_thread
bcache_allocato-424 [000] .... 1126.405125: kthread_should_stop <-bch_allocator_thread
bcache_allocato-424 [000] .... 1126.405126: _cond_resched <-bch_allocator_thread
bcache_allocato-424 [000] .... 1126.405126: schedule <-bch_allocator_thread
ftrace.py-584 [000] .... 1126.405139: closure_sub <-bch_insert_data_loop
ftrace.py-584 [000] .... 1126.405139: closure_sub <-request_write
ksoftirqd/0-3 [000] ..s. 1126.407289: closure_put <-write_bdev_super_endio
ksoftirqd/0-3 [000] ..s. 1126.407289: __closure_wake_up <-closure_put
ksoftirqd/0-3 [000] ..s. 1126.505693: bch_insert_data_endio <-bio_endio
ksoftirqd/0-3 [000] ..s. 1126.505693: bch_bbio_endio <-bch_insert_data_endio
ksoftirqd/0-3 [000] ..s. 1126.505694: bch_bbio_count_io_errors <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1126.505695: bch_count_io_errors <-bch_bbio_count_io_errors
ksoftirqd/0-3 [000] ..s. 1126.505696: bio_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1126.505696: closure_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1126.505697: closure_queue <-closure_put
ksoftirqd/0-3 [000] ..s. 1126.505697: queue_work_on <-closure_queue
kworker/0:0-4 [000] .... 1126.505795: bch_journal <-process_one_work
kworker/0:0-4 [000] .... 1126.505796: _raw_spin_lock <-bch_journal
kworker/0:0-4 [000] .... 1126.505797: memcpy <-bch_journal
kworker/0:0-4 [000] .... 1126.505798: __journal_try_write <-bch_journal
kworker/0:0-4 [000] .... 1126.505798: closure_trylock <-__journal_try_write
kworker/0:0-4 [000] .... 1126.505801: bch_crc64 <-journal_write_unlocked
kworker/0:0-4 [000] .... 1126.505807: bch_bio_map <-journal_write_unlocked
kworker/0:0-4 [000] .... 1126.505808: bch_journal_next <-journal_write_unlocked
kworker/0:0-4 [000] .... 1126.505810: bch_generic_make_request <-journal_write_unlocked
kworker/0:0-4 [000] .... 1126.505811: bch_bio_max_sectors <-bch_generic_make_request
kworker/0:0-4 [000] .... 1126.505812: bch_generic_make_request_hack <-bch_generic_make_request
kworker/0:0-4 [000] .... 1126.505812: generic_make_request <-bch_generic_make_request_hack
kworker/0:0-4 [000] .... 1126.505894: closure_sub <-journal_write_unlocked
kworker/0:0-4 [000] .... 1126.505894: bch_btree_insert_async <-bch_journal
kworker/0:0-4 [000] .... 1126.505895: bch_btree_insert <-bch_btree_insert_async
kworker/0:0-4 [000] .... 1126.505896: bch_keylist_copy <-bch_btree_insert
kworker/0:0-4 [000] .... 1126.505897: bch_keylist_pop <-bch_btree_insert
kworker/0:0-4 [000] .... 1126.505897: memcpy <-bch_btree_insert
kworker/0:0-4 [000] .... 1126.505898: down_write <-bch_btree_insert
kworker/0:0-4 [000] .... 1126.505899: bch_btree_insert_recurse <-bch_btree_insert
kworker/0:0-4 [000] .... 1126.505900: bch_btree_insert_keys <-bch_btree_insert_recurse
kworker/0:0-4 [000] .... 1126.505900: bch_keylist_pop <-bch_btree_insert_keys
kworker/0:0-4 [000] .... 1126.505901: btree_insert_key <-bch_btree_insert_keys
kworker/0:0-4 [000] .... 1126.505902: __bch_btree_iter_init <-btree_insert_key
kworker/0:0-4 [000] .... 1126.505903: __bch_bset_search <-__bch_btree_iter_init
kworker/0:0-4 [000] .... 1126.505904: bch_btree_iter_push <-__bch_btree_iter_init
kworker/0:0-4 [000] .... 1126.505904: __bch_bset_search <-__bch_btree_iter_init
kworker/0:0-4 [000] .... 1126.505905: bch_btree_iter_push <-__bch_btree_iter_init
kworker/0:0-4 [000] .... 1126.505906: bch_btree_iter_next <-fix_overlapping_extents
kworker/0:0-4 [000] .... 1126.505908: __bch_cut_front <-fix_overlapping_extents
kworker/0:0-4 [000] .... 1126.505910: bch_btree_iter_next <-fix_overlapping_extents
kworker/0:0-4 [000] .... 1126.505914: bch_bset_fix_lookup_table <-shift_keys
kworker/0:0-4 [000] .... 1126.505916: bch_keylist_pop <-bch_btree_insert_keys
kworker/0:0-4 [000] .... 1126.505917: queue_delayed_work_on <-bch_btree_insert_recurse
kworker/0:0-4 [000] .... 1126.505922: up_write <-bch_btree_insert
kworker/0:0-4 [000] .... 1126.505922: closure_sub <-bch_btree_insert_async
kworker/0:0-4 [000] .... 1126.505923: closure_put <-closure_sub
kworker/0:0-4 [000] .... 1126.505923: closure_queue <-closure_put
kworker/0:0-4 [000] .... 1126.505923: cached_dev_write_complete <-closure_queue
kworker/0:0-4 [000] .... 1126.505924: up_read <-cached_dev_write_complete
kworker/0:0-4 [000] .... 1126.505924: search_free <-cached_dev_write_complete
ftrace.py-584 [000] .... 1126.505989: cached_dev_make_request <-generic_make_request
ftrace.py-584 [000] .... 1126.505990: search_alloc <-cached_dev_make_request
ftrace.py-584 [000] .... 1126.505992: bch_journal_meta <-cached_dev_make_request
ftrace.py-584 [000] .... 1126.505992: _raw_spin_lock <-bch_journal_meta
ftrace.py-584 [000] .... 1126.505993: closure_wait <-bch_journal_meta
ftrace.py-584 [000] .... 1126.505993: __closure_flush <-bch_journal_meta
ftrace.py-584 [000] .... 1126.505994: del_timer <-__closure_flush
ftrace.py-584 [000] .... 1126.505994: __journal_try_write <-bch_journal_meta
ftrace.py-584 [000] .... 1126.505994: closure_trylock <-__journal_try_write
ftrace.py-584 [000] .... 1126.505995: bch_generic_make_request <-cached_dev_make_request
ftrace.py-584 [000] .... 1126.505995: bch_generic_make_request_hack <-bch_generic_make_request
ftrace.py-584 [000] .... 1126.505995: generic_make_request <-bch_generic_make_request_hack
ftrace.py-584 [000] .... 1126.505998: closure_put <-request_endio
ftrace.py-584 [000] .... 1126.505998: closure_sub <-cached_dev_make_request
ksoftirqd/0-3 [000] ..s. 1126.571814: closure_put <-journal_write_endio
ksoftirqd/0-3 [000] ..s. 1126.571815: closure_queue <-closure_put
ksoftirqd/0-3 [000] ..s. 1126.571815: journal_write_done <-closure_queue
ksoftirqd/0-3 [000] ..s. 1126.571816: __closure_wake_up <-journal_write_done
ksoftirqd/0-3 [000] ..s. 1126.571816: __closure_delay <-journal_write_done
ksoftirqd/0-3 [000] ..s. 1126.571816: add_timer <-__closure_delay
ksoftirqd/0-3 [000] ..s. 1126.571820: closure_sub <-journal_write_done
<idle>-0 [000] ..s. 1126.670915: closure_delay_timer_fn <-call_timer_fn
<idle>-0 [000] ..s. 1126.670915: closure_sub <-closure_delay_timer_fn
<idle>-0 [000] ..s. 1126.670915: closure_queue <-closure_sub
<idle>-0 [000] ..s. 1126.670916: queue_work_on <-closure_queue
kworker/0:0-4 [000] .... 1126.670966: bch_crc64 <-journal_write_unlocked
kworker/0:0-4 [000] .... 1126.670970: bch_bio_map <-journal_write_unlocked
kworker/0:0-4 [000] .... 1126.670971: bch_journal_next <-journal_write_unlocked
kworker/0:0-4 [000] .... 1126.670973: bch_generic_make_request <-journal_write_unlocked
kworker/0:0-4 [000] .... 1126.670973: bch_bio_max_sectors <-bch_generic_make_request
kworker/0:0-4 [000] .... 1126.670973: bch_generic_make_request_hack <-bch_generic_make_request
kworker/0:0-4 [000] .... 1126.670974: generic_make_request <-bch_generic_make_request_hack
kworker/0:0-4 [000] .... 1126.671055: closure_sub <-journal_write_unlocked
ksoftirqd/0-3 [000] ..s. 1126.672174: closure_put <-journal_write_endio
ksoftirqd/0-3 [000] ..s. 1126.672174: closure_queue <-closure_put
ksoftirqd/0-3 [000] ..s. 1126.672174: journal_write_done <-closure_queue
ksoftirqd/0-3 [000] ..s. 1126.672175: __closure_wake_up <-journal_write_done
ksoftirqd/0-3 [000] ..s. 1126.672175: closure_sub <-__closure_wake_up
ksoftirqd/0-3 [000] ..s. 1126.672176: closure_queue <-closure_sub
ksoftirqd/0-3 [000] ..s. 1126.672176: cached_dev_bio_complete <-closure_queue
ksoftirqd/0-3 [000] ..s. 1126.672177: search_free <-cached_dev_bio_complete
ksoftirqd/0-3 [000] ..s. 1126.672199: __closure_delay <-journal_write_done
ksoftirqd/0-3 [000] ..s. 1126.672200: add_timer <-__closure_delay
ksoftirqd/0-3 [000] ..s. 1126.672203: closure_sub <-journal_write_done
リード
ftrace.py-607 [000] .... 1170.895694: cached_dev_make_request <-generic_make_request
ftrace.py-607 [000] .... 1170.895695: search_alloc <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895699: check_should_skip <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895699: bch_get_congested <-check_should_skip
ftrace.py-607 [000] .... 1170.895701: bch_rescale_priorities <-check_should_skip
ftrace.py-607 [000] .... 1170.895702: closure_queue <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895702: btree_read_async <-closure_queue
ftrace.py-607 [000] .... 1170.895704: bch_btree_search_recurse <-btree_read_async
ftrace.py-607 [000] .... 1170.895704: __bch_btree_iter_init <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895705: __bch_bset_search <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895706: bch_btree_iter_push <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895706: __bch_bset_search <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895707: bch_btree_iter_push <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895708: bch_btree_iter_next_filter <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895708: bch_btree_iter_next <-bch_btree_iter_next_filter
ftrace.py-607 [000] .... 1170.895709: bch_ptr_bad <-bch_btree_iter_next_filter
ftrace.py-607 [000] .... 1170.895710: __bch_ptr_invalid <-bch_ptr_bad
ftrace.py-607 [000] .... 1170.895712: submit_partial_cache_miss <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895714: bch_bio_split <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895714: bch_bkey_copy_single_ptr <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895715: __bch_submit_bbio <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895716: bch_generic_make_request <-__bch_submit_bbio
ftrace.py-607 [000] .... 1170.895716: bch_bio_max_sectors <-bch_generic_make_request
ftrace.py-607 [000] .... 1170.895717: bch_generic_make_request_hack <-bch_generic_make_request
ftrace.py-607 [000] .... 1170.895718: generic_make_request <-bch_generic_make_request_hack
ftrace.py-607 [000] .... 1170.895721: bch_cannibalize_unlock <-btree_read_async
ftrace.py-607 [000] .... 1170.895722: closure_sub <-btree_read_async
ftrace.py-607 [000] .... 1170.895722: closure_put <-closure_sub
ftrace.py-607 [000] .... 1170.895723: closure_sub <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895772: cached_dev_make_request <-generic_make_request
ftrace.py-607 [000] .... 1170.895773: search_alloc <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895774: check_should_skip <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895775: bch_get_congested <-check_should_skip
ftrace.py-607 [000] .... 1170.895775: bch_rescale_priorities <-check_should_skip
ftrace.py-607 [000] .... 1170.895776: closure_queue <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895776: btree_read_async <-closure_queue
ftrace.py-607 [000] .... 1170.895777: bch_btree_search_recurse <-btree_read_async
ftrace.py-607 [000] .... 1170.895777: __bch_btree_iter_init <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895778: __bch_bset_search <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895778: __to_inorder <-__bch_bset_search
ftrace.py-607 [000] .... 1170.895779: bch_btree_iter_push <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895779: __bch_bset_search <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895779: bch_btree_iter_push <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895780: bch_btree_iter_next_filter <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895780: bch_btree_iter_next <-bch_btree_iter_next_filter
ftrace.py-607 [000] .... 1170.895780: bch_ptr_bad <-bch_btree_iter_next_filter
ftrace.py-607 [000] .... 1170.895781: __bch_ptr_invalid <-bch_ptr_bad
ftrace.py-607 [000] .... 1170.895781: submit_partial_cache_miss <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895782: bch_bio_split <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895782: bch_bkey_copy_single_ptr <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895782: __bch_submit_bbio <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895783: bch_generic_make_request <-__bch_submit_bbio
ftrace.py-607 [000] .... 1170.895783: bch_bio_max_sectors <-bch_generic_make_request
ftrace.py-607 [000] .... 1170.895783: bch_generic_make_request_hack <-bch_generic_make_request
ftrace.py-607 [000] .... 1170.895784: generic_make_request <-bch_generic_make_request_hack
ftrace.py-607 [000] .... 1170.895786: bch_cannibalize_unlock <-btree_read_async
ftrace.py-607 [000] .... 1170.895786: closure_sub <-btree_read_async
ftrace.py-607 [000] .... 1170.895786: closure_put <-closure_sub
ftrace.py-607 [000] .... 1170.895787: closure_sub <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895814: cached_dev_make_request <-generic_make_request
ftrace.py-607 [000] .... 1170.895815: search_alloc <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895817: check_should_skip <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895817: bch_get_congested <-check_should_skip
ftrace.py-607 [000] .... 1170.895818: bch_rescale_priorities <-check_should_skip
ftrace.py-607 [000] .... 1170.895818: closure_queue <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895818: btree_read_async <-closure_queue
ftrace.py-607 [000] .... 1170.895819: bch_btree_search_recurse <-btree_read_async
ftrace.py-607 [000] .... 1170.895820: __bch_btree_iter_init <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895820: __bch_bset_search <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895820: __to_inorder <-__bch_bset_search
ftrace.py-607 [000] .... 1170.895821: bch_btree_iter_push <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895821: __bch_bset_search <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895821: bch_btree_iter_push <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895822: bch_btree_iter_next_filter <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895822: bch_btree_iter_next <-bch_btree_iter_next_filter
ftrace.py-607 [000] .... 1170.895822: bch_ptr_bad <-bch_btree_iter_next_filter
ftrace.py-607 [000] .... 1170.895823: __bch_ptr_invalid <-bch_ptr_bad
ftrace.py-607 [000] .... 1170.895823: submit_partial_cache_miss <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895823: bch_bio_split <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895824: bch_bkey_copy_single_ptr <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895824: __bch_submit_bbio <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895824: bch_generic_make_request <-__bch_submit_bbio
ftrace.py-607 [000] .... 1170.895825: bch_bio_max_sectors <-bch_generic_make_request
ftrace.py-607 [000] .... 1170.895825: bch_generic_make_request_hack <-bch_generic_make_request
ftrace.py-607 [000] .... 1170.895825: generic_make_request <-bch_generic_make_request_hack
ftrace.py-607 [000] .... 1170.895827: bch_cannibalize_unlock <-btree_read_async
ftrace.py-607 [000] .... 1170.895828: closure_sub <-btree_read_async
ftrace.py-607 [000] .... 1170.895828: closure_put <-closure_sub
ftrace.py-607 [000] .... 1170.895828: closure_sub <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895847: cached_dev_make_request <-generic_make_request
ftrace.py-607 [000] .... 1170.895847: search_alloc <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895849: check_should_skip <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895850: bch_get_congested <-check_should_skip
ftrace.py-607 [000] .... 1170.895850: bch_rescale_priorities <-check_should_skip
ftrace.py-607 [000] .... 1170.895850: closure_queue <-cached_dev_make_request
ftrace.py-607 [000] .... 1170.895851: btree_read_async <-closure_queue
ftrace.py-607 [000] .... 1170.895852: bch_btree_search_recurse <-btree_read_async
ftrace.py-607 [000] .... 1170.895852: __bch_btree_iter_init <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895852: __bch_bset_search <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895853: __to_inorder <-__bch_bset_search
ftrace.py-607 [000] .... 1170.895853: bch_btree_iter_push <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895853: __bch_bset_search <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895854: bch_btree_iter_push <-__bch_btree_iter_init
ftrace.py-607 [000] .... 1170.895854: bch_btree_iter_next_filter <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895854: bch_btree_iter_next <-bch_btree_iter_next_filter
ftrace.py-607 [000] .... 1170.895855: bch_ptr_bad <-bch_btree_iter_next_filter
ftrace.py-607 [000] .... 1170.895855: __bch_ptr_invalid <-bch_ptr_bad
ftrace.py-607 [000] .... 1170.895855: submit_partial_cache_miss <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895856: bch_bio_split <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895856: bch_bkey_copy_single_ptr <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895856: __bch_submit_bbio <-bch_btree_search_recurse
ftrace.py-607 [000] .... 1170.895857: bch_generic_make_request <-__bch_submit_bbio
ftrace.py-607 [000] .... 1170.895857: bch_bio_max_sectors <-bch_generic_make_request
ftrace.py-607 [000] .... 1170.895858: bch_generic_make_request_hack <-bch_generic_make_request
ftrace.py-607 [000] .... 1170.895858: generic_make_request <-bch_generic_make_request_hack
ftrace.py-607 [000] .... 1170.895860: bch_cannibalize_unlock <-btree_read_async
ftrace.py-607 [000] .... 1170.895860: closure_sub <-btree_read_async
ftrace.py-607 [000] .... 1170.895860: closure_put <-closure_sub
ftrace.py-607 [000] .... 1170.895861: closure_sub <-cached_dev_make_request
ksoftirqd/0-3 [000] ..s. 1170.897280: bch_cache_read_endio <-bio_endio
ksoftirqd/0-3 [000] ..s. 1170.897281: bch_bbio_endio <-bch_cache_read_endio
ksoftirqd/0-3 [000] ..s. 1170.897281: bch_bbio_count_io_errors <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.897282: bch_count_io_errors <-bch_bbio_count_io_errors
ksoftirqd/0-3 [000] ..s. 1170.897282: bio_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.897283: closure_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.897283: closure_queue <-closure_put
ksoftirqd/0-3 [000] ..s. 1170.897284: request_read_done_bh <-closure_queue
ksoftirqd/0-3 [000] ..s. 1170.897284: bch_mark_cache_accounting <-request_read_done_bh
ksoftirqd/0-3 [000] ..s. 1170.897285: mark_cache_stats <-bch_mark_cache_accounting
ksoftirqd/0-3 [000] ..s. 1170.897285: mark_cache_stats <-bch_mark_cache_accounting
ksoftirqd/0-3 [000] ..s. 1170.897286: closure_queue <-request_read_done_bh
ksoftirqd/0-3 [000] ..s. 1170.897287: cached_dev_read_complete <-closure_queue
ksoftirqd/0-3 [000] ..s. 1170.897287: search_free <-cached_dev_read_complete
ksoftirqd/0-3 [000] ..s. 1170.897298: bch_cache_read_endio <-bio_endio
ksoftirqd/0-3 [000] ..s. 1170.897299: bch_bbio_endio <-bch_cache_read_endio
ksoftirqd/0-3 [000] ..s. 1170.897299: bch_bbio_count_io_errors <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.897300: bch_count_io_errors <-bch_bbio_count_io_errors
ksoftirqd/0-3 [000] ..s. 1170.897300: bio_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.897300: closure_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.897301: closure_queue <-closure_put
ksoftirqd/0-3 [000] ..s. 1170.897301: request_read_done_bh <-closure_queue
ksoftirqd/0-3 [000] ..s. 1170.897301: bch_mark_cache_accounting <-request_read_done_bh
ksoftirqd/0-3 [000] ..s. 1170.897302: mark_cache_stats <-bch_mark_cache_accounting
ksoftirqd/0-3 [000] ..s. 1170.897302: mark_cache_stats <-bch_mark_cache_accounting
ksoftirqd/0-3 [000] ..s. 1170.897302: closure_queue <-request_read_done_bh
ksoftirqd/0-3 [000] ..s. 1170.897303: cached_dev_read_complete <-closure_queue
ksoftirqd/0-3 [000] ..s. 1170.897303: search_free <-cached_dev_read_complete
ksoftirqd/0-3 [000] ..s. 1170.897311: bch_cache_read_endio <-bio_endio
ksoftirqd/0-3 [000] ..s. 1170.897311: bch_bbio_endio <-bch_cache_read_endio
ksoftirqd/0-3 [000] ..s. 1170.897311: bch_bbio_count_io_errors <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.897312: bch_count_io_errors <-bch_bbio_count_io_errors
ksoftirqd/0-3 [000] ..s. 1170.897312: bio_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.897313: closure_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.897313: closure_queue <-closure_put
ksoftirqd/0-3 [000] ..s. 1170.897313: request_read_done_bh <-closure_queue
ksoftirqd/0-3 [000] ..s. 1170.897313: bch_mark_cache_accounting <-request_read_done_bh
ksoftirqd/0-3 [000] ..s. 1170.897314: mark_cache_stats <-bch_mark_cache_accounting
ksoftirqd/0-3 [000] ..s. 1170.897314: mark_cache_stats <-bch_mark_cache_accounting
ksoftirqd/0-3 [000] ..s. 1170.897314: closure_queue <-request_read_done_bh
ksoftirqd/0-3 [000] ..s. 1170.897315: cached_dev_read_complete <-closure_queue
ksoftirqd/0-3 [000] ..s. 1170.897315: search_free <-cached_dev_read_complete
ksoftirqd/0-3 [000] ..s. 1170.898146: bch_cache_read_endio <-bio_endio
ksoftirqd/0-3 [000] ..s. 1170.898147: bch_bbio_endio <-bch_cache_read_endio
ksoftirqd/0-3 [000] ..s. 1170.898147: bch_bbio_count_io_errors <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.898148: bch_count_io_errors <-bch_bbio_count_io_errors
ksoftirqd/0-3 [000] ..s. 1170.898148: bio_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.898148: closure_put <-bch_bbio_endio
ksoftirqd/0-3 [000] ..s. 1170.898149: closure_queue <-closure_put
ksoftirqd/0-3 [000] ..s. 1170.898149: request_read_done_bh <-closure_queue
ksoftirqd/0-3 [000] ..s. 1170.898149: bch_mark_cache_accounting <-request_read_done_bh
ksoftirqd/0-3 [000] ..s. 1170.898150: mark_cache_stats <-bch_mark_cache_accounting
ksoftirqd/0-3 [000] ..s. 1170.898150: mark_cache_stats <-bch_mark_cache_accounting
ksoftirqd/0-3 [000] ..s. 1170.898150: closure_queue <-request_read_done_bh
ksoftirqd/0-3 [000] ..s. 1170.898151: cached_dev_read_complete <-closure_queue
ksoftirqd/0-3 [000] ..s. 1170.898151: search_free <-cached_dev_read_complete
をつけてビルドすると、データ構造のダンプが見られるそうな。
# cat /sys/kernel/debug/bcache/bcache-243f7556-9a22-4abe-9ab3-3ab28b9656af
0:17 len 1 -> [0:16603 gen 0] dirty
0:19 len 2 -> [0:16542 gen 0]
0:20 len 1 -> [0:16450 gen 0]
0:24 len 4 -> [0:14340 gen 0]
0:48 len 24 -> [0:16544 gen 0]
0:80 len 32 -> [0:14368 gen 0]
0:112 len 16 -> [0:16417 gen 0]
0:120 len 8 -> [0:12713 gen 0]
0:272 len 152 -> [0:14440 gen 0]
0:288 len 16 -> [0:13320 gen 0]
0:968 len 184 -> [0:17496 gen 0]
0:2072 len 8 -> [0:17488 gen 0]
0:4128529 len 1 -> [0:16389 gen 0]
0:4128530 len 1 -> [0:16504 gen 0]
0:4128531 len 1 -> [0:16540 gen 0]
0:4128532 len 1 -> [0:16503 gen 0]
0:4128552 len 16 -> [0:16487 gen 0]
0:4128560 len 8 -> [0:16532 gen 0]
0:8257041 len 1 -> [0:16531 gen 0]
0:8257042 len 1 -> [0:16486 gen 0]
0:8257043 len 1 -> [0:16530 gen 0]
0:8257044 len 1 -> [0:16485 gen 0]
0:8257064 len 16 -> [0:16469 gen 0]
0:8257072 len 8 -> [0:16522 gen 0]
0:8257074 len 2 -> [0:16384 gen 0]
0:8257076 len 2 -> [0:18432 gen 0]
0:8257092 len 8 -> [0:17680 gen 0]
0:8257100 len 6 -> [0:13336 gen 0]
0:8257102 len 2 -> [0:13342 gen 0] dirty
0:8264240 len 512 -> [0:15872 gen 0]
0:12385553 len 1 -> [0:16390 gen 0]
0:12385554 len 1 -> [0:16468 gen 0]
0:12385555 len 1 -> [0:16521 gen 0]
0:12385556 len 1 -> [0:16467 gen 0]
0:12385576 len 16 -> [0:16451 gen 0]
0:12385584 len 8 -> [0:16513 gen 0]
0:16510984 len 8 -> [0:17480 gen 0]
0:16513080 len 8 -> [0:17464 gen 0]
0:16513096 len 8 -> [0:17456 gen 0]
0:16513120 len 8 -> [0:17472 gen 0]
0:16513160 len 8 -> [0:17448 gen 0]
0:16513336 len 8 -> [0:17440 gen 0]
0:16513392 len 8 -> [0:17432 gen 0]
0:16513480 len 8 -> [0:17424 gen 0]
0:16513672 len 8 -> [0:17416 gen 0]
0:16513808 len 8 -> [0:17408 gen 0]
0:16514056 len 248 -> [0:14592 gen 0]
0:16514064 len 8 -> [0:16505 gen 0]
todo
stap で、バックトレース例をとること。static 宣言を外してコンパイル。
http://bcache.evilpiepirate.org/ の bcache Design の訳はできたのだが、作者に配布許可を依頼したけど返事が来ないのだな。
btree を表示するユーザ空間のコマンドがあるといい。
作成 ２０１４年の冬休み。kanda.motohiro@gmail.com 以上