Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Output and rendering improvements #977

Merged
merged 16 commits into from Jun 13, 2017

Conversation

Projects
None yet
3 participants
@nblumhardt
Copy link
Member

nblumhardt commented May 31, 2017

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".

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented May 31, 2017

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

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 1, 2017

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; #839 might take this further.
  • Padding.Apply() no longer allocates for padding <= 80 chars.

Now to bench... :-)

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 1, 2017

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

// 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);

This comment has been minimized.

@nblumhardt

nblumhardt Jun 1, 2017

Author Member

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.


namespace Serilog.Rendering
{
static class MessageTemplateRenderer

This comment has been minimized.

@nblumhardt

nblumhardt Jun 1, 2017

Author Member

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

This comment has been minimized.

Copy link
Contributor

johnduhart commented Jun 1, 2017

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

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 1, 2017

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

This comment has been minimized.

Copy link
Contributor

johnduhart commented Jun 2, 2017

Oh, right, I guess I overlooked that 😅

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 2, 2017

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

This comment has been minimized.

Copy link
Contributor

merbla commented Jun 2, 2017

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

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 3, 2017

@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

This comment has been minimized.

Copy link
Contributor

merbla commented Jun 3, 2017

@nblumhardt a bit of love is needed post #976

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 4, 2017

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

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 5, 2017

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.

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

This comment has been minimized.

@nblumhardt

nblumhardt Jun 5, 2017

Author Member

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

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

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 5, 2017

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.

@nblumhardt nblumhardt referenced this pull request Jun 5, 2017

Merged

2.5.0 Release #980

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 7, 2017

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

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 7, 2017

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.

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 7, 2017

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

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 10, 2017

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

@@ -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)

This comment has been minimized.

@merbla

This comment has been minimized.

@nblumhardt

nblumhardt Jun 13, 2017

Author Member

That's the one 👍

@@ -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)

This comment has been minimized.

@merbla

merbla Jun 11, 2017

Contributor

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

This comment has been minimized.

@nblumhardt

nblumhardt Jun 13, 2017

Author Member

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

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

This comment has been minimized.

@merbla

merbla Jun 11, 2017

Contributor

GOLD 🥇


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

This comment has been minimized.

@merbla

merbla Jun 11, 2017

Contributor

Another note for 2.5 release.

@merbla

This comment has been minimized.

Copy link
Contributor

merbla commented Jun 11, 2017

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

@merbla

This comment has been minimized.

Copy link
Contributor

merbla commented Jun 12, 2017

Lets get this to dev to measure the impact on sinks

@nblumhardt

This comment has been minimized.

Copy link
Member Author

nblumhardt commented Jun 13, 2017

Thanks for the review @merbla 👍

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

2 checks passed

continuous-integration/appveyor/pr AppVeyor build succeeded
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details

@merbla merbla referenced this pull request Jun 14, 2017

Closed

The Great Console Unification #7

4 of 5 tasks complete
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.