從流重定向中糾正亂序打印

Question

我有一個Python腳本，它使用multiprocessing.pool.map來完成一些工作。因爲它打印到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等到執行結束出現在屏幕上。

我的問題如下：這是爲什麼發生？，不太重要的有沒有辦法解決它？

Answer 1

緩衝輸出到stdout：也就是說，打印語句實際寫入緩衝區，並且此緩衝區僅偶爾刷新到終端。每個進程都有一個單獨的緩衝區，這就是爲什麼來自不同進程的寫入可能會出現亂序（這是一個常見問題，如在Why subprocess stdout to a file is written out of order?中）

在這種情況下，輸出按順序排列，它被重定向。爲什麼？ This article說明：

• 標準輸入總是緩衝
• stderr中總是無緩衝
• 如果stdout是終端然後緩衝自動設置爲行緩衝，否則它被設定爲緩衝

所以，當輸出到一個終端時，它正在沖洗每一行，並碰巧按順序出現。重定向時，使用長緩衝區（通常爲4096字節）。由於您打印的數量少於此數量，因此首先完成的子流程首先被刷新。

的解決方案是使用flush()，或完全禁用緩存的處理（參照Disable output buffering）