Skip to content

MessageTemplateParser refactor incl. experimental . support #2063

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.

Sign up for GitHub

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

Jump to bottom
Merged
merged 7 commits into from
May 22, 2024
Merged

MessageTemplateParser refactor incl. experimental . support #2063

merged 7 commits into from
May 22, 2024

Conversation

nblumhardt
Copy link
Member

@nblumhardt nblumhardt commented May 17, 2024 •
edited
Loading

This PR came out of, and includes, #1384. You can read about the reasons for considering . in message template property names, and the various caveats/disadvantages on that thread. The PR enables wider investigation and experimentation, and there is currently no guarantee that this will ever become a first-class, supported Serilog feature.

By setting the experimental and unsupported AppContext switch at program start-up:

AppContext.SetSwitch("Serilog.Parsing.MessageTemplateParser.AcceptDottedPropertyNames", true)

Placeholders such as {http.request.method} will (should!) be accepted in message and output templates. Previously, these templates would have been regarded as invalid.

Dotted placeholders will be interpreted as literal property names, e.g. "http.request.method", and not structured object paths like {http: {request: {method: ...}}}.

In the process of investigating this I cleaned up some message template parsing tests; these are so old and could use a lot more work, especially translating long multi-assert tests into data-driven [Theory]s.

MessageTemplateParser itself has also been unchanged for a long time. It could benefit from porting to a Span<T>-based model, but even improving our use of vanilla string methods yielded a significant performance boost. Long runs of literal text (very common in real-world logs) now allocate dramatically less temporary memory during parsing.

Before:

BenchmarkDotNet=v0.13.5, OS=macOS 14.4.1 (23E224) [Darwin 23.4.0]
Apple M3 Pro, 1 CPU, 11 logical and 11 physical cores
.NET SDK=8.0.204
  [Host]     : .NET 8.0.4 (8.0.424.16909), Arm64 RyuJIT AdvSIMD
  DefaultJob : .NET 8.0.4 (8.0.424.16909), Arm64 RyuJIT AdvSIMD

|                       Method |      Mean |    Error |   StdDev | Ratio | RatioSD |   Gen0 | Allocated | Alloc Ratio |
|----------------------------- |----------:|---------:|---------:|------:|--------:|-------:|----------:|------------:|
|                EmptyTemplate |  46.98 ns | 0.175 ns | 0.164 ns |  1.00 |    0.00 | 0.0268 |     224 B |        1.00 |
| DefaultConsoleOutputTemplate | 475.56 ns | 3.038 ns | 2.842 ns | 10.12 |    0.08 | 0.2575 |    2160 B |        9.64 |
|              LiteralTextOnly | 171.53 ns | 0.223 ns | 0.209 ns |  3.65 |    0.01 | 0.1194 |    1000 B |        4.46 |

After:

BenchmarkDotNet=v0.13.5, OS=macOS 14.4.1 (23E224) [Darwin 23.4.0]
Apple M3 Pro, 1 CPU, 11 logical and 11 physical cores
.NET SDK=8.0.204
  [Host]     : .NET 8.0.4 (8.0.424.16909), Arm64 RyuJIT AdvSIMD
  DefaultJob : .NET 8.0.4 (8.0.424.16909), Arm64 RyuJIT AdvSIMD


|                       Method |      Mean |    Error |   StdDev | Ratio | RatioSD |   Gen0 |   Gen1 | Allocated | Alloc Ratio |
|----------------------------- |----------:|---------:|---------:|------:|--------:|-------:|-------:|----------:|------------:|
|                EmptyTemplate |  48.35 ns | 0.245 ns | 0.229 ns |  1.00 |    0.00 | 0.0277 |      - |     232 B |        1.00 |
| DefaultConsoleOutputTemplate | 432.28 ns | 2.591 ns | 2.423 ns |  8.94 |    0.06 | 0.2074 | 0.0005 |    1736 B |        7.48 |
|              LiteralTextOnly |  59.97 ns | 0.099 ns | 0.088 ns |  1.24 |    0.01 | 0.0343 |      - |     288 B |        1.24 |

Results were similar on .NET 6 on ARM, though much slower across the board.

The additional eight-byte allocation in the baseline EmptyTemplate case is the change in MessageTemplate memory layout due to the additional bool _acceptDottedPropertyNames member.

@nblumhardt
Copy link
Member Author

(Surprising actually, that this late in the game a couple of simple string.IndexOf() calls can > 3x performance and < 1/3x allocations in a fairly mainline scenario 😅 .)

@nblumhardt nblumhardt mentioned this pull request May 18, 2024
Closed
7 tasks
@nblumhardt
Copy link
Member Author

Heads-up also @Mpdreamz - I know that Elastic.Serilog.Sinks currently maps some PascalCase property names to dotted ECS equivalents. It'd be interesting to consider what a future iteration supporting dotted property names in message templates directly would mean over there.

@nblumhardt
Copy link
Member Author

Updated the PR to consider . only, and ignore - for now.

@nblumhardt nblumhardt changed the title MessageTemplateParser refactor incl. experiemental ./- support MessageTemplateParser refactor incl. experiemental . support May 19, 2024
@cchapman-kxs
Copy link

/lgtm

Thanks for taking the first step in enabling easier log schema adherence!

I'm hoping I can find a chance soon to test this but no promises.

@Mpdreamz
Copy link
Member

Love this! Our ECS field based setters can handle both the original dotted key names as well as PascalCased ones.

@cchapman-kxs
Copy link

Tested with an example app going through an ILogger:

_logger.LogInformation("This {action.noun} is {action.adverb} {action.adjective}!", "logging", "ridiculously", "easy");

and got the expected output in DataDog:

image

Not exhaustive testing but at least an initial indication that I'm getting the desired result.

@cchapman-kxs
Copy link

Also verified simple console and file logging works as expected. Sending to DataDog is using the DurableHttpUsingFileSizeRolledBuffers from https://github.com/FantasticFiasco/serilog-sinks-http - very much not a trivial example and many places that could have interfered with the intended result.

@nblumhardt nblumhardt merged commit e1a0047 into serilog:dev May 22, 2024
@nblumhardt nblumhardt added the v4 label May 23, 2024
This was referenced May 23, 2024
Merged
Merged
@nblumhardt nblumhardt mentioned this pull request Jul 26, 2024
Closed
@nblumhardt nblumhardt changed the title MessageTemplateParser refactor incl. experiemental . support MessageTemplateParser refactor incl. experimental . support Nov 25, 2024
@nblumhardt
Copy link
Member Author

Thinking about opening a PR to stabilize this. Any experiences to share, good or bad?

@nblumhardt nblumhardt mentioned this pull request Nov 27, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@nblumhardt @cchapman-kxs @Mpdreamz