Aspnetcore: JsonResult with Newtonsoft.Json results in synchronous IO in large responses

[timgabrhel]

Describe the bug

I am utilizing Ben.BlockingDetector package to identify and resolve any synchronous blockers in my app. I have found a scenario where my API is buffering the response to disk, which is resulting in a synchronous IO call.

The response data of the request is 62KB. I am returning a new JsonResult(myObj). I've found when intentionally clearing one of the large properties on the response, it takes me down to 12KB and no buffering takes place.

To Reproduce

Enable Newtonsoft.Json for serialization and return a large object.

    .AddMvc()
    .SetCompatibilityVersion(CompatibilityVersion.Version_3_0)
    .AddNewtonsoftJson(delegate (MvcNewtonsoftJsonOptions op)
    {
        op.SerializerSettings.Converters.Add(new StringEnumConverter());
        op.SerializerSettings.ReferenceLoopHandling = Newtonsoft.Json.ReferenceLoopHandling.Ignore;
    });

Create an endpoint (this returns ~65KB)

[HttpGet]
[AllowAnonymous]
[Route("/largeresponse")]
public IActionResult LargeResponse()
{
    return new JsonResult(new {d = Enumerable.Range(0, 150).Select(i => "Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo consequat. Duis aute irure dolor in reprehenderit in voluptate velit esse cillum dolore eu fugiat nulla pariatur. Excepteur sint occaecat cupidatat non proident, sunt in culpa qui officia deserunt mollit anim id est laborum." )});
}

Install Ben.BlockingDetector, and observe output.

      Blocking method has been invoked and blocked, this can lead to threadpool starvation.
         at System.Threading.Tasks.TplEventSource.TaskWaitBegin(Int32 OriginatingTaskSchedulerID, Int32 OriginatingTaskID, Int32 TaskID, TaskWaitBehavior Behavior, Int32 ContinueWithTaskID)
         at System.Threading.Tasks.Task.InternalWaitCore(Int32 millisecondsTimeout, CancellationToken cancellationToken)
         at System.IO.FileStream.Write(Byte[] array, Int32 offset, Int32 count)
         at Microsoft.AspNetCore.WebUtilities.PagedByteBuffer.MoveTo(Stream stream)
         at Microsoft.AspNetCore.WebUtilities.FileBufferingWriteStream.Write(Byte[] buffer, Int32 offset, Int32 count)
         at Microsoft.AspNetCore.WebUtilities.HttpResponseStreamWriter.FlushInternal(Boolean flushEncoder)
         at Microsoft.AspNetCore.WebUtilities.HttpResponseStreamWriter.Write(String value)
         at Newtonsoft.Json.Utilities.JavaScriptUtils.WriteEscapedJavaScriptString(TextWriter writer, String s, Char delimiter, Boolean appendDelimiters, Boolean[] charEscapeFlags, StringEscapeHandling stringEscapeHandling, IArrayPool`1 bufferPool, Char[]& writeBuffer)
         at Newtonsoft.Json.JsonTextWriter.WriteEscapedString(String value, Boolean quote)
         at Newtonsoft.Json.JsonWriter.WriteValue(JsonWriter writer, PrimitiveTypeCode typeCode, Object value)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeList(JsonWriter writer, IEnumerable values, JsonArrayContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeObject(JsonWriter writer, Object value, JsonObjectContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty)
         at Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.Serialize(JsonWriter jsonWriter, Object value, Type objectType)
         at Newtonsoft.Json.JsonSerializer.SerializeInternal(JsonWriter jsonWriter, Object value, Type objectType)
         at Newtonsoft.Json.JsonSerializer.Serialize(JsonWriter jsonWriter, Object value)
         at Microsoft.AspNetCore.Mvc.NewtonsoftJson.NewtonsoftJsonResultExecutor.ExecuteAsync(ActionContext context, JsonResult result)

Further technical details

C:\Users\timga>dotnet --info
.NET Core SDK (reflecting any global.json):
 Version:   3.1.100
 Commit:    cd82f021f4

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.18363
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\3.1.100\

Host (useful for support):
  Version: 3.1.0
  Commit:  65f04fb6db

.NET Core SDKs installed:
  3.1.100 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.14 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.14 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.0.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.14 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.2.8 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.0.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 3.0.1 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 3.1.0 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

• VS2019 16.4.2

I originally posted this issue in the BlockingDetector project.
https://github.com/benaadams/Ben.BlockingDetector/issues/14

[Tratcher]

We usually categorize file IO separately from network IO. That said, why is FileStream.Write doing a Task.Wait?

Oh, oh dear... why would they do that?
https://github.com/dotnet/runtime/blob/07f9134f21d99e1a8906619f6c741a49d78b6fa5/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.cs#L424-L435

We mark the stream as async because we want to be able to read out the content async, but maybe we should change that.
https://github.com/dotnet/aspnetcore/blob/3d034feef860002ff53ed70f56d7d11301763293/src/Http/WebUtilities/src/FileBufferingWriteStream.cs#L227-L233

[timgabrhel]

@Tratcher I'm also seeing the same behavior on FileStream.Read (uploading the file bytes[] as a string).

https://github.com/dotnet/runtime/blob/07f9134f21d99e1a8906619f6c741a49d78b6fa5/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.cs#L302-L308

Any ideas to workout for either behavior? I'm more concerned about the FileStream.Write's (API outbound). Some of our data heavy pages hit an excessive number of blocks on the way out with so much data (that's a different issue 🙃)

[anurse]

Triage: The medium-term recommendation here is to migrate to the System.Text.Json serializer that does support a fully async API. Obviously that comes with trade-offs if you are using Newtonsoft features.

Any ideas to workout for either behavior? I'm more concerned about the FileStream.Write's (API outbound). Some of our data heavy pages hit an excessive number of blocks on the way out with so much data (that's a different issue 🙃)

Are you able to try the System.Text.Json-based serializer? If not, what missing features/issues block your migration?

If you can't migrate, you could work around this by doing the serialization yourself to memory and then flush that to the response body asynchronously. You'd probably have to build your own JsonResult to do that.

[timgabrhel]

@anurse I did a very brief test of System.Text.Json earlier, and the web <> api communication worked well, but something in my cookie auth pipeline was failing. I will investigate further.

I'm also investigating response compression. In the real scenario that inspired this post, my 60KB was gzipped to 9KB. This is certainly beneficial for other reasons, but I will check out System.Text.Json first.

[pranavkm]

@Tratcher would it be worthwhile following up with the runtime team if you suspect something is afoot with the way they do sync-writes?

[anurse]

I did a very brief test of System.Text.Json earlier, and the web <> api communication worked well, but something in my cookie auth pipeline was failing. I will investigate further.

I'd be very surprised if System.Text.Json affected that, but I'd be interested in anything you find out!

[Tratcher]

@Tratcher would it be worthwhile following up with the runtime team if you suspect something is afoot with the way they do sync-writes?

It looks very deliberate on their part, it's just surprising. We'll have to re-think how we use FileStream.

[davidfowl]

@stephentoub for ideas/advice. For context, for our JSON.NET formatter (which does synchronous IO) we buffer in memory then to disk over a certain threshold then copy that stream asynchronously to the response body. Turns out marking the FileStream async makes synchornous writes do sync over async. Do you have any idea how we should be using the FileStream here to make this better?

One idea that comes to mind is having 2 file streams, one for writes and one for reads.

PS: It would be good to have a benchmark for a large JSON writes with newtonsoft.

[davidfowl]

@pranavkm Before we fix this we should gather all of the issues with the newtonsoft formatter and put them into an epic. Seems like we have a few (like the one about doing lots of small writes)

[timgabrhel]

@anurse Finally got to debug and it's just a [JsonProperty("xyz")] serialization problem. Upon initial review, we are just doing basic converters & property attributes that have feature parity. The one feature I may be missing is ReferenceLoopHandling. I have this configured in Startup, but I can't recall if I _need_ it off hand.
https://docs.microsoft.com/en-us/dotnet/standard/serialization/system-text-json-migrate-from-newtonsoft-how-to#preserve-object-references-and-handle-loops

This is definitely a medium-term recommendation given the amount of changes to converters and attributes. It's slightly more challenging to fix all references as many 3rd party libraries bring in JSON.NET.

[stephentoub]

It looks very deliberate on their part, it's just surprising. We'll have to re-think how we use FileStream.

On Windows, when you open a file you have choose whether to open it for overlapped I/O or not, and then all operations on the file need to follow-suit. So if you open the file for async, all operations need to be async, and FileStream implements the sync APIs on top of the async ones. The reverse is also true: if you open the file for non-overlapped I/O, then you can't use overlapped, so FileStream implements the async APIs by queueing work items that then do the synchronous IO. (We could probably do better on Unix, where there's no such distinction made when a file is opened. There are a bunch of ways in which I'd like to see FileStream improved; it just keeps getting punted each release.)

[davidfowl]

Yea, that seems fine, I've made a change to adjust our behavior.

[layomia]

The one feature I may be missing is ReferenceLoopHandling

@timgabrhel FWIW, we've added support for preserving object references in .NET 5 https://github.com/dotnet/runtime/pull/655.

[julienGrd]

The one feature I may be missing is ReferenceLoopHandling

@timgabrhel FWIW, we've added support for preserving object references in .NET 5 dotnet/runtime#655.

great news, is this something working now on .net 5 preview ? (im a bit confused because im on .net 5 preview globally but the webassembly dll are still in 3.2, my System.Net.Http.Json dll is on 5.0.0-preview.3.20214.6)

[layomia]

@julienGrd yes, this is included in preview 3. You are using System.Net.Http.Json preview 3 so you should have the bits. You can try the feature by setting JsonSerializerOptions.ReferenceHandling to ReferenceHandling.Preserve. More info at https://github.com/dotnet/runtime/issues/30820#issuecomment-578957043.