Repository navigation
Redirecting process output blocks entire program on Ubuntu #27304
Description
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.
Activity
tmds commentedon Sep 7, 2018
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 commentedon Sep 11, 2018
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:
To me that seems really long for the ThreadPool adjusting to the demand.
tmds commentedon Sep 11, 2018
Neither. It was to check if that is what we are observing: the blocking reads are starving the threadpool.
tmds commentedon Oct 22, 2018
@wtgodbe does this behave better on Windows? Or do the Reads also happen on the ThreadPool?
stephentoub commentedon Oct 22, 2018
@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 commentedon Oct 24, 2019
@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 commentedon Jan 6, 2025
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 commentedon Jan 20, 2025
This issue will now be closed since it had been marked
no-recent-activitybut 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.