After some feedback about the format of
the output from my Dtrace script for looking at SCSI io I how have
added a timestamp which helps sorting the output. The output is now
cleaner and hopefully clearer though does not fit on a 80 column
screen.
00000.844267200 isp1:-> 0×2a (WRITE(10)) address 06:00, lba 0×0143a76e, len 0×000002, control 0×00 timeout 60 CDB 60031134488 SDB 60031134518
00000.844354400 isp1:-> 0×2a (WRITE(10)) address 00:00, lba 0×0143a76e, len 0×000002, control 0×00 timeout 60 CDB 3000cd59e78 SDB 3000cd59f08
00000.848251440 isp1:-> 0×2a (WRITE(10)) address 06:00, lba 0×0143ddd0, len 0×000002, control 0×00 timeout 60 CDB 6001dd1ba50 SDB 6001dd1bae0
00000.848310720 isp1:-> 0×2a (WRITE(10)) address 00:00, lba 0×0143ddd0, len 0×000002, control 0×00 timeout 60 CDB 3001da270f8 SDB 3001da27188
00000.850371280 isp1:<- 0×2a (WRITE(10)) address 00:00, lba 0×0143a76e, len 0×000002, control 0×00 timeout 60 CDB 3000cd59e78 SDB 3000cd59f08, reason 0×0 (COMPLETED) state 0×5f Time 6084us
00000.851151040 isp1:<- 0×2a (WRITE(10)) address 06:00, lba 0×0143a76e, len 0×000002, control 0×00 timeout 60 CDB 60031134488 SDB 60031134518, reason 0×0 (COMPLETED) state 0×5f Time 6927us
00000.853292800 isp1:<- 0×2a (WRITE(10)) address 00:00, lba 0×0143ddd0, len 0×000002, control 0×00 timeout 60 CDB 3001da270f8 SDB 3001da27188, reason 0×0 (COMPLETED) state 0×5f Time 5014us
00000.854442400 isp1:<- 0×2a (WRITE(10)) address 06:00, lba 0×0143ddd0, len 0×000002, control 0×00 timeout 60 CDB 6001dd1ba50 SDB 6001dd1bae0, reason 0×0 (COMPLETED) state 0×5f Time 6226us
00002.839392160 isp1:-> 0×2a (WRITE(10)) address 06:00, lba 0×0143e0b0, len 0×000004, control 0×00 timeout 60 CDB 3001da263c0 SDB 3001da26450
00002.839482480 isp1:-> 0×2a (WRITE(10)) address 00:00, lba 0×0143e0b0, len 0×000004, control 0×00 timeout 60 CDB 60002cb4538 SDB 60002cb45c8
00002.849052160 isp1:<- 0×2a (WRITE(10)) address 00:00, lba 0×0143e0b0, len 0×000004, control 0×00 timeout 60 CDB 60002cb4538 SDB 60002cb45c8, reason 0×0 (COMPLETED) state 0×5f Time 9630us
00002.850171840 isp1:<- 0×2a (WRITE(10)) address 06:00, lba 0×0143e0b0, len 0×000004, control 0×00 timeout 60 CDB 3001da263c0 SDB 3001da26450, reason 0×0 (COMPLETED) state 0×5f Time 10824us
00003.840019440 isp1:-> 0×2a (WRITE(10)) address 06:00, lba 0×0143e200, len 0×000004, control 0×00 timeout 60 CDB 3000cd59e78 SDB 3000cd59f08
00003.840110160 isp1:-> 0×2a (WRITE(10)) address 00:00, lba 0×0143e200, len 0×000004, control 0×00 timeout 60 CDB 30014c0c780 SDB 30014c0c810
00003.846265280 isp1:<- 0×2a (WRITE(10)) address 00:00, lba 0×0143e200, len 0×000004, control 0×00 timeout 60 CDB 30014c0c780 SDB 30014c0c810, reason 0×0 (COMPLETED) state 0×5f Time 6205us
00003.847439680 isp1:<- 0×2a (WRITE(10)) address 06:00, lba 0×0143e200, len 0×000004, control 0×00 timeout 60 CDB 3000cd59e78 SDB 3000cd59f08, reason 0×0 (COMPLETED) state 0×5f Time 7470us
Lots of “fun” games can be played with this, like the
above shows that this system has target 0 and target 6 forming a
mirror making isp1 a Single Point of failure. Although my favourite
is this one:
While running
# dd if=/dev/rdsk/c0t8d0s2 of=/dev/null oseek=1024 iseek=$(( 16#1fffff )) count=2
2+0 records in
2+0 records out
#
I get the following trace:
Th
00001.971470332 qus1:-> 0×00 (TEST UNIT READY) address 08:00, lba 0×00000000, len 0×000000, control 0×00 timeout 60 CDB 300016a94f0 SDB 300016a9520
00001.972324082 qus1:<- 0×00 (TEST UNIT READY) address 08:00, lba 0×00000000, len 0×000000, control 0×00 timeout 60 CDB 300016a94f0 SDB 300016a9520, reason 0×0 (COMPLETED) state 0×17 Time 937us
00001.972433832 qus1:-> 0×00 (TEST UNIT READY) address 08:00, lba 0×00000000, len 0×000000, control 0×00 timeout 60 CDB 300016a9d90 SDB 300016a9dc0
00001.973217082 qus1:<- 0×00 (TEST UNIT READY) address 08:00, lba 0×00000000, len 0×000000, control 0×00 timeout 60 CDB 300016a9d90 SDB 300016a9dc0, reason 0×0 (COMPLETED) state 0×17 Time 826us
00001.973324748 qus1:-> 0×1a (MODE SENSE(6)) address 08:00, lba 0×00000300, len 0×000024, control 0×00 timeout 60 CDB 300016a9380 SDB 300016a93b0
00001.976352165 qus1:<- 0×1a (MODE SENSE(6)) address 08:00, lba 0×00000300, len 0×000024, control 0×00 timeout 60 CDB 300016a9380 SDB 300016a93b0, reason 0×0 (COMPLETED) state 0×5f Time 3070us
00001.976443415 qus1:-> 0×1a (MODE SENSE(6)) address 08:00, lba 0×00000400, len 0×000024, control 0×00 timeout 60 CDB 300016a9ab0 SDB 300016a9ae0
00001.979359665 qus1:<- 0×1a (MODE SENSE(6)) address 08:00, lba 0×00000400, len 0×000024, control 0×00 timeout 60 CDB 300016a9ab0 SDB 300016a9ae0, reason 0×0 (COMPLETED) state 0×5f Time 2959us
00001.979453248 qus1:-> 0×08 ( READ(6)) address 08:00, lba 0×00000000, len 0×000001, control 0×00 timeout 60 CDB 300016a9c20 SDB 300016a9c50
00001.979814748 qus1:<- 0×08 ( READ(6)) address 08:00, lba 0×00000000, len 0×000001, control 0×00 timeout 60 CDB 300016a9c20 SDB 300016a9c50, reason 0×0 (COMPLETED) state 0×5f Time 403us
00001.979898415 qus1:-> 0×08 ( READ(6)) address 08:00, lba 0×00000000, len 0×000001, control 0×00 timeout 60 CDB 300016a90a0 SDB 300016a90d0
00001.980151165 qus1:<- 0×08 ( READ(6)) address 08:00, lba 0×00000000, len 0×000001, control 0×00 timeout 60 CDB 300016a90a0 SDB 300016a90d0, reason 0×0 (COMPLETED) state 0×5f Time 294us
00001.980507332 qus1:-> 0×08 ( READ(6)) address 08:00, lba 0×001fffff, len 0×000001, control 0×00 timeout 60 CDB 300016a9660 SDB 300016a9690
00001.993267665 qus1:<- 0×08 ( READ(6)) address 08:00, lba 0×001fffff, len 0×000001, control 0×00 timeout 60 CDB 300016a9660 SDB 300016a9690, reason 0×0 (COMPLETED) state 0×5f Time 12804us
00001.993382498 qus1:-> 0×28 ( READ(10)) address 08:00, lba 0×00200000, len 0×000001, control 0×00 timeout 60 CDB 300016a9940 SDB 300016a9970
00001.999256915 qus1:<- 0×28 ( READ(10)) address 08:00, lba 0×00200000, len 0×000001, control 0×00 timeout 60 CDB 300016a9940 SDB 300016a9970, reason 0×0 (COMPLETED) state 0×5f Time 5921us
I like it has you see the transition
from READ(6) to READ(10) as it moves from LBA 0×1fffff to 0×200000.
Did I mention needing to get out more?
You can get the script here.
Still do do is correct decoding of CDBs bigger than 10 bytes, which
is not a problem for my current systems and more detailed decoding of
CDBs that are not reads and writes.
Tags: topic:[dtrace] topic:[scsi]
topic:[opensolaris] topic:[solaris]