.Net 6. Running processes as separate tasks increases the execution time drastically #67506
Comments
dotnet-issue-labeler
bot
added
area-System.Diagnostics.Process
untriaged
|
Tagging subscribers to this area: @dotnet/area-system-diagnostics-process Issue DetailsDescriptionStarting and running processes as separate tasks increases the execution time up to 10 times. Configuration.Net 6.0 The following code runs using System.Diagnostics;
using System.Text;
Console.WriteLine("Start processes sync");
Run(16, "/bin/ls", async: false);
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
if (async)
{
var tasks = new Task[count];
for (var i = 0; i < count; i += 1)
{
var task = new Task(() => {
RunProcess(fileName);
});
tasks[i] = task;
task.Start();
}
Task.WaitAll(tasks);
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
process.WaitForExit();
}
Console.WriteLine($"{fileName}: {stopWatch.Elapsed.TotalMilliseconds}");
}Data
|
|
What happens if you use threads instead? I see there's a difference in the task vs non-task variant in that the async example starts all processes simultaneously (or as many as the threadpool will allow). While the sync variant starts them one by one sequentially. Meaning the problem could be anywhere, perhaps not related to tasks at all. What happens if you modify the code to wait for each task one by one? |
|
I ran this and consistently the child processes are slower -- even if I ensure the How many cores do you have? I am guessing part of the issue is the the threadpool assumes you are giving it CPU bound work and will not allow more active threads than roughly the number of cores (or whatever its starting heuristic is). If launching and running Stepping back -- what are you trying to achieve? |
danmoseley
added
area-System.Threading.Tasks
and removed
area-System.Diagnostics.Process
labels
|
Tagging subscribers to this area: @dotnet/area-system-threading-tasks Issue DetailsDescriptionStarting and running processes as separate tasks increases the execution time up to 10 times. Configuration.Net 6.0 The following code runs using System.Diagnostics;
using System.Text;
Console.WriteLine("Start processes sync");
Run(16, "/bin/ls", async: false);
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
if (async)
{
var tasks = new Task[count];
for (var i = 0; i < count; i += 1)
{
var task = new Task(() => {
RunProcess(fileName);
});
tasks[i] = task;
task.Start();
}
Task.WaitAll(tasks);
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
process.WaitForExit();
}
Console.WriteLine($"{fileName}: {stopWatch.Elapsed.TotalMilliseconds}");
}Data
|
|
Thank you for your response.
My use case is pretty simple. GUI application runs about 10-15 relatively short (~30-50ms) git commands on start which makes a noticeable freeze. The operations are (seemingly) absolutely independent. Surprisingly, after running them as tasks, the execution time of a single process increases multiple times and the total time remains basically the same. While I was investigating the problem, I noticed, that the problem can be reproduced with any process, even with A few notes:
It seems to me the problem is in the Process class, but I don't have enough expertise to confirm that (or not).
I don't see any difference. Expand the following section for the details: Threads instead of Tasks. Increased Thread Poolusing System.Diagnostics;
using System.Text;
Console.WriteLine("Start processes sync");
Run(16, "/bin/ls", async: false);
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
if (async)
{
ThreadPool.SetMinThreads(count + 10, count + 10);
var threads = new Thread[count];
for (var i = 0; i < count; i += 1)
{
threads[i] = new Thread(ThreadProc);
}
for (var i = 0; i < count; i += 1)
{
threads[i].Start(fileName);
}
for (var i = 0; i < count; i += 1)
{
threads[i].Join();
}
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
}
void ThreadProc(object? obj)
{
RunProcess((obj as string)!);
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
process.WaitForExit();
}
Console.WriteLine($"{fileName}: {stopWatch.Elapsed.TotalMilliseconds}");
}Results:
This way the processes are executed as fast as they should. Please expand the section below for the details: Wait for each threadusing System.Diagnostics;
using System.Text;
Console.WriteLine("Start processes sync");
Run(16, "/bin/ls", async: false);
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
if (async)
{
ThreadPool.SetMinThreads(count + 10, count + 10);
var threads = new Thread[count];
for (var i = 0; i < count; i += 1)
{
threads[i] = new Thread(ThreadProc);
}
for (var i = 0; i < count; i += 1)
{
threads[i].Start(fileName);
threads[i].Join();
}
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
}
void ThreadProc(object? obj)
{
RunProcess((obj as string)!);
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
process.WaitForExit();
}
Console.WriteLine($"{fileName}: {stopWatch.Elapsed.TotalMilliseconds}");
}Results: I think I've answered all your questions. Please let me know if I missed something. |
|
Nice details, and research! Based on this, the slowdown should be related to the degree of parallelism and processes started simultaneously, and not tasks/threads by themselves. Since waiting for each task/thread seems to yield the fast result. Maybe the application has to wait for a common lock or a blocking OS resource during process Start. I don't have too much insight into the Process implementation under Linux. Maybe someone else have and can explain why this occurs. Could also be valuable to see if the same occurs on Windows. |
|
@DanPristupov Can you please measure the total elapsed time for sync / async. |
|
Windows: |
It's MacOS. Sorry if it wasn't clear. Still *nix though.
@devsko posted that just above. Looks like Windows can also be affected.
I tried to distribute the process start and added |
|
As a side note, starting a process on M1(ARM) CPU is 10 times slower than on Intel CPU: Source codeusing System.Diagnostics;
using System.Text;
Console.WriteLine("Start processes sync");
Run(16, "/bin/ls", async: false);
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
var stopWatch = Stopwatch.StartNew();
if (async)
{
var tasks = new Task[count];
for (var i = 0; i < count; i += 1)
{
var task = new Task(() => {
RunProcess(fileName);
});
tasks[i] = task;
task.Start();
}
Task.WaitAll(tasks);
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
var typeString = async ? "async" : "sync";
Console.WriteLine($"Total type {typeString} {stopWatch.Elapsed.TotalMilliseconds}");
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
process.WaitForExit();
}
Console.WriteLine($"{fileName}: {stopWatch.Elapsed.TotalMilliseconds}");
}Intel (2.3ms avg)M1 (25ms avg)Do you think I should create a separate issue for that? |
Yes please, it was flagged here #67339 but we didn't create an issue. |
I just realized I used Linux. My M1 hasn't arrived yet. Does this repro on Linux for someone else? Or is somehow specific to Windows and Mac (?!) What if you log the time (eg ticks) between when the loop starts, and when process.Start is called? presumably that will show a delay, which ideally in your case would be zero for each call. |
Source codeusing System.Diagnostics;
using System.Text;
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
var stopWatch = Stopwatch.StartNew();
if (async)
{
var tasks = new Task[count];
for (var i = 0; i < count; i += 1)
{
var task = new Task(() => {
Console.WriteLine($"delay: {stopWatch.ElapsedMilliseconds} ms");
RunProcess(fileName);
});
tasks[i] = task;
task.Start();
}
Task.WaitAll(tasks);
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
var typeString = async ? "async" : "sync";
Console.WriteLine($"Total type {typeString} {stopWatch.Elapsed.TotalMilliseconds}");
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
process.WaitForExit();
}
Console.WriteLine($"{fileName}: {stopWatch.Elapsed.TotalMilliseconds}");
}MBP16 M1 Max: My current machine has 10 cores, so the ThreadPool size is also 10. There are 16 tasks, and because of the ThreadPool overflow 2 virtual groups appeared: 10 and 6 simultaneous tasks. We can see that each single process in a group somehow waits for the whole group of the parallel processes. |
|
Hello everyone. Command: CMD /c dir But i think it maybe something with multiple Tasks running at the same time. |
|
I decided to run the profiler. Source codeusing System.Diagnostics;
using System.Text;
System.Threading.Thread.Sleep(5*1000); // sleep to allow to attach the profiler
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
var stopWatch = Stopwatch.StartNew();
if (async)
{
var tasks = new Task[count];
for (var i = 0; i < count; i += 1)
{
var task = new Task(() => {
RunProcess(fileName);
});
tasks[i] = task;
task.Start();
}
Task.WaitAll(tasks);
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
var typeString = async ? "async" : "sync";
Console.WriteLine($"Total type {typeString} {stopWatch.Elapsed.TotalMilliseconds}");
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
process.WaitForExit();
}
Console.WriteLine($"{fileName}: {stopWatch.Elapsed.TotalMilliseconds}");
}Run the profiler on M1 Max: The hot point is the
Direct link to the source code: // Invoke the shim fork/execve routine. It will create pipes for all requested
// redirects, fork a child process, map the pipe ends onto the appropriate stdin/stdout/stderr
// descriptors, and execve to execute the requested process. The shim implementation
// is used to fork/execve as executing managed code in a forked process is not safe (only
// the calling thread will transfer, thread IDs aren't stable across the fork, etc.)
int errno = Interop.Sys.ForkAndExecProcess(
resolvedFilename, argv, envp, cwd,
startInfo.RedirectStandardInput, startInfo.RedirectStandardOutput, startInfo.RedirectStandardError,
setCredentials, userId, groupId, groups,
out childPid, out stdinFd, out stdoutFd, out stderrFd);I've attached the full trace file here StartProcessTest_20220408_102243.speedscope.json.zip You can unzip and open it yourself on https://speedscope.net Also: StartProcessTest_20220408_102243.nettrace.zip
Then it calls |
|
There is a comment in // Lock to avoid races with OnSigChild
// By using a ReaderWriterLock we allow multiple processes to start concurrently.
s_processStartLock.EnterReadLock();Maybe if has never been working properly or it could be a regression. |
|
Even if there were a global lock I'd expect the total time to be roughly the same. A global lock would at most reduce concurrency to 1, as before. Lock overhead can't be relevant here. Why is it 10x slower? |
|
The reader lock gets taken while starting processes, the writer lock is taken when a process exits. In the async case, different processes are starting simultaneous, so the For the sync case, you need to sum the elapsed times. If you move the |
|
For some additional info, see #25879. |
I'm might be missing something, but it looks like
Do you mean like this? Source codeusing System.Diagnostics;
using System.Text;
Console.WriteLine("Start processes sync");
Run(16, "/bin/ls", async: false);
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
var stopWatch = Stopwatch.StartNew();
if (async)
{
var tasks = new Task[count];
for (var i = 0; i < count; i += 1)
{
var task = new Task(() => {
RunProcess(fileName);
});
tasks[i] = task;
task.Start();
}
Task.WaitAll(tasks);
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
var typeString = async ? "async" : "sync";
Console.WriteLine($"Total time {typeString} {stopWatch.Elapsed.TotalMilliseconds}");
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
process.WaitForExit();
}
}In my case, the total time doesn't change that much. M1:
Well, yes, but I don't understand why each of the concurrent events take 5-10 times longer. It doesn't excuse the fact that user must wait for output of a single process 200ms instead of 30ms. |
|
Sorry, I had overlooked this issue was for macOS specifically. On macOS, process starts are serialized due to missing runtime/src/native/libs/System.Native/pal_process.c Lines 286 to 297 in cde7799 |
And for similar reasons, Windows has a lock also: |
|
@tmds is there any possible workaround for that particular use case (i.e. running about 10 processes about 60ms each). I'm just trying to decrease the delay a user must wait for data to appear. |
|
If you can remove the Also, if you are blocking Tasks you might starve the ThreadPool causing things to go even slower. For processes that run long, you should use |
No. I removed it and the result is the same :( With Without Source codeusing System.Diagnostics;
using System.Text;
Console.WriteLine("Start processes sync");
Run(16, "/bin/ls", async: false);
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
var stopWatch = Stopwatch.StartNew();
if (async)
{
var tasks = new Task[count];
for (var i = 0; i < count; i += 1)
{
var task = new Task(() => {
RunProcess(fileName);
});
tasks[i] = task;
task.Start();
}
Task.WaitAll(tasks);
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
var typeString = async ? "async" : "sync";
Console.WriteLine($"Total time {typeString} {stopWatch.Elapsed.TotalMilliseconds}");
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
// process.WaitForExit();
}
Console.WriteLine($"{fileName}: {stopWatch.Elapsed.TotalMilliseconds}");
} |
You get these lower values due to not waiting for exit. |
|
I was curious how that case is handled by Swift. It turned out on Swift async is always faster. M1 (sync: Intel (sync: Source codeimport Foundation
run(count: 16, path: "/bin/ls", async: false)
run(count: 16, path: "/bin/ls", async: true)
func run(count: Int, path: String, async: Bool) {
print("Start processes \(async ? "async" : "sync")")
let start = DispatchTime.now()
let operationQueue = OperationQueue()
if !async {
operationQueue.addOperation {
for _ in 0..<count {
runProcess(path: path)
}
}
} else {
for _ in 0..<count {
operationQueue.addOperation {
runProcess(path: path)
}
}
}
operationQueue.waitUntilAllOperationsAreFinished()
let nanoTime = DispatchTime.now().uptimeNanoseconds - start.uptimeNanoseconds
let elapsed = Int(Double(nanoTime) / 1_000_000)
print("Total time \(async ? "async" : "sync") \(elapsed)ms")
}
func runProcess(path: String) {
let start = DispatchTime.now()
let process = Process()
process.launchPath = path
let outputPipe = Pipe()
process.standardOutput = outputPipe
process.launch()
let _ = outputPipe.fileHandleForReading.readDataToEndOfFile()
process.waitUntilExit()
let nanoTime = DispatchTime.now().uptimeNanoseconds - start.uptimeNanoseconds
let elapsed = Int(Double(nanoTime) / 1_000_000)
print("\(path) \(elapsed)ms")
} |
This uses the macOS specific With .NET, any inheritable handle is available to any child. There is an open issue for an API that would allow to specify the inheritance: #13943. However, because there may be a child To use |
ghost
removed
the
stephentoub
added
area-System.Diagnostics.Process
and removed
area-System.Threading.Tasks
labels
|
Tagging subscribers to this area: @dotnet/area-system-diagnostics-process Issue DetailsDescriptionStarting and running processes as separate tasks increases the execution time up to 10 times. Configuration.Net 6.0 The following code runs using System.Diagnostics;
using System.Text;
Console.WriteLine("Start processes sync");
Run(16, "/bin/ls", async: false);
Console.WriteLine("Start processes async");
Run(16, "/bin/ls", async: true);
Console.WriteLine("Done!");
void Run(int count, string fileName, bool async)
{
if (async)
{
var tasks = new Task[count];
for (var i = 0; i < count; i += 1)
{
var task = new Task(() => {
RunProcess(fileName);
});
tasks[i] = task;
task.Start();
}
Task.WaitAll(tasks);
}
else
{
for (var i = 0; i < count; i += 1)
{
RunProcess(fileName);
}
}
}
void RunProcess(string fileName)
{
var stopWatch = Stopwatch.StartNew();
using (var process = new Process())
{
process.StartInfo = new ProcessStartInfo
{
FileName = fileName,
UseShellExecute = false,
RedirectStandardOutput = true,
ErrorDialog = false,
CreateNoWindow = true,
RedirectStandardInput = true,
StandardOutputEncoding = Encoding.UTF8,
};
process.Start();
var output = process.StandardOutput.ReadToEnd();
process.WaitForExit();
}
Console.WriteLine($"{fileName}: {stopWatch.Elapsed.TotalMilliseconds}");
}Data
|
Description
Starting and running processes as separate tasks increases the execution time up to 10 times.
Configuration
.Net 6.0
So far, I've reproduced the problem on both Intel and M1 macs.
The following code runs
ls, but it can be any other process.Data
The text was updated successfully, but these errors were encountered: