Lots of tasks awaiting on PeriodicBatchingSink.TryWaitToReadAsync

[tbolon]

I am currently debugging a memory dump where we have a lot of .NET Threads created and not destroyed. This was observed after having upgraded Serilog.Sinks.Seq to 7.0.1 which upgraded PeriodicBatching to 4.1.0.

See the thread count increasing during the day:

And here is a dump from the tasks in visual studio:

See the ~200 tasks awaiting in PeriodicBatchingSink.TryWaitToReadAsync

I am first trying to be sure that there are only one instance of the Seq sink before claiming that there is a bug, but I decided to open the isse asap, since I am pretty confident we don't create multiple instances of WriteTo.Seq() when configuring the Logger.

[nblumhardt]

Hi @tbolon, thanks for the heads-up.

I don't think it'll make any difference, but, Serilog.Sinks.Seq 7.0.1 will pull in 4.1.0 of this package and not 4.1.1, as far as I can tell.

What kind of log volume is the app producing, and what's load on the app like, relative to the hardware that's allocated to it?

Also, is this .NET Framework or Core?

Looks like it could be a bug, just trying to narrow down the conditions :-)

[tbolon]

I don't think it'll make any difference, but, Serilog.Sinks.Seq 7.0.1 will pull in 4.1.0 of this package and not 4.1.1, as far as I can tell.

Yes, it's 4.1.0 which fixed the memory leak problem, wrong version in my message.

What kind of log volume is the app producing, and what's load on the app like, relative to the hardware that's allocated to it?

A lot of messages are sent to serilog, but the MinimumLevel(Information) reduces it to a few messages (< 100) per minute. Everything is sent to localhost where a seq instance is configured as a proxy replicated to our central instance.

Also, is this .NET Framework or Core?

.NET Framework 4.8.1

I have identified a problem in the app where the logger could be created multiple times (and overwritten) because it was initialized in the HttpApplication inherited class constructor, and somewhere I forget that multiple instances of the HttpApplication could be created by the runtime.

I need to cleanup this initialization to check that it's not the real cause of the problem and wait for some traces in production.

Sadly, this requires more code move and I am not sure I will be able to quickly move this change into a relevant production tenant.

[nblumhardt]

Thanks for the follow-up. Keen to hear what you find!

Taking a closer look at those parallel stack locations, the .ctor.AnonymousMethod_ ones are:

https://github.com/serilog/serilog-sinks-periodicbatching/blob/dev/src/Serilog.Sinks.PeriodicBatching/Sinks/PeriodicBatching/PeriodicBatchingSink.cs#L136

(Guessing) this is an invisible closure generated behind the scenes to convert the LoopAsync function pointer into a delegate for the Task.Run() method. I'd only expect this location to show up once in the running of the sink, but it's quite common among the tasks listed in the parallel stacks view, so an initialization problem could be the culprit 🤞 ..... :-)

[tbolon]

After some investigation, our supposition was right: the number of tasks was due to the HttpApplication ctor() which is invoked for each new worker thread added to the ASP.NET Webapp. We have moved our log initialization inside the Application_Start method (which is only invoked once) and the problem disappeared.

Sorry for the noise, and thanks for the advices.

[nblumhardt]

Fantastic! Thanks for circling back, @tbolon.

This isn't noise at all; knowing one more person has put this code under the microscope is a good confidence boost for the Serilog 4 release (which I guess I might fire off now... :-)).