Thread starvation on high load with System.Text.Json

[berndku]

Description

After changing the serializer from Newtonsoft to System.Text.Json in a streaming application, where a high number of objects are serialized concurrently, we observe a thread starvation issue.

After a few hours under heavy load the number of native threads in the process increase slowly until ~500, which results in severe throughput degradation of the application. As a consequence we had to switch back to Newtonsoft Json.

A memory dump revealed that most of the threads wait on a critical section, see attached data.

Configuration

• Net Core 3.1, x64
• Windows Server 2016
• Azure D4 VM (8 Cores, 32 GB RAM)

Data

Callstack:
ntdll!NtWaitForAlertByThreadId+14
ntdll!RtlpWaitOnAddressWithTimeout+43
ntdll!RtlpWaitOnAddress+b2
ntdll!RtlpWaitOnCriticalSection+db
ntdll!RtlpEnterCriticalSectionContended+cc
ntdll!RtlEnterCriticalSection+40
coreclr!CEEInfo::reportInliningDecision+51a [f:\workspace_work\1\s\src\vm\jitinterface.cpp @ 8292 + 87] f:\workspace_work\1\s\src\vm\jitinterface.cpp @ 8292 + 87
clrjit!InlineResult::Report+de [f:\workspace_work\1\s\src\jit\inline.cpp @ 749] f:\workspace_work\1\s\src\jit\inline.cpp @ 749
clrjit!Compiler::fgInline+3b0 [f:\workspace_work\1\s\src\jit\flowgraph.cpp @ 22013 + a] f:\workspace_work\1\s\src\jit\flowgraph.cpp @ 22013 + a
clrjit!Compiler::fgMorph+131 [f:\workspace_work\1\s\src\jit\morph.cpp @ 17025] f:\workspace_work\1\s\src\jit\morph.cpp @ 17025
clrjit!Compiler::compCompile+4f2 [f:\workspace_work\1\s\src\jit\compiler.cpp @ 4483] f:\workspace_work\1\s\src\jit\compiler.cpp @ 4483
clrjit!Compiler::compCompileHelper+296 [f:\workspace_work\1\s\src\jit\compiler.cpp @ 6035] f:\workspace_work\1\s\src\jit\compiler.cpp @ 6035
clrjit!Compiler::compCompile+21d [f:\workspace_work\1\s\src\jit\compiler.cpp @ 5367 + 20] f:\workspace_work\1\s\src\jit\compiler.cpp @ 5367 + 20
clrjit!jitNativeCode+273 [f:\workspace_work\1\s\src\jit\compiler.cpp @ 6663 + 53] f:\workspace_work\1\s\src\jit\compiler.cpp @ 6663 + 53
clrjit!CILJit::compileMethod+92 [f:\workspace_work\1\s\src\jit\ee_il_dll.cpp @ 319] f:\workspace_work\1\s\src\jit\ee_il_dll.cpp @ 319
coreclr!invokeCompileMethod+dd [f:\workspace_work\1\s\src\vm\jitinterface.cpp @ 12496 + 6e] f:\workspace_work\1\s\src\vm\jitinterface.cpp @ 12496 + 6e
coreclr!CallCompileMethodWithSEHWrapper+50 [f:\workspace_work\1\s\src\vm\jitinterface.cpp @ 12550 + 25] f:\workspace_work\1\s\src\vm\jitinterface.cpp @ 12550 + 25
coreclr!UnsafeJitFunction+96b [f:\workspace_work\1\s\src\vm\jitinterface.cpp @ 13039 + 6a] f:\workspace_work\1\s\src\vm\jitinterface.cpp @ 13039 + 6a
coreclr!MethodDesc::JitCompileCodeLocked+2f9 [f:\workspace_work\1\s\src\vm\prestub.cpp @ 965 + 5c] f:\workspace_work\1\s\src\vm\prestub.cpp @ 965 + 5c
coreclr!MethodDesc::JitCompileCodeLockedEventWrapper+32d [f:\workspace_work\1\s\src\vm\prestub.cpp @ 827 + 18] f:\workspace_work\1\s\src\vm\prestub.cpp @ 827 + 18
coreclr!MethodDesc::JitCompileCode+15f [f:\workspace_work\1\s\src\vm\prestub.cpp @ 773 + f] f:\workspace_work\1\s\src\vm\prestub.cpp @ 773 + f
coreclr!MethodDesc::PrepareILBasedCode+185 [f:\workspace_work\1\s\src\vm\prestub.cpp @ 432 + b] f:\workspace_work\1\s\src\vm\prestub.cpp @ 432 + b
coreclr!MethodDesc::PrepareInitialCode+40 [f:\workspace_work\1\s\src\vm\prestub.cpp @ 321] f:\workspace_work\1\s\src\vm\prestub.cpp @ 321
coreclr!MethodDesc::DoPrestub+44b [f:\workspace_work\1\s\src\vm\prestub.cpp @ 2025 + 8] f:\workspace_work\1\s\src\vm\prestub.cpp @ 2025 + 8
coreclr!PreStubWorker+24c [f:\workspace_work\1\s\src\vm\prestub.cpp @ 1781 + d] f:\workspace_work\1\s\src\vm\prestub.cpp @ 1781 + d
coreclr!ThePreStub+55 [F:\workspace_work\1\s\src\vm\amd64\ThePreStubAMD64.asm @ 22] F:\workspace_work\1\s\src\vm\amd64\ThePreStubAMD64.asm @ 22
System.Text.Json.JsonPropertyInfoCommon4[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].GetValueAsObject(System.Object)+23 0x000001a7bb9197a8
0x000001a7bb9197a8 0x000001a77e92afc8
0x0000006e0a6bd070 0x000001a7820ab460
System.Text.Json.JsonSerializer.HandleEnumerable(System.Text.Json.JsonClassInfo, System.Text.Json.JsonSerializerOptions, System.Text.Json.Utf8JsonWriter, System.Text.Json.WriteStack ByRef)+33
0x0000006e0a6bd030 0x000001a77fa9e6f8
System.Text.Json.JsonSerializer.Write(System.Text.Json.Utf8JsonWriter, Int32, Int32, System.Text.Json.JsonSerializerOptions, System.Text.Json.WriteStack ByRef)+33c
System.Text.Json.JsonSerializer.WriteCore(System.Text.Json.Utf8JsonWriter, System.Object, System.Type, System.Text.Json.JsonSerializerOptions)+b9
System.Text.Json.JsonSerializer.WriteCore(System.Text.Json.PooledByteBufferWriter, System.Object, System.Type, System.Text.Json.JsonSerializerOptions)+86
System.Text.Json.JsonSerializer.WriteCoreBytes(System.Object, System.Type, System.Text.Json.JsonSerializerOptions)+7a

Analysis

Serialization code in application looks like this:

  var options = new JsonSerializerOptions
  {
        Converters = { new CustomJsonStringEnumConverter() },
        IgnoreNullValues = true
   };
return System.Text.Json.JsonSerializer.SerializeToUtf8Bytes<Message>(toSerialize, options);

The code for CustomJsonStringEnumConverter can be found here.

[stephentoub]

Your repro is creating a new options instance each time. Does the problem go away if you instead cache and reuse a single instance of it?

[berndku]

Thanks, after changing the options to a single instance the issue could not be observed any longer during a 2 hour load test.

[stephentoub]

@steveharter, can we handle this better? While we encourage folks to cache, not doing so leads to really bad perf with all the code generation and jit'ing.

[jkotas]

Add analyzer for this?

[scalablecory]

This is HttpClient all over again, I would find a better solution than an analyzer.

[steveharter]

Add analyzer for this?

That would be good.

@steveharter, can we handle this better? While we encourage folks to cache, not doing so leads to really bad perf with all the code generation and jit'ing.

We should doc this better. Changing to doc issue.

If just the default options are used (no explicit options instance passed in) then the default options instance is automatically cached. It is also cached under ASP.NET. Also we plan on making it easier in 6.0 to specify the default options as well, so one can use the serialization APIs that don't take the options instance but still specify a custom options instance and its location.

Also, the stack appears to enter the critical section on calling the "getter" delegate. This is likely trying to JIT the IL that the serializer emitted to call the getter. With the code-gen effort that will release for 6.0, there will be no IL generated for the getter so the code for the POCOs are generated ahead-of-time, that should avoid the critical section plus the startup time will significantly improve. However, even with that, there is metadata that needs to be built up and cached, so caching of the options is still recommended even with code-gen.

[steveharter]

Also dup of #38982