7

使用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。

4

2 回答 2

6

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

strace -t sleep 2

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

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

于 2013-05-26T08:34:41.613 回答
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 测量第一个时间戳之前（以便稍后计算持续时间）。

于 2019-03-21T15:56:06.437 回答