strace时间戳的含义

Question

使用时strace -T -tt -o outputfile myprogram，输出就像

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>

第一列是系统调用的开始时间还是结束时间？正如给定的-T，最后一列给出为“显示系统调用所花费的时间。这记录了每个系统调用开始和结束之间的时间差。” 为什么它与两次写入调用之间的时间间隔不同？作为前两个，16:14:37.577121 - 16:14:37.576804=0.000317 > 0.000014.

Answer 1

根据我刚刚尝试的实验：

strace -t sleep 2

时间戳是系统调用开始的时间。（它显示的nanosleep时间戳与前面的系统调用匹配，而不是 2 秒后加时间戳的下一个。）

我不能肯定地说在时间上没有一些测量不准确，但你不能指望在系统调用中花费的时间与时间戳的差异完全相同——你的进程必须在用户空间做一些工作系统调用之间。