ablog

strace でシステムコールの所要時間を調べる

Linux

システムコールの所要時間は strace の -T オプションで調べることができる。

• 上はEXCELでピボットテーブルを使ってグラフ化したもの
• I/Oレスポンス（read システムコールの所要時間）は5〜15ミリ秒であることがわかる

例

• strace でシステムコールのトレースを取得する

$ strace -ttT -o strace-T_fs_`date +'%Y%m%d%H%M%S'`.log dd if=OVMRepo.vmdk of=/dev/null iflag=direct bs=1M count=1000

• -T: システムコールの所要時間（秒.マイクロ秒）を出力 ※マイクロ秒=1/1,000,000秒
• -tt: タイムスタンプをマイクロ秒で出力
• -o: トレースを指定したファイルに出力

• 出力結果

$ less strace-T_fs_20150111143101.log
[...]
14:31:01.353151 read(0, "KDMV\1\0\0\0\3\0\0\0\0\0@\6\0\0\0\0\200\0\0\0\0\0\0\0\1\0\0\0"..., 1048576) = 1048576 <0.007620>
14:31:01.360944 write(1, "KDMV\1\0\0\0\3\0\0\0\0\0@\6\0\0\0\0\200\0\0\0\0\0\0\0\1\0\0\0"..., 1048576) = 1048576 <0.000022>
14:31:01.361115 read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576) = 1048576 <0.004771>
14:31:01.366006 write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576) = 1048576 <0.000007>

• 項目説明

列番号	例	説明
1列目	14:31:01.353151	システムコール実行開始時刻（時:分:秒.マイクロ秒）
2列目	read(0, "KDMV\1\0\0\0\..."..., 1048576) = 1048576	システムコール
3列目	<0.007620>	システムコール実行時間（秒.マイクロ秒）

参考

8.6.3. strace, truss

Previous operating system tools for measuring file system latency in detail included the debuggers for the syscall interface, such as strace(1) for Linux and truss(1) for Solaris. Such debuggers can hurt performance and may be suitable for use only when the performance overhead is acceptable and other methods to analyze latency are not possible.

This example shows strace(1) timing reads on an ext4 file system:

$ strace -ttT -p 845
[...]
18:41:01.513110 read(9, "\334\260/\224\356k..."..., 65536) = 65536 <0.018225>
18:41:01.531646 read(9, "\371X\265|\244\317..."..., 65536) = 65536 <0.000056>
18:41:01.531984 read(9, "\357\311\347\1\241..."..., 65536) = 65536 <0.005760>
18:41:01.538151 read(9, "*\263\264\204|\370..."..., 65536) = 65536 <0.000033>
18:41:01.538549 read(9, "\205q\327\304f\370..."..., 65536) = 65536 <0.002033>
18:41:01.540923 read(9, "\6\2738>zw\321\353..."..., 65536) = 65536 <0.000032>

The -tt option prints the relative timestamps on the left, and -T prints the syscall times on the right. Each read() was for 64 Kbytes, the first taking 18 ms, followed by 56 μs (likely cached), then 5 ms. The reads were to file descriptor 9. To check that this is to a file system (and isn’t a socket), either the open() syscall will be visible in earlier strace(1) output, or another tool such as lsof(8) can be used.

ツイートする

Permalink | コメント(0) | トラックバック(0) | 15:28