Added Structured events / Message Templates

[snakefoot]

Have merged https://github.com/NLog/NLog.StructuredEvents together with https://github.com/NLog/NLog

And then introduced a TemplateEnumerator, that only allocates the hole-name-strings (when non-positional), and not any MessageTemplate-object (with friends).

Stolen the unit tests from #2126

Have added some extra performance optimizations:

• New StringBuilderPool so MessageTemplate-renderering only allocates the formatted-string (just like string.Format)
• Using new StringBuilderPool other places in the NLog-core-engine to minimize allocations (AppendBuilderCreator)
• Better reuse of already allocated StringBuilder when possible (AppendBuilderCreator)
• Faster encoding of StringBuilder to byte-array. Instead of doing the encoding twice, to find the exact byte-count, then pre-allocate max-byte-count, and truncate afterwards (if needed).

[snakefoot]

@304NotModified I know that i have stolen your code, and this is mostly a proof-of-concept. But maybe you can take some of the ideas in this PR to hammer the last nails in place for NLog 4.5.

Not sure I like exposing the Hole-structs directly. Would prefer they were just "Index" + "Name" + "Format". But I like reusing the Hole-array-allocation, instead of creating a new container.

Also missing configuration parameter to configure what ILogMessageFormatter NLog should use by default. Maybe also an option to override it for a logger-instance.

[304NotModified]

Not sure I like exposing the Hole-structs directly.

My idea was to use the event-properties for that. The holes renders fills the properties and if desired, users could overwrite them. Less complicated for the user and can use all the targets/layout renders which are built on the event-properties.

I prefer to keep the structured event logic in a separate package because:

• it forces to not making coupled code
• the unit tests and code at NLog is already to large (especially for outsiders).. It develops to slow (see .NET core issues)
• running the unit tests is taking ages.
• On .NET core is everything separated in packages, so that's the new way IMO

[snakefoot]

My idea was to use the event-properties for that.

Have also implemented that by providing the new property LogEventInfo.ParameterProperties.

But I recall this PR #1962 where someone wanted access to the holes and their format-options, and not just the parameter-names and the parameter-objects

[304NotModified]

But I recall this PR #1962 where someone wanted access to the holes and their format-options, and not just the parameter-names and the parameter-objects

I was under the impression that your proposal for that was: reparse the message.

[snakefoot]

prefer to keep the structured event logic in a separate package because:

Since the NLog-engine is going to be fully integrated with the structured-event-logic, then I find it hard to split them without it becoming very artificial.

I understand the need to rip out all the random targets and layout-renderers, but the core engine should stay in one package.

On .NET core is everything separated in packages, so that's the new way IMO

One can also go from one extreme (all classes in one package) to another extreme (each class in separate package). But any NLog-code that the NLog-core-package will depend on, that should be in the NLog-core-package.

Else we need to improve the LogEventInfo-Properties even further so one can have internal meta-properties (they exist already by the fluent-interface). Allow properties with the same name, but with different meta-property-type (Removing the ParameterHoles). And then a logger (from an external package) can attach an external formatter to a LogEventInfo. Then NLog-core will not be dependent on the NLog.StructuredEvents at all (The special logger will probably live inside NLog.StructuredEvents)

But when looking at ASP.NET-CORE loggers that seems prepared for Structured-logging, then I find it less optimal that the NLog-core is not able to handle structured-logging out of the box.

[codecov]

Codecov Report

Merging #2208 into master will increase coverage by <1%.
The diff coverage is 87%.

@@           Coverage Diff           @@
##           master   #2208    +/-   ##
=======================================
+ Coverage      82%     82%   +<1%     
=======================================
  Files         307     317    +10     
  Lines       21858   22613   +755     
  Branches     2663    2771   +108     
=======================================
+ Hits        17879   18542   +663     
- Misses       3299    3370    +71     
- Partials      680     701    +21

[snakefoot]

I was under the impression that your proposal for that was: reparse the message.

My initial thought was to provide a way to request a single parameter to be formatted as string, like specified in the message template. But after seeing that #1962 wants to use his own target-specific-formatter, then my initial thought would be too restrictive.

[304NotModified]

We lost the parse and render tests from https://github.com/NLog/NLog.StructuredEvents?

[snakefoot]

We lost the parse and render tests from https://github.com/NLog/NLog.StructuredEvents?

I will inject them

[304NotModified]

I understand the need to rip out all the random targets and layout-renderers

The idea is now, new code is in new packages and current stuff will be separated after NLog 5 RTM

But when looking at ASP.NET-CORE loggers that seems prepared for Structured-logging, then I find it less optimal that the NLog-core is not able to handle structured-logging out of the box.

It's still out of the box when those are multiple packages. I will think about it, but currently i'm not a fan to merge them.

Else we need to improve the LogEventInfo-Properties even further so one can have internal meta-properties

I don't see why we need that. Just write to the properties, drop everything else.
I agree that having the Tempate inside the EventLogInfo was not the best solution, but IMO it's now even less optimal. It too complicated. I really don't like to expose a Hole list in the LogEventInfo.

[snakefoot]

I really don't like to expose a Hole list in the LogEventInfo.

Glad you feel the same way :). Was not sure how far you wanted to go to cater for nlog-targets-seq.

But I don't like pushing the parameter-names directly into LogEventInfo.Properties, because of the potential name-clashing (that you have also tried to handle). It will give unexpected behavior, no matter what you do.

Instead of having the ParameterHoles. Then we could have something called ParameterNames, that is just a IList<string> ? (Since there is a one-to-one relationship between Parameters and ParametersNames, when non-positional. When ParameterNames is empty then it is a positional-template).

[304NotModified]

But I don't like pushing the parameter-names directly into LogEventInfo.Properties, because of the potential name-clashing

IMO the structured syntax is another way to define properties. I don't see the benefit of having properties and parameters. Those are on the same level (logevent level) and so separation is only over complicating things IMO.

[snakefoot]

I don't see the benefit of having properties and parameters.

Then one will just be surprised the day one have a custom-logger that always inject some custom-properties, and that logger is suddenly presented with a message-template that clashes.

Also I like how one can get direct mapping from the parameter-names to the parameter-values without allocating a dictionary (but that is just me).

What if we introduce a new MetaProperties-dictionary (that extends the object-key with a meta-type-enum). This will give one MetaProperties-collection, that will just allow "duplicate" object-keys. The existing Properties-dictionary will be marked obsolete and will then just return the values included from meta-type-property (and not meta-type-parametername)

[304NotModified]

Then one will just be surprised the day one have a custom-logger that always inject some custom-properties, and that logger is suddenly presented with a message-template that clashes.

That would be also the case now, as I could set the logevent properties with C#

We have now the following contexts:

• GDC
• MDC & MDLC
• NDC & NDLC
• event properties
• event context (deprecated)

Adding a new context on event level is makes it even more complex. That the event context is already deprecated is a burden (inconsistent names, old docs floating on the net) . Only if it's absolute necessary I would consider create a new "dictionary like"-structure on logeventinfo

[304NotModified]

PS:

Merging #2208 into master will decrease coverage by <1%.
The diff coverage is 80%.

Another issue with merging here, I cannot see easily if the new code is tracked by the unit tests. It doesn't look like it (it was in the other github repos 95% coverage)

But maybe that's an issue that we have to tackle differently, maybe sending the code coverage to sonar would help (but I did not get that working)

[snakefoot]

That would be also the case now, as I could set the logevent properties with C#

Usually the logger will just receive the logevent-message and parameters, and not any properties. But now it is possible for the logger to unwittingly overwrite the properties introduced by message-template.

Another issue with merging here, I cannot see easily if the new code is tracked by the unit tests

Well that is how proof-of-concept works for me, first you shuffle things around until it looks good, and then you lock things down with unit-tests (and remove unneeded code).

[snakefoot]

@304NotModified Have now removed ParameterHoles, and now injecting message-template parameter-names, when asking for the normal Properties-dictionary.

When removing ParameterHoles, then one could skip the need to allocate MesageTemplate, Holes-array and Literal-arrays, but just change the TemplateEnumerator to render the formatted message, and inject the parameter-names directly into the properties dictionary. Then the overhead would be very little (just some stack usage), and of course the StringBuilder (can probably be pooled).

One might even consider to have a MruCache, so if the same log-message-template is frequent seen, then it will cache the message-template, and reuse it instead of re-parsing the log-message (probably need to be performance tested).

[snakefoot]

@304NotModified Made a very simple performance test of this PR:

Logger Name	Messages	Size	Args	Threads	Loggers
SimpleLogger	5.000.000	128	2	1	1

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Mem (MB)
NLog-Standard	21.361	234.061	0	18	37	23.015	113,258

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Mem (MB)
NLog-Positional	24.747	202.036	0	18	36	26.156	118,078

The extra CPU time in"NLog-Positional" is caused by the scanning if the template is positional or not.

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Mem (MB)
Serilog-Positional	34.779	143.762	0	32	64	69.156	102,852

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Mem (MB)
NLog-Template	34.724	143.989	0	87	175	37.687	130,496

The extra allocations in"NLog-Template" is caused by allocation of mesage-template, properties-dictionary and stringbuilder for formatting.

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Mem (MB)
Serilog-Template	34.039	146.888	0	32	65	67.750	100,773

I think serilog has an optimization where it caches the MesageTemplates, which helps Serilog in this test. I also think Serilog doesn't allocate the formatted string, but writes it directly to its TextWriter.

NLog could probably improve its performance by not allocating a StringBuilder for every template-format-operation, and maybe attempt to cache the recent message-templates (avoid re-allocating the hole-name-strings).

The result when reusing the StringBuilder for rendering:

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Mem (MB)
NLog-Builder	32.448	154.089	0	46	93	34.187	129,164

The result when also caching the MessageTemplate:

Test Name	Time (ms)	Msgs/sec	GC2	GC1	GC0	CPU (ms)	Mem (MB)
NLog-Cache	22.458	222.634	0	31	63	23.812	122,250

[304NotModified]

Cool! Can I see the test cases code some where?

We like to use cache, it was always in the plan. Are you using the mru cache in the test?

Serilog uses a dictionary with a 1000 limit and full clear when over limit.

[snakefoot]

Cool! Can I see the test cases code some where?

It is just the performance test-project where I'm injecting a log-message-arg (with a hole-name of 25 chars) for every 64 char (Thus one in the middle and one at the end of the 128 char log-message).

The serilog-config is this:

var serilogConfig = new Serilog.LoggerConfiguration().WriteTo.Async(a => a.File(@"C:\Temp\Log\Serilog.txt"));
var serilogger = serilogConfig.CreateLogger();

We like to use cache, it was always in the plan. Are you using the mru cache in the test?

No the two bonus perf-tests is just me hardcoding things to see how caching affect allocations. The MruCache is not super-concurrent when there is a constant high insert-rate. All Loggers will hit this code-path and NLog has made an effort in not grapping a global-lock. I have not made any concurrency-tests to see how things scales as the thread-count rises.

Serilog uses a dictionary with a 1000 limit and full clear when over limit.

They have changed to a HashTable as it allows them to do the lookup without holding a monitor-lock.

An alternative approach would be to just cache the parameter-hole-names (for the property-dictionary). Since the MessageTemplate is just discarded after the rendering. Then modify the TemplateEnumerator to render without allocating any MessageTemplate (Would not be an easy task). The number of unique hole-names are probably much less than the number of unique-messages.

[304NotModified]

They have changed to a HashTable as it allows them to do the lookup without holding a monitor-lock.

Ow yes indeed: https://github.com/serilog/serilog/blob/dev/src/Serilog/Core/Pipeline/MessageTemplateCache.cs

[304NotModified]

An alternative approach would be to just cache the parameter-hole-names (for the property-dictionary). Since the MessageTemplate is just discarded after the rendering. Then modify the TemplateEnumerator to render without allocating any MessageTemplate (Would not be an easy task). The number of unique hole-names are probably much less than the number of unique-messages.

Sounds complicated and not really needed IMO

No the two bonus perf-tests is just me hardcoding things to see how caching affect allocations. The MruCache is not super-concurrent when there is a constant high insert-rate.

Maybe it's a good idea to start with this one? What do you think?

[snakefoot]

The MruCache is not super-concurrent when there is a constant high insert-rate.

Maybe it's a good idea to start with this one? What do you think?

Yes it cannot be that complicated to find a lock-free-container with fast lookup, fast insert, fast cleanup and minimum allocation :)

The above test was merely to see how far from the reference-point (Serilog) the current implementation is. Right now it looks pretty close, so maybe it is just a matter of improving the template-parser a little, and NLog is ready.

Before you start on implementing this caching business, then we might want to create another test, that pushes the concurrency a little (Closer to what a web-application might do):

• Have 6 threads that each are writing to their own log-level
• Each log-level is redirected to their individual target/sink
• Each of the 6 threads will shuffle between their own 300 unique log-messages.

For me the low hanging fruit is implementing a StringBuilder-pool, so that will probably be next two tasks (builder-pool + new test).

[304NotModified]

don't get it. LogEventTemplateShouldHaveProperties_even_when_changed fails locallly, even on dedd1e2!

[304NotModified]

ow it only works when I run all tests from LoggerTests.cs at once.

[304NotModified]

@snakefoot

I don't see it where exactly is the side-effect, but LogEvent.HasMessageTemplateParameters has a side effect. Could you try to make this more explicit?

[snakefoot]

@304NotModified I don't see it where exactly is the side-effect, but LogEvent.HasMessageTemplateParameters has a side effect.

Cannot see it either, but this call has a sideeffect:

!ReferenceEquals(this.Message, this.FormattedMessage)

It renders the formatted message, and captures properties (if any)

[snakefoot]

@304NotModified Interesting. Your test LogAfterAwait_CleanNamesOfAsyncContinuationsIsFalse_ShouldNotCleanNames seems to be unstable also on AppVeyor.

[304NotModified]

@304NotModified Interesting. Your test LogAfterAwait_CleanNamesOfAsyncContinuationsIsFalse_ShouldNotCleanNames seems to be unstable also on AppVeyor.

Don't get it. But that's the risk of stack walking. Feel free to skip the test.

[snakefoot]

@304NotModified Do we need more changes. Or can I perform a squash of the commits? (Btw. updated the Serilog performance numbers, after I disabled its lossy default behavior).

[304NotModified]

I prefer to check it again, but don't think I will find big issues. Currently working on NLog.web which should be asp.net core 2 ready asap.

#2208 (comment) -> this will be another PR?

[snakefoot]

#2208 (comment) -> this will be another PR?

Maybe start as an issue, and when having decided on something, then create a PR. I have not seen any confirmation or rejection of any of my statements :)

[304NotModified]

I have not seen any confirmation or rejection of any of my statements :)

Unfortunately hadn't find time for that.

[304NotModified]

👍 less public = less maintenance

[snakefoot]

@304NotModified Think I have found an okay solution for making it possible to provide an external override of the object-serialization (IValueSerializer)

It has the side-effect that EventPropertiesLayoutRenderer will suddenly render the contents of ienumerable-objects instead of doing ToString().

[snakefoot]

@304NotModified Squashed the commits and performed forced push.

[304NotModified]

bam!

Sorry for the delay.

thx!

[snakefoot]

@304NotModified No issue. Glad that it could be approved. Have been a long journey :)

I have found some extra modification, that I would like to include. See #2319

[ericnewton76]

This is cool. Just found out about Serilog and got led here, I already use NLog all the time.

Does the target only support going to a Seq server? Will it be possible to just dump into a file?

Ie, enable retarget to a file target and still preserve the possibility of backloading all the messages into something like Seq later?

[snakefoot]

@ericnewton76 NLog extracts the named parameters from the structured-message, and injects them into existing collection of properties, these can be used by any type of Target/Layout. Please post your comments and questions here instead: #2332

[304NotModified]

PS for seq there is https://www.nuget.org/packages/NLog.Targets.Seq/1.0.0-dev-00032