衡量一个进程在 IO 上花费的总时间

Question

运行时间命令时，其中一个程序给出以下输出：

real    1m33.523s
user    0m15.156s
sys 0m1.312s

这里的真实时间和用户+系统时间有很大的不同。这很可能是由于花费在 IO 等待/调用上的时间。我想测量程序在 IO 等待或 IO 调用中花费的总时间。有什么办法吗？

我尝试使用 iotop。但是，它不会报告程序执行 IO 所花费的总时间。

Answer 1

是的，strace - 可以提供每个系统调用的统计信息。

示例 1

我想测量在访问 stackoverflow.com 时花费在 I/O 上的时间：

$ time  curl stackoverflow.com >/dev/null 2>&1
curl stackoverflow.com > /dev/null 2>&1  0.00s user 0.01s system 2% cpu 0.392 total

好的，2% CPU 和 0.01 秒在系统中。让我们找出答案：

$ strace -c curl stackoverflow.com >/dev/null 
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  240k    0  240k    0     0   127k      0 --:--:--  0:00:01 --:--:--  130k
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 54.12    0.005497          11       506           write
 18.16    0.001845          43        43           fstat
 11.95    0.001214          30        41           poll
  5.75    0.000584          32        18           recvfrom
  3.40    0.000345           3       101           mmap
  2.51    0.000255           4        62           mprotect
  1.98    0.000201           4        50           close
  1.84    0.000187          31         6           getsockname
  0.29    0.000029           1        42         1 open

将此结果与在不带参数的情况下运行curl 时测量的结果进行比较特别有用。

无论如何。 strace 显示 curl 主要花时间在 write、fstat 和 poll 上。

另一个例子

第一种方法似乎显示不正确的睡眠结果。如果您对第一种方法不满意，您可以打印每个系统调用的获取时间 (strace -T)。获取这些数据并对其进行处理以查找每个系统调用的摘要时间。

$ strace 2>&1 -T curl stackoverflow.com >/dev/null | head -n 20

execve("/usr/bin/curl", ["curl", "stackoverflow.com"], [/* 62 vars */]) = 0 <0.000219>
brk(0)                                  = 0x186e000 <0.000175>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc04c9e6000 <0.000166>
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory) <0.000238>
open("/etc/ld.so.cache", O_RDONLY)      = 3 <0.000144>
fstat(3, {st_mode=S_IFREG|0644, st_size=96498, ...}) = 0 <0.000175>
mmap(NULL, 96498, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fc04c9ce000 <0.000164>
close(3)                                = 0 <0.000160>
open("/usr/lib64/libcurl.so.4", O_RDONLY) = 3 <0.000047>
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\333\300\">\0\0\0"..., 832) = 832 <0.000160>
fstat(3, {st_mode=S_IFREG|0755, st_size=346008, ...}) = 0 <0.000216>
mmap(0x3e22c00000, 2438600, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3e22c00000 <0.000189>
mprotect(0x3e22c51000, 2097152, PROT_NONE) = 0 <0.000032>
mmap(0x3e22e51000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x51000) = 0x3e22e51000 <0.000119>
close(3)                                = 0 <0.000110>
open("/lib64/libidn.so.11", O_RDONLY)   = 3 <0.000257>
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0/@U1\0\0\0"..., 832) = 832 <0.000051>
fstat(3, {st_mode=S_IFREG|0755, st_size=209088, ...}) = 0 <0.000041>
mmap(0x3155400000, 2301736, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x3155400000 <0.000037>
mprotect(0x3155432000, 2093056, PROT_NONE) = 0 <0.000037>