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.

services
    .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.
benaadams/Ben.BlockingDetector#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.

aspnetcore/src/Http/WebUtilities/src/FileBufferingWriteStream.cs

Lines 227 to 233 in 3d034fe

	FileStream = new FileStream(
	tempFileName,
	FileMode.Create,
	FileAccess.ReadWrite,
	FileShare.Delete,
	bufferSize: 1,
	FileOptions.Asynchronous | FileOptions.SequentialScan | FileOptions.DeleteOnClose);

[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 🙃)

[analogrelay]

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?

[analogrelay]

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)