Worth considering system.threading.channels?

[dazinator]

I've had good fun using system.threading.channels for producer/consumer of late, and I have seen decent perf metrics. An intro is here: https://devblogs.microsoft.com/dotnet/an-introduction-to-system-threading-channels/ It might be worth considering adopting this, or perhaps not - what do you think?

[dazinator]

One key differentiator:

BlockingCollection involves blocking; there are no task-based APIs to perform work asynchronously. Channels is all about asynchrony; there are no synchronously-blocking APIs.

[dazinator]

One potential nicety with channels, is that the consuming thread can read new items from the channel by awaiting a value task (in a loop) that will complete synchronously when items are available, and will yield the thread when no items are available, rather than block the thread - so the thread can be freed temporarily to do other work if the channel is empty.

This would possibly fit better in a dotnet core IHostedService scenario if the background loop (pump) was started / stopped there.

[nblumhardt]

Hey @dazinator! Thanks for the note. A channels-based implementation would be interesting but I'm not sure how it'd all come out - might be something to try spiking as e.g. Serilog.Sinks.Channels? This sink has a pretty deep dependency on BlockingCollection for backpressure and other options, not sure it could itself be ported to channels, but always room for experimentation and improvement :-)

[murshex]

I think this should still be

Edit: https://github.com/manigandham/serilog-sinks-fastconsole This seems related

[bartelink]

I recently ported some code from BlockingCollection to Channels, and I'm all but sure that all relevant primitives are present, rendering it a pretty-straightforward porting exercise.

As covered above and/or in the article linked previously, the main win it'd offer is that the sink would not permanently lock a thread in the way it does atm via GetConsumingEnumerable. In some exotic setups where there's more than one Async Sink in a process, that might be a significant win.

As Nick says, probably best attacked by forking the current code so people can road test it (though if the same platforms can be be served without crazy dependencies, it may make sense to offer it in a dev version for validation?)

[murshex]

https://github.com/c0nd3v/Serilog.Sinks.Channels

I made my implementation of channels for serilog publicly available. Hope this helps someone!

[nblumhardt]

Awesome, thanks @c0nd3v :+1:

[murshex]

@nblumhardt No problem :) Is there anyway we could put this into official Serilog github?

[nblumhardt]

Hi @c0nd3v; the Serilog org isn't accepting any new sinks; we can link it from the wiki or alternatively, if you reach a point where you think the sink is stable and equivalent to what we currently have here, PRing a changeset to this repo that moves the sink (conditionally?) over to channels would also be welcome. HTH!

[timstokman]

Just adding some data, when I add Async around the console sync:

logConfiguration.WriteTo.Async(l => l.Console());

Instead of:

logConfiguration.WriteTo.Console();

A full 14.8% of the CPU in my application is used by the BlockingCollection in BackgroundWorkerSink. If I remove the Async sink, I don't see serilog anywhere significantly in my profiler trace.

Makes the Async sink unusable performance-wise outside extreme cases for my applications. This trace is for when I set the minimum log level to warning, so that I'm only logging a few lines here and there.

[bartelink]

@timstokman have you measured the perf difference using a Channels based impl of the Async Sink? While the current impl definitely blocks a thread (which involves non-trivial resources for stack and book-keeping, but not intrinsically CPU consumptino), it does sleep during that time, so I'd have a closer look (i.e. there's a difference between showing that 15% of the runtime of the app involves activity in that call stack vs e.g. there actually being 15% CPU consumption). (ultimately, unless you have a lot of actual events going through, I'd be very surprised if the main loop was actually consuming CPU when inactive) Note I'm definitely not suggesting the Sink is perfect and/or that a Channels-based impl can't be more efficient, just that beyond the fact that one less thread will be occupied full-time, it's just trade-offs as usual. Also, its important to note that Async vs not-async can have impacts on app-throughput (even with a Console Sink) - so simply removing it may not be an apples to apples comparison in a real app.

[timstokman]

Unfortunately my profile doesn't say whether something actually consumes CPU, so I dug a bit deeper, and you're right, the lock doesn't actually consume much CPU, it's not a hard loop (some locking algorithms are). I guess I'll need to treat my profiler results with a bit more nuance. The channel package looks like it's a bit more efficient in my case (looking at the trace and final CPU percentage), but also doesn't look it's maintained unfortunately (only two commits two years ago).

Regarding tradeoffs, in my case it's still probably better to remove the async sink. My application is heavily multithreaded and CPU bound in a somewhat resource constrained environment, I need my full thread-pool free, and usually I just run the loglevel at warning to ensure I only get a small amount of logging messages.