FileStream.Windows useAsync WriteAsync calls blocking apis

[benaadams]

e.g SetEndOfFile in the async path is 50% of the time and it doesn't need to be called (as WriteFile will expand the File).

SetEndOfFile is also a blocking api itself; so expanding the file using it blocks the thread for as much time (or more) as the async saves blocking.

---

Previous

Seen in electricessence/AsyncFileWriter#1 (Windows 10; netcoreapp2.0 and netcoreapp2.1)

Non-async (just for FileStream.Write)

AsyncFileWriterTester>dotnet run -c Release
100,000 bounded capacity.
Total Time: 2.3680831 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:02.6254878
------------------------

10,000 bounded capacity.
Total Time: 2.0399536 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:02.3390593
------------------------

1,000 bounded capacity.
Total Time: 2.1499109 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:02.3699012
------------------------

100 bounded capacity.
Total Time: 2.0656293 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:03.0224013
------------------------

Press ENTER to continue.

Making the change electricessence/AsyncFileWriter@752f7ef

useAsync = true and fs.Write( => await fs.WriteAsync(

Causes a dramatic slow down:

AsyncFileWriterTester>dotnet run -c Release
100,000 bounded capacity.
Total Time: 4.1238278 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:14.3291113
------------------------

10,000 bounded capacity.
Total Time: 4.370184 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:19.3693952
------------------------

1,000 bounded capacity.
Total Time: 4.1362524 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:19.0104628
------------------------

100 bounded capacity.
Total Time: 4.2608508 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:20.4615956
------------------------

Press ENTER to continue.

Seems to use a lot of threads, though maybe that's Channels

[benaadams]

useAsync = false and await fs.WriteAsync

AsyncFileWriterTester>dotnet run -c Release
100,000 bounded capacity.
Total Time: 4.732445 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:20.8928633
------------------------

10,000 bounded capacity.
Total Time: 4.5554379 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:22.0848356
------------------------

1,000 bounded capacity.
Total Time: 4.7196995 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:21.6726637
------------------------

100 bounded capacity.
Total Time: 4.4949652 seconds
Total Bytes: 115,888,890
Total Wait Time: 00:00:21.4277106
------------------------

Press ENTER to continue.

[benaadams]

useAsync = false and await fs.WriteAsync

netcoreapp2.0

netcoreapp2.1

[benaadams]

netcoreapp2.1 useAsync = true

I was expecting FileStreamCompletionSource in the allocations from WriteAsyncInternalCore but don't see it? Is going via Stream base class?

[stephentoub]

Is this using a FileStream or is it using something derived from FileStream?

[stephentoub]

async FileStream Writing is x2 worse in perf than non-async

It's got more overhead and scales better; that's the tradeoff.

We could look at using an IValueTaskSource to back the new ValueTask-returning overload, but I'm afraid that ship may have sailed at this point, as it's an observable change and we're locking down the 2.1 release.

[electricessence]

https://stackoverflow.com/questions/49827208/ado-async-all-the-way-down-the-tubes/49837693#49837693

Iterate 1,000,000 times .Write(bytes)

Total Elapsed Time: 0.1750803 seconds

Iterate 1,000,000 times .WriteAsync(bytes)

Total Elapsed Time: 3.1865426 seconds

[electricessence]

And to be clear, the times Ben listed are not correct. The performance is much worse when Async.

@stephentoub:

It's got more overhead and scales better; that's the tradeoff.

That's what I've been thinking is that when quick-iterating, it's just not worth the async overhead per write. Especially if you've already got your data queued up.

[benaadams]

Is this using a FileStream or is it using something derived from FileStream?

FileStream directly:

using (var fs = new FileStream(FilePath, FileMode.Append, 
                      FileAccess.Write, FileShareMode, bufferSize: 4096 * 4, useAsync: true))

Overloads weren't looking right; as didn't go through ReadOnlyMemory<byte>; built self-contained and copied over coreclr test wrapper and the allocations are looking more like expected; but have built incorrectly for useAsync for the profile

[benaadams]

Closing for now; was concerned it wasn't taking the overlapped path, but that seem to not be the case - was a build mix up; probably from switching runtimes,

Will open a new one if I get a smaller repo for perf

[benaadams]

So WriteCore only calls VerifyOSHandlePosition() whereas WriteAsyncInternalCore makes far more syscalls (including VerifyOSHandlePosition())

With SetEndOfFile looking like it takes the same time as WriteFileNative

async FileStream, async WrtieAsync

[benaadams]

Non-async FileStream, blocking Write

[stephentoub]

@benaadams, I don't understand what the action item is meant to be on this issue.

[benaadams]

I don't understand what the action item is meant to be on this issue.

With this one weird trick... dotnet/coreclr#17581?

[benaadams]

Pre

Post

Pre

netcoreapp2.1\win-x64\publish>AsyncFileWriterTester.exe
100,000 bounded capacity.
Total Time: 9.2379032 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:00:51.9054476
------------------------

10,000 bounded capacity.
Total Time: 10.4082898 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:01:07.2506591
------------------------

1,000 bounded capacity.
Total Time: 10.5997765 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:01:10.7627665
------------------------

500 bounded capacity.
Total Time: 10.0306642 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:01:06.5325461
------------------------

100 bounded capacity.
Total Time: 10.7193698 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:01:08.3325643
------------------------

Press ENTER to continue.

Post

netcoreapp2.1\win-x64\publish>AsyncFileWriterTester.exe
100,000 bounded capacity.
Total Time: 2.2788458 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:00:04.6358343
------------------------

10,000 bounded capacity.
Total Time: 2.0491854 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:00:05.0332742
------------------------

1,000 bounded capacity.
Total Time: 1.8854354 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:00:03.7733625
------------------------

500 bounded capacity.
Total Time: 1.880664 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:00:03.7166907
------------------------

100 bounded capacity.
Total Time: 1.9010611 seconds
Total Bytes: 116,888,890
Aggregate Waiting: 00:00:03.8017758
------------------------

Press ENTER to continue.

[benaadams]

There's a second behviour difference. WriteAsync will issue a Flush+Write if it would over fill the buffer; whereas Write will issue a Flush and then copy into the cleared buffer (if under buffer size; otherwise Write); so may have an extra Write creeping in - but that's a more involved item to look at, at some point in future.

[electricessence]

@benaadams Make sure you're you are using the latest code. Your previous code was not completing all the writes. It just cut short and made the times look strange. They are much worse. (I added an assertion that compares the total bytes written to the total bytes of the file.) A successful benchmark has to have all the bytes written.

[benaadams]

Am using latest code; also using a very fast SSD so it would be much worse without it.

It looks like the main cause of slow down for async vs blocking is the number of extra file interactions that occur in that path; rather than it being async.

[benaadams]

e.g. SetEndOfFile in the async path is 50% of the time and it doesn't need to be called. It is also a blocking api itself; so expanding the file using it blocks the thread for as much time (or more) as the async saves blocking

[adamsitnik]

Fixed by #49975, please expect a blog post with all the details and perf numbers in April (before we ship preview 4)