从流重定向更正乱序打印 [英] Correcting out of order printing from stream redirection
问题描述
我有一个使用multiprocessing.pool.map做一些工作的python脚本.在执行过程中，它将内容打印到stdout，对于错误将其显示到stderr.我决定为每个流创建一个单独的日志文件会很不错，经过一番思考后，我应该像这样运行它:
I have a python script that uses multiprocessing.pool.map to do some work. As it goes it prints things to stdout, for errors it prints to stderr. I decided it would be nice to have a separate log file for each of the streams and after a bit of thinking worked out that I should run it like this:
time ./ecisSearch.py 58Ni.conf 4 1 > >(tee stdout.log) 2> >(tee stderr.log >&2)
这给了我日志文件，并将输出保留在适当的流上.但是，这里出现了问题.如果我在没有重定向的情况下运行它，则会得到以下信息:
This gives me the log files and preserves the output on the appropriate streams. However here comes the problem. If I run it without the redirects I get this:
$ 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
但是，通过重定向运行它会生成以下输出.
However, running it with the redirects generates the following output.
$ 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都等到执行结束才出现在屏幕上.
Just looking at the time stamps we can see something strange is happening here. Not only are the stderr and stdout streams not interspersed with each other as they should be, but the stdout component seems to have stuff from the sub-processes first and then stuff from the 'master' process, regardless of the order it appeared in. I know that stderr is unbuffered and stdout is buffered, but that does not explain why the stdout information is out of order within its own stream. Also, not apparent from my posting, is the fact that all the stdout waited until the end of execution to appear on the screen.
我的问题如下:为什么会这样?，而且更重要的是是否有一种解决方法?
My questions are as follows: Why is this happening? and, less importantly Is there a way to fix it?
推荐答案
stdout的输出被缓冲:也就是说，print语句实际上写入缓冲区，并且该缓冲区只是偶尔刷新到终端.每个进程都有一个单独的缓冲区，这就是为什么不同进程的写入可能会乱序显示的原因(这是一个常见问题，如
The output to stdout is buffered: that is, print statements actually write to a buffer, and this buffer is only occassionally flushed to the terminal. Each process has a separate buffer, which is why writes from different processes can appear out of order (This is a common problem, as in Why subprocess stdout to a file is written out of order?)
在这种情况下，输出是按顺序排列的，但是在重定向时却显示为乱序.为什么? 本文解释:
In this case, the output is in order, but appears out of order when it is redirected. Why? This article explains:
- stdin始终处于缓冲状态
- stderr始终没有缓冲
- 如果stdout是终端，则缓冲将自动设置为行缓冲，否则将设置为缓冲
- stdin is always buffered
- stderr is always unbuffered
- if stdout is a terminal then buffering is automatically set to line buffered, else it is set to buffered
因此，当输出进入终端时，它会刷新每一行，并且碰巧出现在顺序中.重定向时，将使用一个长缓冲区(通常为4096个字节).由于您的打印量少于该值，因此先刷新的哪个子流程都将首先刷新.
So, when output was going to a terminal, it was flushing every line, and happened to appear in order. When redirecting, a long buffer is used (typically 4096 bytes). Since you printed less than that, whichever subprocess finished first was flushed first.
解决方案是使用flush()，或者完全禁用该进程的缓冲(请参见禁用输出缓冲)
The solution is to use flush(), or entirely disable buffering for the process (see Disable output buffering)
这篇关于从流重定向更正乱序打印的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
