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

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

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

$ 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 システムコール
最終列 <0.007620> システムコール実行に要した時間(秒.マイクロ秒)

参考

B.Gregg の書籍

Systems Performance: Enterprise and the Cloud

Systems Performance: Enterprise and the Cloud

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.

strace の man
$ strace -V
strace -- version 4.5.19
$ man strace
-r    Print a relative timestamp upon entry to each system call.  This records the time difference 
      between the beginning  of  successive system calls.

-t    Prefix each line of the trace with the time of day.

-tt   If given twice, the time printed will include the microseconds.

-ttt  If  given  thrice,  the  time printed will include the microseconds and the leading portion 
      will be printed as the number of seconds since the epoch.

-T    Show the time spent in system calls. This records the time difference between the beginning 
      and the end of each system call.

tやttはタイムスタンプの絶対値。rは相対値、つまり、tやttで出力される絶対値から差分を求めて出力したもののようだ。

空色ブログ

strace コマンドでよく使用するオプションに -tt オプションがあります。このオプションを付けると、システムコールが呼ばれた時刻を調べることが出来ます。-t オプションを付けると秒単位の時間、-tt オプションを付けるとマイクロ秒単位の時刻を出力します。出力に時刻を含めることにより、他のログとの照合や、プログラムのどの場所で時間が掛かっているのかを解析する事が出来ます。

プログラムの性能に問題が発生している時には、-T オプションが便利です。-T オプションを付けると、各システムコールが呼び出されてから完了するまでにどのくらいの時間が掛かったかを表示してくれます。

Strace -- システム管理者の顕微鏡 (空色ブログ)
strace のソース
$ tar jfx strace-4.5.19.tar.bz2
$ cd strace-4.5.19
  • strace.c
                case 'r':
                        rflag++;
                        tflag++;
                        break;
                case 't':
                        tflag++;
                        break;
                case 'T':
                        dtime++;
                        break;