strace时间戳的含义

The meaning of strace timestamp

本文关键字：时间戳 strace      更新时间：2023-10-16

使用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, "66098tTt41t....,.....,,,.,,,,..."..., 4096) = 4096 <0.000016>

第一列是指系统调用的开始时间，还是结束时间？如给定的-T，最后一列被给定为"T"；显示用于系统调用的时间。这记录了每个系统调用开始和结束之间的时间差"为什么它与两个写电话之间的时间间隔不同？作为前两个，16:14:37.577121 - 16:14:37.576804=0.000317 > 0.000014。

根据我刚刚尝试的一个实验：

strace -t sleep 2

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

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

我刚刚调查过这一点，所以我认为也许有必要恢复这个线程，呵呵

基于Git代码(d091f1a9e2中的HEAD(，代码如下：

trace_syscall(struct tcb *tcp, unsigned int *sig)
{
        if (entering(tcp)) {
                int res = syscall_entering_decode(tcp); // print the -tt timestamp
                [...]
                syscall_entering_finish(tcp, res); // measure the first timestamp for -T
                return res;
        } else {
                struct timespec ts = {};
                int res = syscall_exiting_decode(tcp, &ts); // measure second timestamp for -T
                if (res != 0) {
                        res = syscall_exiting_trace(tcp, &ts, res); // calculate the delta for syscall duration
                }
                syscall_exiting_finish(tcp);
                return res;
        }
}

因此，总之，-t/-tt在系统调用开始之前，甚至在-t测量第一个时间戳之前(以便稍后计算持续时间(，都会获取时间。

相关文章：