Why are .Net Core Async Stream operations dramatically slower than synchronous operations?

Question

I wouldn't expect an async benefit in this particular command line harness, but neither would I expect such a large penalty.

On my machine, under repeated runs, for a 46 MB input file (Git-2.27.0-64-bit.exe) the async version is consistently around 7x slower.

I find it surprising that disposing the outputFile stream takes so long (averaging arouund 16 seconds) even though it is preceded by an explicit Flush/FlushAsync - however that is the case for both the synchronous and asynchronous calls, so not a difference between them.
In the async version ConfigureAwait(false) doesn't appear to make much difference in this particular harness (and I didn't really expect it to)
Playing with buffer size in CopyTo/CopyToAsync didn't seem to narrow the gap any.

Example Asynchronous results:

\Base64\bin\Release\netcoreapp3.1>Base64.exe
WriteFile completed in 00:02:40.5583442
Flushing outputFile
Flush outputFile completed in 00:00:00.0010565
disposing outputFile
disposed outputFile in 00:00:15.7304240
disposing base64Stream
disposed base64Stream in 00:00:00.0029926
disposing inputFile
disposed inputFile in 00:00:00.0002473
disposing base64Transform
disposed base64Transform in 00:00:00.0020258
Total Elapsed: 00:02:56.3132804

Example Synchronous results:

\Base64\Base64\bin\Release\netcoreapp3.1>Base64.exe
WriteFile completed in 00:00:08.9381189
Flushing outputFile
Flush outputFile completed in 00:00:00.0016328
disposing outputFile
disposed outputFile in 00:00:16.5799980
disposing base64Stream
disposed base64Stream in 00:00:00.0046472
disposing inputFile
disposed inputFile in 00:00:00.0019350
disposing base64Transform
disposed base64Transform in 00:00:00.0014333
Total Elapsed: 00:00:25.5501378

Asynchronous test

static async Task Main(string[] args)
{
    var totalStopWatch = new Stopwatch();
    totalStopWatch.Start();

    var stopWatch = new Stopwatch();
    stopWatch.Start();

    using (var base64Transform = new ToBase64Transform())
    {
        await using (FileStream inputFile = new FileStream(@"Git-2.27.0-64-bit.exe", FileMode.Open, FileAccess.Read))
        {
            await using (CryptoStream base64Stream = new CryptoStream(inputFile, base64Transform, CryptoStreamMode.Read))
            {
                await using (FileStream outputFile = new FileStream($@"outfile{Guid.NewGuid()}.html", FileMode.CreateNew, FileAccess.Write))
                {
                    await outputFile.WriteAsync(Encoding.UTF8.GetBytes(@"<!doctype html>
    <html>
    <head>
    <title>base 64 encoding test</title>
    </head>
    <body>
        <img alt=""Ok so not really an image."" src=""data:image/jpeg;base64,")).ConfigureAwait(false);

                    await base64Stream.CopyToAsync(outputFile, 8192).ConfigureAwait(false);

                    await outputFile.WriteAsync(Encoding.UTF8.GetBytes(@""" />
    </body>
    </html>
    ")).ConfigureAwait(false);

                    Console.WriteLine($"WriteFile completed in {stopWatch.Elapsed}");

                    stopWatch.Restart();
                    Console.WriteLine($"Flushing {nameof(outputFile)}");
                    await outputFile.FlushAsync().ConfigureAwait(false);
                    Console.WriteLine($"Flush {nameof(outputFile)} completed in {stopWatch.Elapsed}");

                    stopWatch.Restart();
                    Console.WriteLine($"disposing {nameof(outputFile)}");
                }
                Console.WriteLine($"disposed outputFile in {stopWatch.Elapsed}");

                stopWatch.Restart();
                Console.WriteLine($"disposing {nameof(base64Stream)}");
            }
            Console.WriteLine($"disposed base64Stream in {stopWatch.Elapsed}");

            stopWatch.Restart();
            Console.WriteLine($"disposing {nameof(inputFile)}");
        }
        Console.WriteLine($"disposed inputFile in {stopWatch.Elapsed}");

        stopWatch.Restart();
        Console.WriteLine($"disposing {nameof(base64Transform)}");
    }
    Console.WriteLine($"disposed base64Transform in {stopWatch.Elapsed}");

    Console.WriteLine($"Total Elapsed: {totalStopWatch.Elapsed}");
}

Synchronous test

static void Main(string[] args)
{
    var totalStopWatch = new Stopwatch();
    totalStopWatch.Start();

    var stopWatch = new Stopwatch();
    stopWatch.Start();

    using (var base64Transform = new ToBase64Transform())
    {
        using (FileStream inputFile = new FileStream(@"Git-2.27.0-64-bit.exe", FileMode.Open, FileAccess.Read))
        {
            using (CryptoStream base64Stream = new CryptoStream(inputFile, base64Transform, CryptoStreamMode.Read))
            {
                using (FileStream outputFile = new FileStream($@"outfile{Guid.NewGuid()}.html", FileMode.CreateNew, FileAccess.Write))
                {
                    outputFile.Write(Encoding.UTF8.GetBytes(@"<!doctype html>
    <html>
    <head>
    <title>base 64 encoding test</title>
    </head>
    <body>
        <img alt=""Ok so not really an image."" src=""data:image/jpeg;base64,"));

                    base64Stream.CopyTo(outputFile, 8192);

                    outputFile.Write(Encoding.UTF8.GetBytes(@""" />
    </body>
    </html>
    "));
                    Console.WriteLine($"WriteFile completed in {stopWatch.Elapsed}");

                    stopWatch.Restart();
                    Console.WriteLine($"Flushing {nameof(outputFile)}");
                    outputFile.Flush();
                    Console.WriteLine($"Flush {nameof(outputFile)} completed in {stopWatch.Elapsed}");

                    stopWatch.Restart();
                    Console.WriteLine($"disposing {nameof(outputFile)}");
                }
                Console.WriteLine($"disposed outputFile in {stopWatch.Elapsed}");

                stopWatch.Restart();
                Console.WriteLine($"disposing {nameof(base64Stream)}");
            }
            Console.WriteLine($"disposed base64Stream in {stopWatch.Elapsed}");

            stopWatch.Restart();
            Console.WriteLine($"disposing {nameof(inputFile)}");
        }
        Console.WriteLine($"disposed inputFile in {stopWatch.Elapsed}");

        stopWatch.Restart();
        Console.WriteLine($"disposing {nameof(base64Transform)}");
    }
    Console.WriteLine($"disposed base64Transform in {stopWatch.Elapsed}");

    Console.WriteLine($"Total Elapsed: {totalStopWatch.Elapsed}");
}

Have you tried setting the `isAsync` to `true` (to use the *overlapped I/O mode*) in the constructor of the `FileStream` so the `WinApi` uses the [`FILE_FLAG_OVERLAPPED`](https://learn.microsoft.com/en-au/windows/win32/fileio/synchronous-and-asynchronous-i-o?redirectedfrom=MSDN) structure ? Anyway you are not likely to get any performance benefit from the `async` methods in any normal sense. — TheGeneral, Sep 02 '20 at 03:05
I didn't expect an async benefit. I'm looking for an explanation of the *large* penalty. I missed FileOptions.Asynchrounous as a constructor option. I'll give that a try. — Nathan, Sep 02 '20 at 03:07
Otherwise you will be giving your self a whole lot of overhead for no reason and no benefit. — TheGeneral, Sep 02 '20 at 03:08
What does `async` do for you in a console application? There is no context to worry about. You notice the benefits of `async/await` when working in the backend or in a UI framework like WinForms or WPF. This pattern wasn't created to increase speed in your application. It was to make parallel programming easier when dealing with a context. — Andy, Sep 02 '20 at 03:15
@Andy - As I stated in the question, I did not expect an async benefit in this scenario. I was surprised by the large penalty. There are scenarios where async io could be helpful. Learning scenarios and experimentation are not always for the purpose of immediate production usage. They are still useful for gaining understanding. — Nathan, Sep 02 '20 at 03:23
@Andy although true, the real benefit of the *async and await* pattern is actually scalability, thats not to say it doesn't make working with continuations and message-pumps (or similar technologies) easier, simplistic and succinct. Yet many non UI frameworks actually benefit the most from through-put and scalability — TheGeneral, Sep 02 '20 at 03:24
@Nathan are your results much diffrent with the async options or parameter set ? — TheGeneral, Sep 02 '20 at 03:28
Adding 8192 as a buffer size with `FileOptions.Asynchronous | FileOptions.SequentialScan` made it almost identical — JohanP, Sep 02 '20 at 03:30
So simply adding `useAsync:true` immediately brought the asynchronous much closer to the synchronous code. Using `FileOptions.Asynchrounous` alone seemed on par with `useAsync:true`. Adding both `FileOptions.Asynchronous | FileOptions.SequentialScan` seemed to bring the difference down even further on average, at least to the point where I would need more rigorous benchmarks to determine an average difference - that is "nearly identical". Also pointed out by @JohanP to make the buffer sizes match between the file stream constructors and the `CopytTo` operations. — Nathan, Sep 02 '20 at 03:49
For those of you playing at home `FileOptions.Asynchronous` does exactly the same as `isAsync`. When its not applied the `async` operations are actually synchronous and doesn't follow through to the OS (with a massive overhead) and is creating a task for every internal buffer read. the sequential scan is defaulted in both and shouldn't factor, so is the defaulted buffer size. all in all async will be slower, however it will be better for your resources and threadpool which would make it more scalable in a larger system — TheGeneral, Sep 02 '20 at 03:51
Somewhat related: [Why File.ReadAllLinesAsync() blocks the UI thread?](https://stackoverflow.com/questions/63217657/why-file-readalllinesasync-blocks-the-ui-thread) There are some interesting comments regarding performance under the accepted answer. — Theodor Zoulias, Sep 02 '20 at 10:05

Why are .Net Core Async Stream operations dramatically slower than synchronous operations?

0 Answers0