Nasty exceptions in Timer scope

Björn Weström — Tue, 16 Mar 2021 22:37:00 +0000

TL; DR

Unhandled exceptions occurring in Timer scope in a .Net Core application will crash the application without any logs or any graceful shutdown. Make sure to catch any exceptions in Timer scope and handle them without rethrowing.

Timer scope

With Timer scope I refer to any method that is set to execute when a Timer fires. Typically the code would look something like this:

var timer = new System.Threading.Timer(MethodInTimerScope);
...
private void MethodInTimerScope(object state)
{
    // Perform Timer based task
}

Exceptions in Timer scope

When an unhandled exception occurs within request scope (anything initiated from an incoming HTTP request through a Controller), it will be caught by a default exception handler. The exception will be logged and the request will receive a 500 response.
Similarly, when an exception occurs during application startup, shutdown, or inside a Background task (such as a BackgroundService), it is nicely logged and handled appropriately.

However, when an unhandled exception occurs within Timer scope, it seems this scope is out of reach for the regular catch-alls of exceptions. It causes the whole application to crash immediately, without leaving any clues behind in the logs.

Avoiding hard crashes from Timer scope exceptions

The key to avoiding this situation is to catch any exceptions within the Timer scope to log and handle them. If the exceptions are so severe that the application should shut down, a graceful shutdown operation can be initiated using the IHostApplicationLifetime.StopApplication() method.

Disclaimer

This applies for .Net Core 3.1 and above. Has been tested on Windows with IIS hosting, and on OS X from Visual Studio.

Keeping System.Text.Json lean

Björn Weström — Wed, 09 Sep 2020 21:25:20 +0000

TL; DR

Serialization with System.Text.Json has an unexpected performance penalty when used with options, such as setting the PropertyNamingPolicy to CamelCase. For small objects, serialization is ~200x slower! To avoid this issue, store the options object in a class member and pass that member to JsonSerializer.Serialize.

UPDATE 2020-09-15

I posted an issue about this on Github, and the dotnet maintainers were quick to respond. This behavior is understood and the recommendation is to use a static (or shared) options object to avoid it. The root cause is:

The serializer undergoes a warm-up phase during the first (de)serialization of every type in the object graph when a new options instance is passed to it. This warm-up includes creating a cache of metadata it needs to perform (de)serialization: funcs to property getters, setters, ctor arguments, specified attributes etc. This metadata caches is stored in the options instance. This process is not cheap, and it is recommended to cache options instances for reuse on subsequent calls to the serializer to avoid unnecessarily undergoing the warm-up repeatedly

There are related issues #40072 and #38982.

How it all began

I was working on upgrading several of our applications from .Net Core 2.1 to .Net Core 3.1. One significant change was the switch from Newtonsoft.Json to System.Text.Json for serialization. Since the System.Text.Json package has been positively received due to the improved performance, I decided to give it a go.

Making the transition wasn't particularly difficult, since we didn't use any advanced features of Newtonsoft.Json. The main snag was handling reference loops, which Newtonsoft.Json conveniently could sort out for you, but even that has been fixed with a few well placed [JsonIgnore] attributes.

To keep the transition as smooth as possible, I decided to configure System.Text.Json to use camelCase for property names. Many of the APIs has a angular based frontend as its main consumer, and it just didn't make sense to me to start sending PascalCase JSON. (This is also the default configuration for the serializer built into .Net Core MVC)

I was just finishing up a Web API, and everything looked promising. But there was a particular operation that seemed unusually slow. The operation fetches a list of objects, in my tests I was retrieving 80 objects. Stepping through the code in the debugger, I found that the Automapper conversion from entity model to contract model took ~150 ms! The objects are simple enough, about 10 properties. However, they include a Hash property, which is calculated from a serialization of the entity object.

In a trial and error attempt to find the root cause of the delay, I removed the options parameter to the JsonSerializer.Serialize call. And sure enough, the same Automapper conversion now took only 3 ms! I found it hard to believe that using camelCase would make the serialization orders of magnitude slower - looking at available benchmarks online the performance impact should be hardly noticeable. This piqued my interest and I decided to do some benchmarks of my own!

Different methods of passing the options

Some more trial and error revealed that putting the JsonSerializationOptions in a static class member and passing that member to JsonSerialize.Serialize reached similar performance as without passing any options at all. Hence I put together this benchmark with different methods of passing in options, with and without camelCase, and comparing that to using no options.

Benchmark

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.17763.1397 (1809/October2018Update/Redstone5)
Intel Core i7-8700 CPU 3.20GHz (Coffee Lake), 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=3.1.101
  [Host]     : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT
  DefaultJob : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT

Method	Mean	Error	StdDev
Serialize	4.479 μs	0.0123 μs	0.0103 μs
Serialize_InlineOptions_Default	839.179 μs	7.5675 μs	7.0786 μs
Serialize_InlineOptions_CamelCase	858.304 μs	11.1388 μs	9.3014 μs
Serialize_LocalOptions_Default	842.628 μs	4.0955 μs	3.4199 μs
Serialize_LocalOptions_CamelCase	839.716 μs	6.8355 μs	6.3939 μs
Serialize_StaticMemberOptions_Default	4.464 μs	0.0144 μs	0.0120 μs
Serialize_StaticMemberOptions_CamelCase	4.428 μs	0.0588 μs	0.0699 μs
Serialize_MemberOptions_Default	4.499 μs	0.0311 μs	0.0259 μs
Serialize_MemberOptions_CamelCase	4.578 μs	0.0228 μs	0.0202 μs

The difference between creating the options on the fly (inline or locally) and providing them from a class member is daunting! It adds nearly 1 ms to the serialization time. Since creating the options on the fly means creating them for each call to JsonSerializer.Serialize it was expected that these should perform slightly worse. Could the instantiation of the options object explain this difference? Lets find out!

Benchmark code

Type of function call

The middle part of the name of each benchmark identifies the type of call to JsonSerializer.Serialize.

InlineOptions - Options are instantiated inline

JsonSerializer.Serialize(myObject, new JsonSerializerOptions());

LocalOptions - Options are instantiated as a local variable

var options = new JsonSerializerOptions();
JsonSerializer.Serialize(myObject, options);

StaticMemberOptions - Options are instantiated as a static class member

private static JsonSerializerOptions jsonStaticDefaultOptions = new JsonSerializerOptions();
...
JsonSerializer.Serialize(myObject, jsonStaticDefaultOptions);

MemberOption - Options are instantiated as a class member

private JsonSerializerOptions jsonDefaultOptions;
...
this.jsonDefaultOptions = new JsonSerializerOptions();
...
JsonSerializer.Serialize(jsonDefaultOptions);

Type of options

The suffix of the name of each benchmark identifies the type of options used.

Default - Default options

new JsonSerializerOptions();

CamelCase - Options set for camelCase

new JsonSerializerOptions() { PropertyNamingPolicy = JsonNamingPolicy.CamelCase };

Options construction

If creating the options when they are needed slows down the serialization, could it be that the options object requires some heavy lifting to be instantiated? Unlikely but worth a benchmark.

Benchmark

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.17763.1397 (1809/October2018Update/Redstone5)
Intel Core i7-8700 CPU 3.20GHz (Coffee Lake), 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=3.1.101
  [Host]     : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT
  DefaultJob : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT

Method	Mean	Error	StdDev
NoOp	0.0163 ns	0.0014 ns	0.0011 ns
CreateMyObject	4.7044 ns	0.0101 ns	0.0089 ns
CreateOptions	337.1717 ns	3.2470 ns	2.5351 ns
CreateOptions_Camel	341.6551 ns	3.1801 ns	2.8190 ns

The results show that the options object is indeed a rather large one (compare to the test object MyObject used for the serialization). But it still takes only a fraction of a μs to instantiate - this cannot explain the large performance gap in the previous benchmark.

Benchmark code

NoOp is simply an empty function, added for reference
CreateMyObject instantiates an object of the simple test class MyObject
CreateOptions / CreateOptions_Camel instantiates a JsonSerializerOptions object in a similar way as in the previous benchmark.

Serialization of a list

In the previous benchmarks a really small object was serialized. How does this performance gap scale if we serialize something larger, like a list of the small objects?

Benchmark

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.17763.1397 (1809/October2018Update/Redstone5)
Intel Core i7-8700 CPU 3.20GHz (Coffee Lake), 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=3.1.101
  [Host]     : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT
  DefaultJob : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT

Method	N	Mean	Error	StdDev
Serialize	10	45.92 μs	0.913 μs	1.250 μs
Serialize_InlineOptions_Default	10	944.99 μs	9.046 μs	8.019 μs
Serialize_InlineOptions_CamelCase	10	938.90 μs	17.853 μs	19.844 μs
Serialize_StaticOptions_Default	10	43.30 μs	0.106 μs	0.089 μs
Serialize_StaticOptions_CamelCase	10	44.24 μs	0.040 μs	0.037 μs
Serialize	100	528.36 μs	1.481 μs	1.313 μs
Serialize_InlineOptions_Default	100	1,429.01 μs	10.067 μs	8.924 μs
Serialize_InlineOptions_CamelCase	100	1,434.56 μs	4.027 μs	3.570 μs
Serialize_StaticOptions_Default	100	510.18 μs	2.280 μs	2.133 μs
Serialize_StaticOptions_CamelCase	100	517.13 μs	2.558 μs	2.268 μs
Serialize	1000	4,852.29 μs	25.266 μs	23.634 μs
Serialize_InlineOptions_Default	1000	5,727.67 μs	81.384 μs	72.145 μs
Serialize_InlineOptions_CamelCase	1000	5,713.51 μs	84.481 μs	70.545 μs
Serialize_StaticOptions_Default	1000	4,829.04 μs	25.773 μs	24.108 μs
Serialize_StaticOptions_CamelCase	1000	4,939.82 μs	22.851 μs	21.374 μs

Where N is the number of objects in the list. Ok, so it seems that the on the fly options add about 900 μs to the serialization regardless of object size. That's good news at least.

Serialization in a loop

How about serializing those objects one by one?

Benchmark

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.17763.1397 (1809/October2018Update/Redstone5)
Intel Core i7-8700 CPU 3.20GHz (Coffee Lake), 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=3.1.101
  [Host]     : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT
  DefaultJob : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT

Method	N	Mean	Error	StdDev
Serialize	10	44.59 μs	0.038 μs	0.033 μs
Serialize_InlineOptions_Default	10	8,364.56 μs	80.834 μs	75.612 μs
Serialize_InlineOptions_CamelCase	10	8,438.08 μs	57.459 μs	53.747 μs
Serialize_StaticOptions_Default	10	45.02 μs	0.142 μs	0.133 μs
Serialize_StaticOptions_CamelCase	10	44.94 μs	0.126 μs	0.112 μs
Serialize	100	463.57 μs	1.972 μs	1.748 μs
Serialize_InlineOptions_Default	100	84,244.24 μs	594.933 μs	556.501 μs
Serialize_InlineOptions_CamelCase	100	88,661.04 μs	1,743.013 μs	1,711.872 μs
Serialize_StaticOptions_Default	100	503.88 μs	9.914 μs	14.532 μs
Serialize_StaticOptions_CamelCase	100	504.59 μs	10.077 μs	20.810 μs
Serialize	1000	5,070.30 μs	101.357 μs	224.600 μs
Serialize_InlineOptions_Default	1000	898,815.78 μs	16,983.724 μs	17,441.035 μs
Serialize_InlineOptions_CamelCase	1000	900,245.68 μs	17,592.917 μs	25,231.237 μs
Serialize_StaticOptions_Default	1000	4,902.03 μs	74.758 μs	58.366 μs
Serialize_StaticOptions_CamelCase	1000	5,213.93 μs	103.911 μs	282.699 μs

Where N is the number of objects to serialize. All objects are created before the benchmark, then they are serialized one by one (one call to JsonSerializer.Serialize per object). This is similar to the results from serialization of the list - on the fly instantiation of options adds 800-900 μs per call.

Alternate overloads

Finally I decided to check if there are other overloads of JsonSerializer.Serialize that would perform better with on the fly options.

Benchmark

BenchmarkDotNet=v0.12.1, OS=Windows 10.0.17763.1397 (1809/October2018Update/Redstone5)
Intel Core i7-8700 CPU 3.20GHz (Coffee Lake), 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=3.1.101
  [Host]     : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT
  DefaultJob : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT

Method	Mean	Error	StdDev
Serialize	4.470 μs	0.0237 μs	0.0185 μs
Serialize_InlineOptions_Default	848.252 μs	5.4895 μs	5.1349 μs
Serialize_AltInlineOptions_Default	836.154 μs	3.9665 μs	3.5162 μs
Serialize_Alt2InlineOptions_Default	846.886 μs	8.8031 μs	8.2345 μs

The results are clear, all overloads for passing options to JsonSerializer.Serialize shares the same weakness.

Benchmark code

InlineOptions - This is the method used in the previous benchmarks
AltInlineOptions - Overload that accepts a type argument

JsonSerializer.Serialize(myObject, typeof(MyObject), new JsonSerializerOptions());

Alt2InlineOptions - Generic overload that accepts a type argument

JsonSerializer.Serialize<MyObject>(myObject, new JsonSerializerOptions());

Discussion

Some will claim that 900 μs of additional delay for serialization isn't a big deal. While this is correct in some scenarios, I think that anyone striving to keep their request pipeline lean won't agree. In our applications we are approaching 10 ms response time for the less complex requests (not a record for sure, but this includes a lot of enterprise stuff like logging, audit logging, AD authorization). Adding 900 μs makes or apps 9% slower!

Secondly, I would presume that there are many others who perform multiple serializations within a single request. In our case, we do this for each item in a list to calculate a hash value for each item. When returning 100 items, you are suddenly accumulating ~100 ms of delay, which is pretty bad - in particular when it can be easily avoided.

What is worse is that the official documentation is full of examples that instantiate the options on the fly! Example of how to use camelCase. I agree fully that it makes the example code much more compact when presented this way, but there are no notes about the performance impact. A senior developer would probably move the options to a class member if that member is used multiple times within a class, but when the options object is used only once it makes the code more clean to simply do it inline.

The burning question is why does this performance gap exist? If instantiating objects inline and passing them to functions is really this terrible, we should avoid that everywhere. But that cannot be true?
My guess is that the options object is used quite heavily when initiating the serialization. We saw from the object creation benchmark that the options object is quite large, hence there are plenty of options that must be processed. If accessing properties of a class member is slightly faster than accessing properties of a locally scoped object, then this difference would accumulate.

Still I think it is a mystery that the difference is so huge. How can serializing a small object be 200x slower due to how options are passed?

Source code

The full source used in the benchmarks can be found here.

Tools

All benchmarks are performed using BenchmarkDotNet.
Test data for serialization is generated using AutoBogus.

DEV Community: Björn Weström

Nasty exceptions in Timer scope

TL; DR

Timer scope

Exceptions in Timer scope

Avoiding hard crashes from Timer scope exceptions

Disclaimer

Keeping System.Text.Json lean

TL; DR

UPDATE 2020-09-15

How it all began

Different methods of passing the options

Benchmark

Benchmark code

Type of function call

Type of options

Options construction

Benchmark

Benchmark code

Serialization of a list

Benchmark

Serialization in a loop

Benchmark

Alternate overloads

Benchmark

Benchmark code

Discussion

Source code

Tools