Output and rendering improvements #977

nblumhardt · 2017-05-31T04:12:36Z

Bundling a whole range of output and template rendering improvements for #958 here.

We won't be able to remove all of the obsolete code until the literate console sink has been weaned off of OutputProperties.GetOutputProperties(), but when that's done we should be able to clear out a lot of gunk here.

Currently just making the first few moves, will streamline things a bit before this is "done".

…ering

nblumhardt · 2017-05-31T04:15:27Z

Oh, and I'll fix the tests ;-)

nblumhardt · 2017-06-01T11:44:25Z

Now includes #958, #956 and the optional JSON output style suggested in serilog/serilog-sinks-console#7.

This is, unfortunately, a bit of a monster changeset. Digging in to output formatting unearthed a lot of code that needed cleanup - I ended up fixing a few things like unused usings globally to get us back to "ReSharper Green".

Here are the main points:

Output templates can now include one or both of two optional formats, e.g.
- {Message:l} will omit "quotes" and not perform any escaping on strings embedded in the message
- {Message:j} will use JSON, rather than Serilog's friendly formatting, for embedded data (this includes numbers, structures, arrays and so-on)
- {Message:lj} is as for JSON, but with unquoted/unescaped string values
Output formatting now makes many less allocations. Benchmarks coming shortly.
OutputProperties.GetOutputProperties() and the original allocatey output formatting types are still around for API compatibility but marked [Obsolete]; it's probably only LiterateConsoleSink really depends on them, can remove in a future major release.
Rendering of message templates is now separate from the MessageTemplate class; in general, the two places where our data structures implement their own rendering (MessageTemplate and LogEventPropertyValue) are at odds with the need for multiple different styles.
- The new MessageTemplateRenderer can be used as the basis for some of the console sink improvements, where coloring etc. make other reuse methods awkward
- Planning to take this further and move LogEventPropertyValue rendering into a visitor implementation at a later date
- For now, I've left the public API surface the same
Obsoleted RawFormatter - discovered we have no tests for it, and I'm not sure there's any real need for it.
In light of the terminology we tend to use these days I've moved some internal types into Serilog.Capturing and Serilog.Rendering namespaces; Destructure -> Capture? (Discussion) #839 might take this further.
Padding.Apply() no longer allocates for padding <= 80 chars.

Now to bench... :-)

nblumhardt · 2017-06-01T22:35:51Z

Having trouble with the benchmark runner, will need to come back to this when it's sorted out :-(

nblumhardt · 2017-06-01T22:37:56Z

src/Serilog/Formatting/Display/MessageTemplateTextFormatter.cs

-            // This could be lazier: the output properties include
-            // everything from the log event, but often we won't need any more than
-            // just the standard timestamp/message etc.
-            var outputProperties = OutputProperties.GetOutputProperties(logEvent, _outputTemplate);


The changes in this method are the meat of the "less allocations" change - GetOutputProperties() above would previously allocate objects for {Level}, {Message}, {Exception} etc. Instead now we just iterate and examine property names, and write the output inline.

nblumhardt · 2017-06-01T22:40:39Z

src/Serilog/Rendering/MessageTemplateRenderer.cs

+
+namespace Serilog.Rendering
+{
+    static class MessageTemplateRenderer


This class is the remainder - formatting of message templates is externalized from the MessageTemplate and related token classes here.

I expect there will be a small perf hit because dispatch is done by switching on type, rather than by virtual dispatch.

johnduhart · 2017-06-01T23:49:06Z

After a quick look, it seems that a few class namespaces have changed. Is this considered a breaking change?

nblumhardt · 2017-06-01T23:59:04Z

Thanks for checking it out, @johnduhart. It would be if the namespaces contained public types, but these are all internal types so there shouldn't be externally visible effects this time around.

...unless I've overlooked something public in there, of course :-)

johnduhart · 2017-06-02T00:07:13Z

Oh, right, I guess I overlooked that 😅

nblumhardt · 2017-06-02T00:08:43Z

I am really itching to clean up some of the public type names and namespaces - they've been frozen for compatibility reasons for three years or so now, and a few like #839 would be worthwhile improvements. Someday!

merbla · 2017-06-02T22:38:08Z

@nblumhardt can you link to your Resharper profile/settings? Just want to be on the same page.

nblumhardt · 2017-06-03T01:16:47Z

@merbla I just exported them in their entirety and included the dotsettings file in this PR: https://github.com/serilog/serilog/pull/977/files#diff-a08cec6edf37e99e02d322888266d97d

:-)

merbla · 2017-06-03T04:27:18Z

@nblumhardt a bit of love is needed post #976

…improvements

nblumhardt · 2017-06-04T22:58:27Z

OutputTemplateRenderingBenchmark

Before:

Method	Mean	StdDev
FormatToOutput	2.5465 us	0.0497 us

After:

Method	Mean	StdDev
FormatToOutput	1.4546 us	0.0188 us

This doesn't take the garbage reduction into account, so I think it's nice to get a ~40% perf boost along the way.

MessageTemplateRenderingBenchmark

Before:

Method	Mean	StdDev
TemplateWithNoProperties	NA	NA
TemplateWithVariedProperties	524.7727 ns	9.0085 ns

After:

Method	Mean	StdDev
TemplateWithNoProperties	NA	NA
TemplateWithVariedProperties	576.5388 ns	9.5544 ns

So, the switch from virtual to type-driven dispatch looks like it will cost about 10%. Not awesome, but also not too worrying.

The broken benchmark turned up some problems with this one in general, namely, the code intended to reset the output StringWriter before each test was only being run once. Having a look at the implications now.

nblumhardt · 2017-06-05T00:22:37Z

Fixed the message template rendering benchmark; this is the "after":

Method	Mean	Error	StdDev
TemplateWithNoProperties	6.773 ns	0.0551 ns	0.0488 ns
TemplateWithVariedProperties	408.450 ns	1.8831 ns	1.7614 ns

Knocks ~25% off the overall time, meaning the differences in the earlier run are probably understated by about that much.

BDN 0.10.6 doesn't get the .NET Framework target running successfully either, unfortunately.

nblumhardt · 2017-06-05T00:28:43Z

src/Serilog/Rendering/Padding.cs

+            }
+            else
+            {
+                output.Write(new string(' ', pad));


We now only allocate if the padding applied to a token is > 80 chars. (We allocated for every render, previously.)

nblumhardt · 2017-06-05T00:33:20Z

I think this'd benefit from a look over, now. Might be some future improvements to make, but I'm happy that it makes enough progress to be a worthwhile merge.

… on select benchmarks.

nblumhardt · 2017-06-07T05:54:31Z

Ran these again, with the benchmark changes backported to my local dev branch for the "before" numbers.

BenchmarkDotNet=v0.10.6, OS=Windows 10 Redstone 2 (10.0.15063)
Processor=Intel Core i7-7700HQ CPU 2.80GHz (Kaby Lake), ProcessorCount=8
Frequency=2742186 Hz, Resolution=364.6726 ns, Timer=TSC
dotnet cli version=1.0.4
  [Host]     : .NET Core 4.6.25211.01, 64bit RyuJIT
  DefaultJob : .NET Core 4.6.25211.01, 64bit RyuJIT

OutputTemplateRenderingBenchmark

Before:

Method	Mean	Error	StdDev	Gen 0	Allocated
FormatToOutput	2.438 us	0.0189 us	0.0167 us	0.3662	1.13 KB

After:

Method	Mean	Error	StdDev	Gen 0	Allocated
FormatToOutput	1.433 us	0.0344 us	0.0992 us	0.1545	488 B

MessageTemplateRenderingBenchmark

Before:

Method	Mean	Error	StdDev	Gen 0	Allocated
TemplateWithNoProperties	5.232 ns	0.0798 ns	0.0708 ns	-	0 B
TemplateWithVariedProperties	406.996 ns	3.5597 ns	3.3298 ns	0.0300	96 B

After:

Method	Mean	Error	StdDev	Gen 0	Allocated
TemplateWithNoProperties	8.287 ns	0.2085 ns	0.2401 ns	-	0 B
TemplateWithVariedProperties	437.724 ns	2.9852 ns	2.7924 ns	0.0300	96 B

I'm not unhappy with these, but I don't think TemplateWithNoProperties should show such a difference. Trying a couple of other tweaks.

nblumhardt · 2017-06-07T07:55:31Z

Alright, figured out the regression :-) This is the "after" now:

Method	Mean	Error	StdDev	Gen 0	Allocated
TemplateWithNoProperties	5.591 ns	0.1466 ns	0.1907 ns	-	0 B
TemplateWithVariedProperties	418.376 ns	2.6112 ns	2.3148 ns	0.0300	96 B

The additional cost was a couple of argument checks. The numbers are so small I think it probably makes sense to leave (at least some of) the extra checks in. I'll see what I can come up with.

…ning

nblumhardt · 2017-06-07T10:16:41Z

Method	Mean	Error	StdDev	Gen 0	Allocated
TemplateWithNoProperties	5.934 ns	0.0778 ns	0.0690 ns	-	0 B
TemplateWithVariedProperties	411.162 ns	8.2177 ns	13.0341 ns	0.0300	96 B

Ready to go.

There's one further sneaky change here - the classes PropertyToken and TextToken are now sealed. This is technically a breaking change, but I don't believe there are any valid scenarios for deriving from these, and I've never seen it done in the wild. There are two reasons for sealing - first, it makes Render() on these types potentially statically dispatchable through a subclass reference, but also, it makes clear that these aren't designed for inheritance anyway.

nblumhardt · 2017-06-10T23:58:27Z

Is there a chance anyone has some time to look over this one? :-)

merbla · 2017-06-11T22:02:09Z

src/Serilog/Formatting/Display/OutputProperties.cs

@@ -62,7 +65,7 @@ public static class OutputProperties
        /// </summary>
        /// <param name="logEvent">The log event.</param>
        /// <returns>A dictionary with properties representing the log event.</returns>
-        [Obsolete("Pass the full output template using the other overload.")]
+        [Obsolete("These implementation details of output formatting will not be exposed in a future version.")]
        public static IReadOnlyDictionary<string, LogEventPropertyValue> GetOutputProperties(LogEvent logEvent)


Just confirming this is the main consumer we are worried about? https://github.com/serilog/serilog-sinks-literate/blob/dev/src/Serilog.Sinks.Literate/Sinks/Literate/LiterateConsoleSink.cs#L88

That's the one 👍

merbla · 2017-06-11T23:08:54Z

src/Serilog/Formatting/Display/OutputProperties.cs

@@ -74,7 +77,7 @@ public static class OutputProperties
        /// <param name="logEvent">The log event.</param>
        /// <param name="outputTemplate">The output template.</param>
        /// <returns>A dictionary with properties representing the log event.</returns>
-        public static IReadOnlyDictionary<string, LogEventPropertyValue> GetOutputProperties(LogEvent logEvent, MessageTemplate outputTemplate)
+        internal static IReadOnlyDictionary<string, LogEventPropertyValue> GetOutputProperties(LogEvent logEvent, MessageTemplate outputTemplate)


Do we call this out as a breaking change in 2.5?

I think it would make sense to list it prominently. Super surprised if it breaks anything out there today, though.

merbla · 2017-06-11T23:10:54Z

src/Serilog/Serilog.csproj

@@ -18,6 +18,8 @@
    <GenerateAssemblyVersionAttribute>false</GenerateAssemblyVersionAttribute>
    <!-- Don't reference the full NETStandard.Library -->
    <DisableImplicitFrameworkReferences>true</DisableImplicitFrameworkReferences>
+    <TreatWarningsAsErrors>True</TreatWarningsAsErrors>


merbla · 2017-06-11T23:11:46Z

src/Serilog/Parsing/TextToken.cs


 namespace Serilog.Parsing
 {
    /// <summary>
    /// A message template token representing literal text.
    /// </summary>
-    public class TextToken : MessageTemplateToken
+    public sealed class TextToken : MessageTemplateToken


Another note for 2.5 release.

merbla · 2017-06-11T23:12:34Z

@nblumhardt all good from me, just some questions to make sure these changes are noted in release.

merbla · 2017-06-12T05:55:30Z

Lets get this to dev to measure the impact on sinks

nblumhardt · 2017-06-13T07:49:57Z

Thanks for the review @merbla 👍

Initial work for #958 - stop allocating output properties during rend…

d2dd76d

…ering

nblumhardt added 7 commits May 31, 2017 14:19

Fix tests

391882a

Separate current and obsolete formatting code

b02acd2

Separate rendering of message templates from their representation

ffee0db

Namespace layout and RESHARPER GREEN!

a74938c

Improve flow of MessageTemplateRenderer

2ce90e4

Tests for {Message:l} and {Message:j} formatting

3ba9d2a

Merge branch 'dev' into output-improvements

8a57c07

nblumhardt commented Jun 1, 2017

View reviewed changes

Render text token through the external method

5f5770d

nblumhardt added 4 commits June 5, 2017 07:13

Merge branch 'dev' of https://github.com/serilog/serilog into output-…

3cec4bd

…improvements

Update BenchmarkDotNet to 0.10.6

0308bc7

Merge branch 'bdn-update' into output-improvements

9b99d7e

Fix some dodgy string formatting benchmarks

4b0e2be

nblumhardt commented Jun 5, 2017

View reviewed changes

nblumhardt changed the title ~~Output and rendering improvements [WIP]~~ Output and rendering improvements Jun 5, 2017

nblumhardt mentioned this pull request Jun 5, 2017

2.5.0 Release #980

Merged

Prevent xunit from shadow-copying test assemblies

c17ea15

nblumhardt mentioned this pull request Jun 6, 2017

PropertyValueConverter improvements #981

Merged

Merge branch 'dev' into output-improvements; enable MemoryDiagnoser…

ce2caef

… on select benchmarks.

Fewer arg checks; seal message template token classes; encourage inli…

e205c07

…ning

merbla reviewed Jun 11, 2017

View reviewed changes

nblumhardt merged commit e42245c into serilog:dev Jun 13, 2017

merbla mentioned this pull request Jun 14, 2017

The Great Console Unification serilog/serilog-sinks-console#7

Closed

5 tasks

Output and rendering improvements #977

Output and rendering improvements #977

Uh oh!

Conversation

nblumhardt commented May 31, 2017

Uh oh!

nblumhardt commented May 31, 2017

Uh oh!

nblumhardt commented Jun 1, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

nblumhardt commented Jun 1, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

johnduhart commented Jun 1, 2017

Uh oh!

nblumhardt commented Jun 1, 2017

Uh oh!

johnduhart commented Jun 2, 2017

Uh oh!

nblumhardt commented Jun 2, 2017

Uh oh!

merbla commented Jun 2, 2017

Uh oh!

nblumhardt commented Jun 3, 2017

Uh oh!

merbla commented Jun 3, 2017

Uh oh!

nblumhardt commented Jun 4, 2017

OutputTemplateRenderingBenchmark

MessageTemplateRenderingBenchmark

Uh oh!

nblumhardt commented Jun 5, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

nblumhardt commented Jun 5, 2017

Uh oh!

nblumhardt commented Jun 7, 2017

OutputTemplateRenderingBenchmark

MessageTemplateRenderingBenchmark

Uh oh!

nblumhardt commented Jun 7, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

nblumhardt commented Jun 7, 2017

Uh oh!

nblumhardt commented Jun 10, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

merbla commented Jun 11, 2017

Uh oh!

merbla commented Jun 12, 2017

Uh oh!

nblumhardt commented Jun 13, 2017

Uh oh!

Uh oh!

nblumhardt commented Jun 1, 2017 •

edited

Loading

nblumhardt commented Jun 7, 2017 •

edited

Loading