Redirecting process output blocks entire program on Ubuntu

[jnodev]

We observe strange behavior on our application, when starting processes with their output redirected. The complete application seems to be affected and gets very slow. This is very notable when the started processes write data to stdout in a medium frequency (e.g. 10 Hz).

We observe this with the current SDK (2.1.401) on Ubuntu 16.04.

I created a minimal repo to reproduce the issue. For future references I also uploaded the files to a gist.

Current behavior
The program starts a script multiple (5) times, which prints to stdout with 10Hz. It then creates a few (3) Tasks, which measure how long a delay takes (should take 500ms). They write "SLEPT TOO LONG" to the console, when the delay exceeds a threshold (100ms).

When I execute the program with dotnet run on a decent machine with an i7-6700K CPU @ 4.00GHz, I receive the following output:

Start sleep test. {
                numberOfProcesses: 5,
                spamSleepInSeconds: 0.1,
                numberOfSleepTests: 3,
                sleepTestDelay: 500,
                sleepTestTolerance: 100,
                redirect: True
            }

------- SLEPT TOO LONG: 8603.7407
------- SLEPT TOO LONG: 8606.5207
------- SLEPT TOO LONG: 8101.826
------- SLEPT TOO LONG: 2674.7937
------- SLEPT TOO LONG: 2674.9363
------- SLEPT TOO LONG: 1638.7887
------- SLEPT TOO LONG: 2282.059
------- SLEPT TOO LONG: 1743.126
------- SLEPT TOO LONG: 1231.055

It seems that the delay that should have taken 500ms, is exceeded by several seconds, especially at the beginning.

Expected behavior
Do not see any "SLEPT TOO LONG". This can be archived by setting redirect to false in line 20, but this should also be possible with the output redirected.

[tmds]

Looking a bit at the implementation I think the reading the child output is performed on the ThreadPool.
When the threads are exhausted, it takes a while for new threads to be added. This may be what you are observing.
What happens when you increase the thread count at the start: ThreadPool.SetMinThreads(100, 100)?

[jnodev]

Thank you for your response. Increasing the minimum amount of threads in the ThreadPool indeed seem to fix the issue at least in the sample program. But I am not sure if that is really a fix or just a work-around. For example when running the sample program with 10 processes, each printing with 2Hz (without raising the minimum thread amount) it takes over a minute before the program is running as expected:

Start sleep test. {
                numberOfProcesses: 10,
                spamSleepInSeconds: 0.5,
                numberOfSleepTests: 3,
                sleepTestDelay: 500,
                sleepTestTolerance: 100,
                redirect: True
            }

------- SLEPT TOO LONG: 992.2123
------- SLEPT TOO LONG: 71362.003
------- SLEPT TOO LONG: 71362.7185
------- SLEPT TOO LONG: 70368.6326

To me that seems really long for the ThreadPool adjusting to the demand.

[tmds]

But I am not sure if that is really a fix or just a work-around.

Neither. It was to check if that is what we are observing: the blocking reads are starving the threadpool.

[tmds]

@wtgodbe does this behave better on Windows? Or do the Reads also happen on the ThreadPool?

[stephentoub]

@tmds, I would expect a similar issue on Windows, as the pipes created for the redirect FileStreams are currently opened for synchronous rather than overlapped I/O.

[tmds]

@stephentoub I'd be interested in taking a look into this for Linux/Unix.
Adding a shared poll thread, would be a way to make the operations async without blocking the threadpool.
Maybe someone else wants to improve this for Windows.

[dotnet-policy-service]

Due to lack of recent activity, this issue has been marked as a candidate for backlog cleanup. It will be closed if no further activity occurs within 14 more days. Any new comment (by anyone, not necessarily the author) will undo this process.

This process is part of our issue cleanup automation.

[dotnet-policy-service]

This issue will now be closed since it had been marked no-recent-activity but received no further activity in the past 14 days. It is still possible to reopen or comment on the issue, but please note that the issue will be locked if it remains inactive for another 30 days.