纠正流重定向中的乱序打印

Posted 2023-02-16

【中文标题】纠正流重定向中的乱序打印

【英文标题】：Correcting out of order printing from stream redirection

【发布时间】：2015-01-09 20:02:58

【问题描述】：

我有一个使用multiprocessing.pool.map 做一些工作的python 脚本。在运行过程中，它会将内容打印到stdout，对于错误，它会打印到stderr。我决定为每个流都有一个单独的日志文件会很好，经过一番思考后，我应该像这样运行它：

time ./ecisSearch.py 58Ni.conf 4 1 > >(tee stdout.log) 2> >(tee stderr.log >&2)

这为我提供了日志文件并将输出保留在适当的流上。然而问题来了。如果我在没有重定向的情况下运行它，我会得到：

$ time ./ecisSearch.py 58Ni.conf 4 1

2015-01-09 14:42:37.524333: This job will perform 4 fit(s)   //this is stdout

2015-01-09 14:42:37.524433: Threaded mapping of the fit function onto the starting point input set is commencing   //this is stdout

2015-01-09 14:42:37.526641: Starting run #: 0   //this is stdout
2015-01-09 14:42:37.527018: Starting run #: 1   //this is stdout
2015-01-09 14:42:37.529124: Starting run #: 2   //this is stdout
2015-01-09 14:42:37.529831: Starting run #: 3   //this is stdout
2015-01-09 14:42:54.052522: Test of std err writing in run 0 is finished   //this is stderr
2015-01-09 14:42:54.502284: Test of std err writing in run 1 is finished   //this is stderr
2015-01-09 14:42:59.952433: Test of std err writing in run 3 is finished   //this is stderr
2015-01-09 14:43:03.259783: Test of std err writing in run 2 is finished   //this is stderr

2015-01-09 14:43:03.260360: Finished fits in job #: 1 preparing to output data to file   //this is stdout

2015-01-09 14:43:03.275472: Job finished   //this is stdout


real    0m26.001s
user    0m44.145s
sys 0m32.626s

但是，使用重定向运行它会生成以下输出。

$ time ./ecisSearch.py 58Ni.conf 4 1 > >(tee stdout.log) 2> >(tee stderr.log >&2)
2015-01-09 14:55:13.188230: Test of std err writing in run 0 is finished   //this is stderr
2015-01-09 14:55:13.855079: Test of std err writing in run 1 is finished   //this is stderr
2015-01-09 14:55:19.526580: Test of std err writing in run 3 is finished   //this is stderr
2015-01-09 14:55:23.628807: Test of std err writing in run 2 is finished   //this is stderr
2015-01-09 14:54:56.534790: Starting run #: 0   //this is stdout
2015-01-09 14:54:56.535162: Starting run #: 1   //this is stdout
2015-01-09 14:54:56.538952: Starting run #: 3   //this is stdout
2015-01-09 14:54:56.563677: Starting run #: 2   //this is stdout

2015-01-09 14:54:56.531837: This job will perform 4 fit(s)   //this is stdout

2015-01-09 14:54:56.531912: Threaded mapping of the fit function onto the starting point input set is commencing   //this is stdout


2015-01-09 14:55:23.629427: Finished fits in job #: 1 preparing to output data to file   //this is stdout

2015-01-09 14:55:23.629742: Job finished   //this is stdout


real    0m27.376s
user    0m44.661s
sys 0m33.295s

只要查看时间戳，我们就会发现这里发生了一些奇怪的事情。不仅stderr 和stdout 流没有按应有的方式相互穿插，而且stdout 组件似乎首先具有来自子流程的内容，然后是来自“主”流程的内容，无论它出现的顺序。我知道 stderr 是无缓冲的，stdout 是缓冲的，但这并不能解释为什么 stdout 信息在它自己的流中是无序的。另外，从我的帖子中看不出，所有stdout 都等到执行结束才出现在屏幕上。

我的问题如下：为什么会发生这种情况？而且，不太重要的是有没有办法解决它？

【问题讨论】：

缓冲。 stderr 是无缓冲的，这就是为什么那些首先出现的原因，然后我猜其他行会留在缓冲区中，并在它们的进程完成时被刷新。 ***.com/questions/15931526/… 的可能重复项。不知道为什么这些重定向会有所不同，但这是一个很好的地方。

想解释一下标准输出的乱序性质吗？如果只是 stderr vs stdout 缓冲也是我选择的解释。但正如我在问题后面所说的那样，不仅仅是这样。标准输出组件的顺序也不正确。只有说“测试标准错误写入”的部分被写入标准错误，其余部分是标准输出，时间戳告诉我们的东西是先写入标准输出的，然后出现。

stdout 上的无序行来自不同的子进程，对吧？每个都有自己的缓冲区。这似乎是一个很好的解释（不是特定于 Python 的）：pixelbeat.org/programming/stdio_buffering

看起来，已经存在答案的建议问题似乎有解决方案。在整个代码中撒上一些精心放置的sys.stdout(stderr).flush() 之后，它现在似乎可以正常工作了。现在我该怎么做？关闭问题？等待重复的答案？自己回答？

实际上，虽然我已标记为重复，但存在细微差别，因为您询问重定向时为什么会发生这种情况，但不是其他情况。我正在写一个简短的答案

【参考方案1】：

stdout 的输出是缓冲的：也就是说，打印语句实际上写入一个缓冲区，而这个缓冲区只是偶尔刷新到终端。每个进程都有一个单独的缓冲区，这就是为什么来自不同进程的写入可能会出现乱序（这是一个常见问题，如Why subprocess stdout to a file is written out of order?）

在这种情况下，输出是有序的，但在重定向时会出现乱序。为什么？ This article 解释：

stdin 总是被缓冲 stderr 总是无缓冲的 如果 stdout 是终端，则缓冲自动设置为行缓冲，否则设置为缓冲

所以，当输出到终端时，它会刷新每一行，并且恰好按顺序出现。重定向时，使用长缓冲区（通常为 4096 字节）。由于您打印的数量少于该数量，因此首先刷新了先完成的子进程。

解决方案是使用flush()，或者完全禁用进程缓冲（参见Disable output buffering）

【讨论】：

再次感谢您帮助我解决这个问题。我曾怀疑缓冲是 stderr 与 stdout 的罪魁祸首，但没有想到缓冲会导致子进程与主进程的标准输出中的怪异。我敢打赌，如果我测试的不是很小的输入集，它可能会更明显。