C++ – The meaning of strace timestamp


When use strace -T -tt -o outputfile myprogram, the out put is like

16:14:37.576804 write(1, "EFFEEFFFEFFGGEEFEEFECEEDB"..., 4096) = 4096 <0.000014>
16:14:37.577121 write(1, ",...,,,.\tDEDEEDEDEEBDEEFECECFBEE"..., 4096) = 4096 <0.000015>
16:14:37.577434 write(1, "66098\tT\t41\t....,.....,,,.,,,,..."..., 4096) = 4096 <0.000016>

Does the first column mean the start time of that system call, or the finish time? As given -T, the last column is given as "Show the time spent in system calls. This records the time difference between the beginning and the end of each system call." Why is it different from the time gap between two write calls? As the first two, 16:14:37.577121 - 16:14:37.576804=0.000317 > 0.000014.

Best Solution

According to an experiment I just tried:

strace -t sleep 2

the timestamps are the times the syscall started. (It showed a nanosleep with a timestamp that matched the preceding syscall, not the following one that was timestamped 2 seconds later.)

I can't say for sure that there isn't some measurement inaccuracy in the times, but you can't expect the time spent in syscall to be exactly the same as the difference in timestamps - your process has to do some work in userspace between the syscalls.