6

As a step in switching from NLog to Serilog, I want to redirect the standard wiring underlying standard invocations of NLog's LogManager.GetLogger(name) to Bridge any code logging to NLog to forward immediately to the ambient Serilog Log.Logger - i.e. I want to just one piece of config that simply forwards the message, without buffering as Log4net.Appender.Serilog does for Log4net.

Can anyone concoct or point me to a canonical snippet that does this correctly and efficiently please? Requirements I can think of:

  • Maintain the level, i.e. nlog.Warn should be equivalent to serilog.Warning
  • It's ok for Serilog to generate the time anew
  • materializing the message in the appender - i.e., there's no need to maintain any properties associated with the 'message' (the LogEvent in Serilog terms)
  • no buffering
  • I don't need any other NLog Target to be used (i.e. mutating/deleting the message would be fine)
Ruben Bartelink
  • 59,778
  • 26
  • 187
  • 249
  • Curious why you want to get away from NLog. Is something missing in NLog? – Rolf Kristensen Apr 05 '18 at 21:57
  • The way the Async wrapper coordinates among threads caused issues, also I had a leak related to the same mechanism. The Serilog sinks are very clean and you'd trust what they do by reading them. There's also a good gitter community. It also gave me a 30% increase in capacity under load to switch in my context – Ruben Bartelink Apr 06 '18 at 15:54
  • Do you have an example config (or example code) that shows this bad behavior in NLog ? (Doesn't have to compile, but just give an idea how you are using NLog). My own testing of NLog and Serilog gives me a different picture. – Rolf Kristensen Apr 06 '18 at 16:51
  • Never boiled it down properly but we were on a ~1.5yo version of NLog's async wrapper and the newer one looked even scarier to me. Both leaked objects relating to the Async transition. The NLog config was all programmatic. In more recent times, I looked at a mem dump that showed 60+ threads all in an async write action (all hitting same file target). My scanning of the NLog code suggested there isnt a simple passing of the info over to a writer thread but instead a complex arrangements of awaiting the handoff (which facilitates the blocking/ grow behaviors and doubtless other power features) – Ruben Bartelink Apr 06 '18 at 19:22
  • My testing consisted of back to back runs attempting to feed up to 600 rps into a local web server doing interesting work requiring parallelism internally (reading/writing EventStore) with a minthreads settings of default, 100 and 768. Throughput under load (not saturated, but high) went from ~100 to ~130 krps in 10 mins - it writes ~10mbps across about 4 files, with probably 10-15 hits per transaction. My serilog config set the sinks to (wrapped in async) buffer and roll and dump once per second. (the nlog equivalents where half async, half sync without any specific buffering config) – Ruben Bartelink Apr 06 '18 at 19:25
  • To be clear: I did not set out to do back to back comparisons or benchmark things - the actual issue was behaviour of the nlog async wrapper when saturated and/or file writing gets blocked/interruped (and formerly the leaking behavior - I can't say 100% its actually the fault of NLog, but removing the NLog wrapper and writing sync fixed the problem and took it off the agenda) – Ruben Bartelink Apr 06 '18 at 19:32
  • Sounds like the same problems I was having, that caused me to file several pullrequests that was included in NLog 4.4.2 (With a hidden feature that AsyncWrapper timeToSleepBetweenBatches=0 would give a very nice performance boost). I find that Serilog is also having concurrency issues in its message template cache. Think more performance can be squeezed out of NLog by optimizing the layout logic for concurrency and using ConcurrentQueue in AsyncWrapper on NetCore2 and Net472. What version of NLog were you using? – Rolf Kristensen Apr 06 '18 at 20:39
  • It was using a relatively old version with webapi+katana 5.2.3+3.0 and have not used a profiler. As long as writing is batched, 10ish log entries (even if one is massive, as it was in my case) should not be interesting compared to an out of process hop. Regarding seriolog concurrency issues, my load test was not terribly mixed in nature so there could be lurking fun. I dont think there's any reason why NLog and/or Serilog can't steal sink impl techniques from each other and/or achieve similar perf, but it does seem the Async scheme in NLog is fairly deep baked - it is also more powerful. – Ruben Bartelink Apr 06 '18 at 21:36
  • You're obviously way deeper in, and there are always many levels to understanding/being able to grok a codebase than what it scans like before you try to do something. However my sense is Serilog has easier to grok and simpler schemes wrt how sinks and their buffering compose. I'll have the real answer for you in about 6 months ;) – Ruben Bartelink Apr 06 '18 at 21:42
  • @RolfKristensen NuGet version I was/am testing with is 4.4.12 [from 20170808]. The leak first presented with a version which was ~1y older – Ruben Bartelink Apr 07 '18 at 07:30
  • If you can post an example config (and maybe code) at https://github.com/NLog/NLog/issues/new then I would be interested. – Rolf Kristensen Apr 07 '18 at 08:06
  • @RolfKristensen Unfortunately, moving it to sync solved the leak at the time and there are way too many moving parts for me to generate an isolated repro. It is _not_ clear that there necessarily is a specific leak or bug in NLog, although there 100% was a leak in our system which went away by removing the async. We continued to use the async wrapper in other contexts for some time without leaks (aside from the queueing effect under load) for a long time after. Now I'm using Serilog. Please treat above as unvalidated hearsay - I have not even looked at the Concurrency Visualizer view after all – Ruben Bartelink Apr 07 '18 at 09:05
  • Made a comparison of Serilog.Async 1.3.0 (blockWhenFull=true) and NLog 4.5.5 (overflowAction=Block) with 4 threads to a single file with default Serilog JsonFormatter and similar NLog JsonLayout. Serilog handled 60.000 msgs/sec while NLog handled 105.000 msgs/sec and used 5 time less CPU-time and less allocations. – Rolf Kristensen May 26 '18 at 11:03
  • @rolfkristensen I was/am using `RenderedCompactJsonformatter` (cheaper; see benchmarks in https://github.com/serilog/serilog-formatting-compact) and hundreds of threads, also NLog < 4.5. Another key thing is that I do periodic batching of 1s on the file sink which can help a lot (though its behind async so should not matter too much). Less allocations from NLog is possible but also having no pauses/p99 effects is also important. If you can post a benchmark.net repo I'd be happy to have a look as I'm definitely seeing throughput on in-app benchmarks. I'm personally only interested in drop mode. – Ruben Bartelink May 27 '18 at 10:57
  • My performance test shows that RenderedCompactJsonformatter allocates twice the memory as Serilog JsonFormatter, and both are same speed when 4 threads logging to the same file. But CompactJsonFormatter is 30 pct faster and allocates 50 pct less than Serilog JsonFormatter. But when adding Serilog Async-wrapper then performance becomes 100 pct slower, while NLog-Async becomes 50 pct faster. Serilog CompactJsonFormatter without Async is a little faster than NLog. When using drop-mode then NLog wins because it discards 80 pct and Serilog discards 50 pct :) – Rolf Kristensen May 27 '18 at 18:02
  • Now see that both Serilog JsonFormatter and CompactJsonFormatter doesn't render the log-message but just outputs the input-template. NLog performs the same whether it has to output log-message or input-template. – Rolf Kristensen May 27 '18 at 20:29
  • @RolfKristensen It's all trade-offs; I'm referring to the _Rendered_ version; I believe (based on reading the source of NLog about a year ago) that the perf diff is based on how it hands to the background thread. I don't doubt that NLog can beat it in a variety of circumstances, but it all depends on the exact topology. Serilog definitely has significant scope to remove allocations. Regarding 4 threads writing to file, that's not my test (and there are ways of marshalling it efficiently) - again, if you have a test repo, I'd be happy to have a look. Def have zero interest in dropping events;) – Ruben Bartelink May 27 '18 at 21:45
  • Have just made some minor modifications to exercise Serilog: https://github.com/NLog/NLog-Performance-tests/tree/master/NLogPerformance – Rolf Kristensen May 27 '18 at 21:56
  • @rolfkristensen hm, there's a lot in there; in order to meaningfully compare, I'd be looking to have a test which logs from a variable number of threads testing various logger configurations, and let benchmark.net do the comparisons in order to remove a lot of opportunities for variation due to issues of methodology. I thought I saw someone had done such a comparison. For Serilog, there are definitely multiple ways to rig things, and showing exactly how the config looks is critical. – Ruben Bartelink May 27 '18 at 22:36
  • I have no reason to doubt you, and am not questioning you, but a proper rig and iterative to/fro to ensure comparison is of something meaningful that is doing something representative using the best approaches possible per logger is critical to the exercise. This is a non-trivial undertaking though; my intention neither to goad you into anything or chuck loads of FUD, just to caution against us or any onlookers trying to conclude anything from this. I am testing my app in Katana from ~300 client threads and seeing differences due to contention impacts, you are doing something different. – Ruben Bartelink May 27 '18 at 22:40
  • I'm guessing you don't have 300 cores, so maybe "only" 48 threads are actively logging at the same time depending on your hardware. I sadly don't have such hardware on my home computer :) – Rolf Kristensen May 27 '18 at 22:43
  • I have a 2015 MacBook with Parallels and about 10G allocated to the VM; I generate all the load locally (which is debatable too), but I'm using a pretty battle tested (but homespun) load test rig. My only point is that the specifics of how one wires a logging configuration matter a lot on all loggers - there are differing strengths of each logger, and it's very easy to configure one suboptimally and/or set up a test which is very far away from the sweet spot of the use case something is optimising for. – Ruben Bartelink May 27 '18 at 22:54
  • I was using a version of NLog that was 1.5yo and am writing to 4+ logs and the problem observed in prod was when lots of threads were in play - I understand exactly what Serilog is doing and why it might be efficient given how I am using it. Its entirely possible that the problem was solvable with NLog; I'm not trying to claim that everyone must move to Serilog because the perf is different class. Both are top class loggers with a huge amount of features and maturity and for most normal usage the variance in perf will never show up in any perf trace or load test result - lets leave it lie ;) – Ruben Bartelink May 27 '18 at 22:58
  • 1
    Yes it is very difficult to setup a performance tests that fits all scenarios. Which you can also see from the single NLog benchmark project. Many different scenario parameters can be tweaked. And many different NLog-configurations are included for testing. Low memory allocation is a very important requirement in my world. So yes lets leave it lie :) – Rolf Kristensen May 27 '18 at 23:05

1 Answers1

10

I think the best option is indeed a custom NLog target. Something like this: (C#)

using NLog;
using NLog.Targets;
using Serilog;
using Serilog.Events;

namespace MyNamespace
{
    [Target("SerilogTarget")]
    public sealed class SerilogTarget : TargetWithLayout
    {
        protected override void Write(LogEventInfo logEvent)
        {
            var log = Log.ForContext(Serilog.Core.Constants.SourceContextPropertyName, logEvent.LoggerName);
            var logEventLevel = ConvertLevel(logEvent.Level);
            if ((logEvent.Parameters?.Length ?? 0) == 0)
            {
                // NLog treats a single string as a verbatim string; Serilog treats it as a String.Format format and hence collapses doubled braces
                // This is the most direct way to emit this without it being re-processed by Serilog (via @nblumhardt)
                var template = new Serilog.Events.MessageTemplate(new[] { new Serilog.Parsing.TextToken(logEvent.FormattedMessage) });
                log.Write(new Serilog.Events.LogEvent(DateTimeOffset.Now, logEventLevel, logEvent.Exception, template, Enumerable.Empty<Serilog.Events.LogEventProperty>()));
            }
            else
                // Risk: tunneling an NLog format and assuming it will Just Work as a Serilog format
#pragma warning disable Serilog004 // Constant MessageTemplate verifier
                log.Write(logEventLevel, logEvent.Exception, logEvent.Message, logEvent.Parameters);
#pragma warning restore Serilog004
        }

        static Serilog.Events.LogEventLevel ConvertLevel(LogLevel logEventLevel)
        {
            if (logEventLevel == LogLevel.Info)
                return Serilog.Events.LogEventLevel.Information;
            else if (logEventLevel == LogLevel.Trace)
                return Serilog.Events.LogEventLevel.Verbose;
            else if (logEventLevel == LogLevel.Debug)
                return Serilog.Events.LogEventLevel.Debug;
            else if (logEventLevel == LogLevel.Warn)
                return Serilog.Events.LogEventLevel.Warning;
            else if (logEventLevel == LogLevel.Error)
                return Serilog.Events.LogEventLevel.Error;
            return Serilog.Events.LogEventLevel.Fatal;
        }
    }
}

register it in your main() or app_start:

// Register so it can be used by config file parsing etc
Target.Register<MyNamespace.SerilogTarget>("SerilogTarget"); 

Before any logging takes place, the Target needs to be wired in so LogManager.GetLogger() can actually trigger a call to SerilogTarget.Write

    public static void ReplaceAllNLogTargetsWithSingleSerilogForwarder()
    {
        // sic: blindly overwrite the forwarding rules every time
        var target = new SerilogTarget();
        var cfg = new NLog.Config.LoggingConfiguration();
        cfg.AddTarget(nameof(SerilogTarget), target);
        cfg.LoggingRules.Add(new NLog.Config.LoggingRule("*", LogLevel.Trace, target));
        // NB assignment must happen last; rules get ingested upon assignment
        LogManager.Configuration = cfg;
    }

See also: https://github.com/nlog/nlog/wiki/How-to-write-a-custom-target

the optimal way to do this without inducing any avoidable perf impact etc.

This is the optimal way in NLog and has no performance impact on the NLog's site.

what does the TargetAttribute buy me ?

Well in this case you don't need it. The TargetAttribute is used when registering a full assembly, but because we register manually, it's not needed. I think it's best practice, but you could leave it out.

Also what does the Register buy me

This is indeed not needed when using programmatically config. But if you have XML config, you need the register.

I've the habit to write targets that works in all ways (register manually, register by assembly, config from code, config from XML). I could understand that could be confusing.


F# port:

module SerilogHelpers =

    let private mapLevel = function
        | x when x = NLog.LogLevel.Info -> LogEventLevel.Information
        | x when x = NLog.LogLevel.Off || x = NLog.LogLevel.Trace -> LogEventLevel.Verbose
        | x when x = NLog.LogLevel.Debug -> LogEventLevel.Debug
        | x when x = NLog.LogLevel.Warn -> LogEventLevel.Warning
        | x when x = NLog.LogLevel.Error ->  LogEventLevel.Error
        | _ -> LogEventLevel.Fatal

    // via https://stackoverflow.com/a/49639001/11635
    [<NLog.Targets.Target("SerilogTarget")>]
    type SerilogTarget() =
        inherit NLog.Targets.Target()

        static member InitializeAsGlobalTarget() =
            // sic: blindly overwrite the forwarding rules every time
            // necessary as Azure Startup establishes a different config as a bootstrapping step
            // see: LogModule.To.target("rollingFile", create, "*", LogLevel.Trace)
            let cfg, target = NLog.Config.LoggingConfiguration(), SerilogTarget()
            cfg.AddTarget("SerilogTarget", target)
            cfg.LoggingRules.Add(NLog.Config.LoggingRule("*", NLog.LogLevel.Trace, target))
            // NB assignment must happen last; rules get ingested upon assignment
            NLog.LogManager.Configuration <- cfg

        override __.Write(logEvent : NLog.LogEventInfo) =
            let log = Log.ForContext(Serilog.Core.Constants.SourceContextPropertyName, logEvent.LoggerName)
            match logEvent.Parameters with
            | xs when isNull xs || xs.Length = 0 ->
                // NLog treats a single string as a verbatim string; Serilog treats it as a String.Format format and hence collapses doubled braces
                // This is the most direct way to emit this without it being re-processed by Serilog (via @nblumhardt)
                let template = MessageTemplate [| Serilog.Parsing.TextToken(logEvent.FormattedMessage) |]
                log.Write(new LogEvent(DateTimeOffset.Now, mapLevel logEvent.Level, logEvent.Exception, template, Seq.empty<LogEventProperty>))
            | _ ->
                // Risk: tunneling an NLog format and assuming it will Just Work as a Serilog format
                log.Write(mapLevel logEvent.Level, logEvent.Exception, logEvent.Message, logEvent.Parameters)
Julian
  • 33,915
  • 22
  • 119
  • 174
  • Thanks so much - will be deleting [my answer](https://stackoverflow.com/a/49642631/11635) shortly. I can't actually think of a use for my Inner so will use your idea of using `Log` directly. – Ruben Bartelink Apr 04 '18 at 04:24
  • what does the `TargetAttribute` buy me ? Also what does the `Register` buy me ? my planned initialization was to do: `LogManager.Configuration = new NLog.Config.LoggingConfiguration(); LogManager.Configuration.AddTarget(new SerilogTarget());` ... would I be guessing right that the `.Register` would have the same effect but still leave it open for others to attach targets? – Ruben Bartelink Apr 04 '18 at 04:29
  • i've updated my answer. I'm not sure if it's OK for you if I copy the changes from your post. – Julian Apr 04 '18 at 07:58
  • Thank you, and thanks for the politeness; but _please take any and all of it_ - nothing would give me more pleasure than deleting it! My outstanding question is how much of `LogManager.Configuration = new NLog.Config.LoggingConfiguration(); LogManager.Configuration.AddTarget("SerilogTarget",new SerilogTarget()); NLog.Targets.Target.Register("SerilogTarget"); ` I need in my apps startup to wire it in as a default target in the `LogManager`. I'm going to take a liberty and paste it into your post; please feel free to clean as you see fit. – Ruben Bartelink Apr 04 '18 at 10:21
  • I updated my answer - I can't actually make it hit the `Write` method (obviously as I'm missing something obvious!) and am going to park it for a while... – Ruben Bartelink Apr 04 '18 at 12:01
  • You need the register **before** setting logmanager.configuration. – Julian Apr 04 '18 at 17:57
  • Will update post later; I eventually figured out the problem - cant mutate the config after setting it into the logmanager.configuration (IOW `LogManager.Configuration = ` needs to be last after doing full rigging) - the register does not matter. Thanks again for the help! – Ruben Bartelink Apr 04 '18 at 19:42
  • Well you can, but you have to set it again. (Yes its a bit clumsy) – Julian Apr 04 '18 at 19:45
  • Edited the solution as I applied it into your answer. Thanks ;) – Ruben Bartelink Apr 04 '18 at 22:57
  • In the C# code, the static method `ConvertLevel` is missing the case for log events with level "warning" – Tyson Williams Mar 31 '20 at 17:45
  • 1
    Thanks @TysonWilliams, added it – Julian Mar 31 '20 at 17:59