为什么 C++ 和 strace 不同意 open() 系统调用需要多长时间？

Question

我有一个打开大量文件的程序。我正在计时执行 C++ 循环，该循环实际上只是使用 C++ 计时器和 strace 打开和关闭文件。奇怪的是，系统时间和 C++ 记录的时间（彼此一致）比 strace 声明在系统调用中花费的时间要大几个数量级。怎么会这样？我已经把源和输出放在下面了。

这一切都是因为我发现我的应用程序花费了不合理的时间来打开文件。为了帮助我确定问题，我编写了以下测试代码（供参考，文件“files.csv”只是一个每行一个文件路径的列表）：

#include <stdio.h>
#include...

using namespace std;

int main(){
  timespec start, end;
  ifstream fin("files.csv");
  string line;
  vector<string> files;
  while(fin >> line){
    files.push_back(line);
  }
  fin.close();

  clock_gettime(CLOCK_MONOTONIC, &start);
  for(int i=0; i<500; i++){
    size_t filedesc = open(files[i].c_str(), O_RDONLY);
    if(filedesc < 0) printf("error in open");
    if(close(filedesc)<0) printf("error in close");
  }
  clock_gettime(CLOCK_MONOTONIC, &end);
  printf("  %fs elapsed\n", (end.tv_sec-start.tv_sec) + ((float)(end.tv_nsec - start.tv_nsec))/1000000000);
  return 0;
}

这是我运行它时得到的结果：

-bash$ time strace -ttT -c ./open_stuff
  5.162448s elapsed <------ Output from C++ code

% time     seconds  usecs/call     calls    errors syscall 
------ ----------- ----------- --------- --------- ----------------
 99.72    0.043820          86       508           open  <------output from strace
  0.15    0.000064           0       508           close
  0.14    0.000061           0       705           read
  0.00    0.000000           0         1           write
  0.00    0.000000           0         8           fstat
  0.00    0.000000           0        25           mmap
  0.00    0.000000           0        12           mprotect
  0.00    0.000000           0         3           munmap
  0.00    0.000000           0        52           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         1         1 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         3         1 futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.043945                  1834         2 total

real    0m5.821s  <-------output from time
user    0m0.031s
sys     0m0.084s

理论上，从 C++ 报告的“经过”时间应该是调用 open(2) 的执行时间加上执行 for 循环 500 次的最小开销。然而，来自 strace 的 open(2) 和 close(1) 调用的总时间缩短了 99%。我不知道发生了什么。

PS C 的经过时间和系统时间的差异是因为files.csv实际上包含了数万条路径，这些路径都被加载了。

Answer 1

比较运行时间和执行时间就像比较苹果和橙汁一样。 （其中一个缺少纸浆:)）要打开文件，系统必须找到并读取适当的目录条目......如果路径很深，它可能需要读取许多目录条目。如果条目未缓存，则需要从磁盘读取它们，这将涉及磁盘查找。当磁头移动时，当扇区旋转到磁头所在的位置时，挂钟一直在滴答作响，但 CPU 可以做其他事情（如果有工作要做的话。）所以这算作经过时间-- 无情的时钟在滴答作响 -- 但不是执行时间。