.NET - Event OutputDataReceived is not triggered in time

OutputDataReceivedProcess的一个事件,会在接收到一行输出时触发事件,其定义如下:

Occurs each time an application writes a line to its redirected StandardOutput stream.

public event System.Diagnostics.DataReceivedEventHandler OutputDataReceived;

然而在实践过程中,其行为和预期可能并不一致,下面通过实验说明:

  • 创建一个主程序,主程序会执行一个子程序并截获其输出:
class StandardAsyncOutputExample
{
    public static void Run()
    {
        int lineCount = 0;
        Process process = new Process();
        process.StartInfo.FileName = @"D:\Workspace\test\output.exe";
        process.StartInfo.UseShellExecute = false;
        process.StartInfo.RedirectStandardOutput = true;
        process.OutputDataReceived += new DataReceivedEventHandler((sender, e) => {
            // Prepend line numbers to each line of the output.

            if (!String.IsNullOrEmpty(e.Data)) {
                lineCount++;
                var msg = "\n[" + lineCount + "]: " + e.Data;
                Console.WriteLine(msg);
            }
        });
 
        process.Start();
 
        // Asynchronously read the standard output of the spawned process. 

        // This raises OutputDataReceived events for each line of output.

        process.BeginOutputReadLine();
        process.WaitForExit();
    }
}

我们采用了不同的程序语言实现output子程序,发现了不同的情况:

  • C++
#include "stdafx.h"
#include <Windows.h>
 
int main()
{
    for (int i = 0; i &lt; 10; i++) {
        printf("Hello Message %d\r\n", i);
        ::Sleep(500);
    }
    return 0;
}

我们预期主程序将捕获的内容逐行输出停顿0.5秒后继续下一行,然而实际情况是等待子程序完成后,将整个10行输出集中输出,难以理解。

  • C#
using System;

namespace output
{
    class Program
    {
        static void Main(string[] args)
        {
            for (int i = 0; i < 10; i++) {
                Console.WriteLine("Message {0}", i);
                System.Threading.Thread.Sleep(500);
            }
        }
    }
}

C#程序是正常的。

  • 批处理
@echo off
echo 1
nsleep -s 0.5
echo 2
nsleep -s 0.5
echo 3
nsleep -s 0.5
echo 4
nsleep -s 0.5
echo 5
nsleep -s 0.5

批处理也正常。

  • Ruby
#!/bin/ruby

 
10.times do |i|
    puts "#{Process.pid} #{i} - #{ARGV.join(' ')}"
    sleep(1)
end

和C++程序一样,也会阻塞。

  • 原因揭晓

之所以接收端在最后程序退出的时刻才获取到输出,是因为发送端在每次输出之后没有及时调用fflush的原因所致,对于上面C++版本的输出程序,如果在每次printf之后调用fflush(stdout)就Ok。

void output_msg(const char *msg, int count, bool auto_flush)
{
    auto id = ::GetCurrentProcessId();
    for (int i = 0; i < count; i++) {
        printf("[%d] (v.%s %s) Message %d: %s\r\n", id, __DATE__, __TIME__, i + 1, msg);
        if (auto_flush) fflush(stdout);
        ::Sleep(500);
    }
}