システムコールの所要時間は strace の -T オプションで調べることができる。
例
- 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 | システムコール |
| 最終列 | <0.007620> | システムコール実行に要した時間（秒.マイクロ秒） |
参考
B.Gregg の書籍
Systems Performance: Enterprise and the Cloud (English Edition)
- 作者: Brendan Gregg
- 出版社/メーカー: Prentice Hall
- 発売日: 2013/10/07
- メディア: Kindle版
- この商品を含むブログを見る
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 オプションを付けると、各システムコールが呼び出されてから完了するまでにどのくらいの時間が掛かったかを表示してくれます。
Oracle Blogs | Oracle Solaris Blog
strace のソース
- strace - Browse /strace/4.5.19 at SourceForge.net から strace-4.5.19.tar.bz2 をダウンロードする。
- 解凍する
$ 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;
