为什么迭代文件比读入内存和计算两次快两倍？

Question

我正在比较以下内容

tail -n 1000000 stdout.log | grep -c '"success": true'
tail -n 1000000 stdout.log | grep -c '"success": false'

与以下

log=$(tail -n 1000000 stdout.log)
echo "$log" | grep -c '"success": true'
echo "$log" | grep -c '"success": false'

令人惊讶的是，第二个花费的时间几乎是第一个的 3 倍。它应该更快，不是吗？

Answer 1

我已经完成了以下测试，在我的系统上，第二个脚本的结果差异大约长了 100 倍。

我的文件是一个名为的 strace 输出 bigfile

$ wc -l bigfile.log 
1617000 bigfile.log

脚本

xtian@clafujiu:~/tmp$ cat p1.sh
tail -n 1000000 bigfile.log | grep '"success": true' | wc -l
tail -n 1000000 bigfile.log | grep '"success": false' | wc -l

xtian@clafujiu:~/tmp$ cat p2.sh
log=$(tail -n 1000000 bigfile.log)
echo "$log" | grep '"success": true' | wc -l
echo "$log" | grep '"success": true' | wc -l

我实际上没有与 grep 匹配的任何内容，因此没有任何内容写入到最后一个管道中 wc -l

以下是时间安排：

xtian@clafujiu:~/tmp$ time bash p1.sh
0
0

real    0m0.381s
user    0m0.248s
sys 0m0.280s
xtian@clafujiu:~/tmp$ time bash p2.sh
0
0

real    0m46.060s
user    0m43.903s
sys 0m2.176s

所以我通过 strace 命令再次运行了这两个脚本

strace -cfo p1.strace bash p1.sh
strace -cfo p2.strace bash p2.sh

以下是跟踪结果：

$ cat p1.strace 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97.24    0.508109       63514         8         2 waitpid
  1.61    0.008388           0     84569           read
  1.08    0.005659           0     42448           write
  0.06    0.000328           0     21233           _llseek
  0.00    0.000024           0       204       146 stat64
  0.00    0.000017           0       137           fstat64
  0.00    0.000000           0       283       149 open
  0.00    0.000000           0       180         8 close
...
  0.00    0.000000           0       162           mmap2
  0.00    0.000000           0        29           getuid32
  0.00    0.000000           0        29           getgid32
  0.00    0.000000           0        29           geteuid32
  0.00    0.000000           0        29           getegid32
  0.00    0.000000           0         3         1 fcntl64
  0.00    0.000000           0         7           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    0.522525                149618       332 total

和 p2.strace

$ cat p2.strace 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 75.27    1.336886      133689        10         3 waitpid
 13.36    0.237266          11     21231           write
  4.65    0.082527        1115        74           brk
  2.48    0.044000        7333         6           execve
  2.31    0.040998        5857         7           clone
  1.91    0.033965           0    705681           read
  0.02    0.000376           0     10619           _llseek
  0.00    0.000000           0       248       132 open
...
  0.00    0.000000           0       141           mmap2
  0.00    0.000000           0       176       126 stat64
  0.00    0.000000           0       118           fstat64
  0.00    0.000000           0        25           getuid32
  0.00    0.000000           0        25           getgid32
  0.00    0.000000           0        25           geteuid32
  0.00    0.000000           0        25           getegid32
  0.00    0.000000           0         3         1 fcntl64
  0.00    0.000000           0         6           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    1.776018                738827       293 total

分析

毫不奇怪，在这两种情况下，大部分时间都花在等待进程完成上，但 p2 等待的时间是 p1 的 2.63 倍，正如其他人提到的，您在 p2.sh 中起步较晚。

所以现在忘记waitpid, 忽略该%列并查看两条跟踪上的秒列。

最长的时间p1 大部分时间都花在读取上可能是可以理解的，因为有一个大文件要读取，但 p2 花在读取上的时间是 p1 的 28.82 倍。-bash不希望将如此大的文件读入变量，并且可能一次读取缓冲区，拆分为行然后再获取另一个。

p2 的读取计数为 705k，而 p1 为 84k，每次读取都需要上下文切换到内核空间并再次切换。读取和上下文切换次数的近 10 倍。

写入p2 的时间比 p1 的写入时间长 41.93 倍

写入计数p1 的写入次数比 p2 多，42k 与 21k，但它们要快得多。

可能是因为echo行进入grep而不是尾部写入缓冲区。

此外，p2 在写入上花费的时间比在读取上花费的时间多，而 p1 则相反！

其他因素看看brk系统调用的数量：p2 花费的时间是读取时间的 2.42 倍！在 p1 中（它甚至没有注册）。brk是当程序需要扩展其地址空间时，因为最初没有分配足够的空间，这可能是由于 bash 必须将该文件读入变量，并且不希望它有那么大，正如@scai 提到的，如果文件变得太大，即使那样也行不通。

tail可能是一个非常有效的文件阅读器，因为这是它的设计目的，它可能对文件进行内存映射并扫描换行符，从而允许内核优化 i/o。bash 在阅读和写作上的时间都不是很好。

p2 花费了 44 毫秒和 41 毫秒clone，execv这对于 p1 来说不是一个可衡量的数量。可能是 bash 读取并从尾部创建变量。

最后总计p1 执行 ~ 150k 系统调用 vs p2 740k（4.93 倍）。

消除 waitpid，p1 花费 0.014416 秒执行系统调用，p2 花费 0.439132 秒（长 30 倍）。

所以看起来 p2 大部分时间都花在用户空间中，除了等待系统调用完成和内核重新组织内存之外，什么都不做，p1 执行更多的写入，但效率更高，导致系统负载显着减少，因此速度更快。

结论

在编写 bash 脚本时，我永远不会尝试通过内存进行编码，这并不意味着您不尝试提高效率。

tail旨在做它所做的事情，它可能memory maps是文件，以便有效读取并允许内核优化 i/o。

一个更好的方式来优化你的问题可能是第一个grep为“‘成功’：”行再算上trues和falses，grep具有计数选项，再次避免了wc -l，甚至更好的是，管的尾巴穿过来awk和计数trues和假同时。p2 不仅需要很长时间，而且在内存被 brks 打乱的同时增加了系统负载。

Answer 2

一方面，第一个方法调用tail两次，因此它必须比只执行一次的第二个方法做更多的工作。另一方面，第二种方法必须将数据复制到 shell 中然后再退出，因此它必须比tail直接通过管道输入的第一个版本做更多的工作grep。第一种方法在多处理器机器上有一个额外的优势：grep可以与 并行工作tail，而第二种方法是严格串行化的， first tail， then grep。

所以没有明显的理由为什么一个应该比另一个更快。

如果您想了解发生了什么，请查看 shell 进行的系统调用。也尝试使用不同的外壳。

strace -t -f -o 1.strace sh -c '
  tail -n 1000000 stdout.log | grep "\"success\": true" | wc -l;
  tail -n 1000000 stdout.log | grep "\"success\": false" | wc -l'

strace -t -f -o 2-bash.strace bash -c '
  log=$(tail -n 1000000 stdout.log);
  echo "$log" | grep "\"success\": true" | wc -l;
  echo "$log" | grep "\"success\": true" | wc -l'

strace -t -f -o 2-zsh.strace zsh -c '
  log=$(tail -n 1000000 stdout.log);
  echo "$log" | grep "\"success\": true" | wc -l;
  echo "$log" | grep "\"success\": true" | wc -l'

使用方法 1，主要阶段是：

1. tail 阅读并寻求找到它的起点。
2. tail写入 4096 字节的块，其grep读取速度与生成速度一样快。
3. 对第二个搜索字符串重复上一步。

使用方法 2，主要阶段是：

1. tail 阅读并寻求找到它的起点。
2. tail 写入 4096 字节的块，其中 bash 一次读取 128 个字节，而 zsh 一次读取 4096 个字节。
3. Bash 或 zsh 写入 4096 字节的块，它们的grep读取速度与它们产生的速度一样快。
4. 对第二个搜索字符串重复上一步。

读取命令替换的输出时，Bash 的 128 字节块会显着减慢速度；zsh 对我来说和方法 1 一样快。您的里程可能会因 CPU 类型和数量、调度程序配置、所涉及工具的版本以及数据大小而异。

Answer 3

实际上，第一个解决方案也将文件读入内存！这称为缓存，由操作系统自动完成。

并为已经正确地解释mikeserv第一个解决方案exectutesgrep 而正在读取的文件，而第二个解决方案执行它后，该文件已被读取tail。

所以第一个解决方案由于各种优化而更快。但这并不总是正确的。对于操作系统决定不缓存的非常大的文件，第二个解决方案可能会变得更快。但请注意，对于不适合您内存的更大文件，第二种解决方案根本不起作用。