☰

解释开放系统调用的 strace 上显示的时间

tag-icon • tag-icon linux io system-calls strace
解释开放系统调用的 strace 上显示的时间

我们遇到了供应商应用程序的延迟问题。我运行了strace -Tttt这个过程并得到了这个：

[...]
1470166748.946144 open("/opt/app/shdbrth/X       ", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000016>
1470166800.850979 open("/opt/app/shdbrth/X38347", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 10 <0.000070>
1470166800.851139 fstat(10, {st_mode=S_IFREG|0660, st_size=0, ...}) = 0 <0.000006>
[...]

根据联机帮助页，-ttt每行的前缀都是系统调用的时间。该-T选项将处理调用所花费的时间附加在<和>括号之间。然而，这在上面的例子中似乎并不成立。

例如，第二行从 1,470,166,800 纪元秒和 850,979 微秒开始。根据附加的计时器，处理时间为 70 微秒。然而，下一行从相同的纪元秒和 851,139 微秒开始——相差 90 微秒。

我本来打算将其记为开销，但也许有更准确的解释。

答案1

该行开头的时间是内核开始处理该系统调用的时间。该行末尾的持续时间是内核开始处理该系统调用的时间与内核回复该系统调用的时间之间的间隔。

下一行开头的时间是内核开始处理下一个系统调用的时间。在回复一个系统调用和进入下一个系统调用之间，发生了两种情况：进程运行用户代码，并且可能在同一处理器上调度其他进程。

在您的示例中，第一个open调用花费了 16 微秒，大约 12 秒后发出下一个调用。在这十二秒内，该进程运行用户代码，并且可能多次被抢占以运行其他进程。在第二次open调用和随后的之间fstat，大约经过了 90μs；考虑到这个值有多小，这表明该进程只运行了少量的用户代码并且没有被抢占。

相关内容