Skip to content

fix: message templates alignment compliance #2064

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 6 commits into from
May 22, 2024
Merged

fix: message templates alignment compliance #2064

merged 6 commits into from
May 22, 2024

Conversation

Insomniak47
Copy link
Contributor

Based on our conversation in messagetemplates/grammar#6

This brings alignment parsing in line with the message-templates spec which specifies: Alignment := -?[0-9]+. I've benchmarked it locally on my laptop and desktop - these are my results from my laptop. Performance ends up the same in all current benchmarks and I'd expect that in alignment heavy workloads it'd be the sameish, maybe better

The method is a bit of a misnomer that I've introduced
IsValidAlignment because it really only checks that it doesn't contain any invalid characters in slots but - for example would pass. Not worrisome because we parse it right afterwards but might be a better name.

I tried both benchmarks with AggressiveInlining but the compiler was smart enough to do it already so there was no perf change. Below are the benchmarks before and after. All of the memory benchmarks are approximately the same & def within the distributions noise in general while the parsing seems to be very similar as well which I'd expect given there's no alignment in the default parsing.

Before

Allocations

Method Mean Error StdDev Ratio RatioSD Gen0 Gen1 Allocated Alloc Ratio
LogEmpty 5.135 ns 0.0135 ns 0.0120 ns 1.00 0.00 - - - NA
LogEmptyWithEnricher 18.742 ns 0.0592 ns 0.0554 ns 3.65 0.01 - - - NA
LogScalar 212.647 ns 0.3584 ns 0.3352 ns 41.42 0.10 0.0572 - 360 B NA
LogDictionary 1,419.678 ns 2.8334 ns 2.6503 ns 276.52 0.93 0.3490 - 2192 B NA
LogSequence 330.138 ns 0.6384 ns 0.5972 ns 64.29 0.16 0.0916 - 576 B NA
LogAnonymous 1,792.173 ns 7.1056 ns 6.2989 ns 349.01 1.44 0.4616 0.0019 2896 B NA
FormatMessage 62.933 ns 0.2528 ns 0.2365 ns 12.26 0.05 0.0050 - 32 B NA

Parsing

Method Mean Error StdDev Ratio RatioSD Gen0 Gen1 Allocated Alloc Ratio
EmptyTemplate 74.78 ns 0.488 ns 0.456 ns 1.00 0.00 0.0356 - 224 B 1.00
DefaultConsoleOutputTemplate 777.85 ns 2.501 ns 2.217 ns 10.40 0.07 0.3443 0.0010 2160 B 9.64

After

Allocations

Method Mean Error StdDev Ratio RatioSD Gen0 Gen1 Allocated Alloc Ratio
LogEmpty 5.137 ns 0.0126 ns 0.0112 ns 1.00 0.00 - - - NA
LogEmptyWithEnricher 18.876 ns 0.0545 ns 0.0455 ns 3.67 0.01 - - - NA
LogScalar 163.145 ns 0.2094 ns 0.1856 ns 31.76 0.08 0.0572 - 360 B NA
LogDictionary 2,168.033 ns 3.9589 ns 3.7032 ns 422.02 1.11 0.3471 - 2192 B NA
LogSequence 323.136 ns 0.6160 ns 0.5461 ns 62.90 0.16 0.0916 - 576 B NA
LogAnonymous 1,787.612 ns 4.0751 ns 3.8119 ns 347.98 1.26 0.4616 0.0019 2896 B NA
FormatMessage 63.315 ns 0.3750 ns 0.3508 ns 12.33 0.07 0.0050 - 32 B NA

Parsing

Method Mean Error StdDev Ratio RatioSD Gen0 Gen1 Allocated Alloc Ratio
EmptyTemplate 75.94 ns 1.174 ns 1.098 ns 1.00 0.00 0.0356 - 224 B 1.00
DefaultConsoleOutputTemplate 778.35 ns 2.074 ns 1.732 ns 10.27 0.15 0.3443 0.0010 2160 B 9.64

@Insomniak47 Insomniak47 mentioned this pull request May 19, 2024
Closed
@nblumhardt
Copy link
Member

Thanks for checking this out, @Insomniak47 👍

It seems like the change should be reasonable and safe to make.

Is there any reason we couldn't switch to using int.TryParse(...) on the whole alignment value, with specific number styles and invariant culture, and then derive the direction from whether the result is negative or not? Seems like it'd be advantageous for us to get rid of the unnecessary Substring() call, and could be a bit faster, if we're lucky.

It looks like you may have branched off of main, there's a stack of additional unrelated commits in there, perhaps reapplying this from dev would clean it up?

@Insomniak47
Copy link
Contributor Author

Insomniak47 commented May 20, 2024 •
edited
Loading

Is there any reason we couldn't switch to using int.TryParse(...) on the whole alignment value, with specific number styles and invariant culture

I think we could tryparse the whole thing but I don't think that we can use the output because -0 and 0 would end up the same. We can still just check the first character but it'd still remove the substring call which would be nice.

It looks like you may have branched off of main, there's a stack of additional unrelated commits in there, perhaps reapplying this from dev would clean it up?

Yeah for sure, I'll rebase onto dev. I noticed this when I was putting the PR up then I got distracted 😄

@Insomniak47 Insomniak47 force-pushed the fix/message-templates-alignment-compliance branch from 58e3f4a to 7b5313d Compare May 20, 2024 14:17
@Insomniak47
Copy link
Contributor Author

Insomniak47 commented May 20, 2024 •
edited
Loading

Alrighty, I've moved to just the parsing, I added an additional check to make sure that '+' also isn't at the beginning + a test for it. I've also rebased on dev.

In really heavy alignment based workflows this might end up a little faster which would be neat. Looks like it allocates one additional few bytes in gen0 in the alloc benches in specific cases. I'm assuming that's because Int32.TryParse allocates and in the allocation benches it previously never had to hit it but it's still a small overall impact. I can take a peek at eliding it if you'd like

Edit: Looks like it gets rid of any Gen1's now though so might have just shifted it in some cases
Edit2: Actually just looking and realizing that this might just be a difference in the base - going to check it out
Edit3: Yeah just checked, exact same alloc as on dev

Method Mean Error StdDev Ratio RatioSD Gen0 Allocated Alloc Ratio
LogEmpty 5.032 ns 0.0433 ns 0.0362 ns 1.00 0.00 - - NA
LogEmptyWithEnricher 19.565 ns 0.0337 ns 0.0315 ns 3.89 0.03 - - NA
LogScalar 228.838 ns 0.4075 ns 0.3812 ns 45.49 0.34 0.1721 360 B NA
LogDictionary 2,347.531 ns 4.0454 ns 3.3781 ns 466.54 3.34 1.0567 2216 B NA
LogSequence 614.448 ns 1.2356 ns 1.0953 ns 122.11 0.96 0.2747 576 B NA
LogAnonymous 3,290.065 ns 5.4689 ns 4.5667 ns 653.86 4.83 1.4076 2944 B NA
FormatMessage 93.986 ns 0.4202 ns 0.3930 ns 18.67 0.16 0.0153 32 B NA

@nblumhardt
Copy link
Member

Looks good! Are those final After numbers from the same benchmarking setup as the Before series? Looks like some unexpected regressions, guessing it's a benchmarking issue rather than a real regression but just keen to double-check :)

@Insomniak47
Copy link
Contributor Author

Looks good! Are those final After numbers from the same benchmarking setup as the Before series? Looks like some unexpected regressions, guessing it's a benchmarking issue rather than a real regression but just keen to double-check :)

The last numbers I posted in #2064 (comment) are against dev not main. The dev allocations numbers are the same (no regressions) and the perf is == or better I'll post an updated before/after this evening

The ones that are in there now:

  • Before is from master
  • After is from dev

@Insomniak47
Copy link
Contributor Author

Insomniak47 commented May 22, 2024 •
edited
Loading

Before -> On dev

Method Mean Error StdDev Ratio RatioSD Gen0 Allocated Alloc Ratio
LogEmpty 5.054 ns 0.0113 ns 0.0106 ns 1.00 0.00 - - NA
LogEmptyWithEnricher 20.017 ns 0.0267 ns 0.0237 ns 3.96 0.01 - - NA
LogScalar 238.454 ns 2.4491 ns 2.2909 ns 47.18 0.44 0.1721 360 B NA
LogDictionary 2,426.358 ns 36.6736 ns 34.3045 ns 480.10 6.45 1.0567 2216 B NA
LogSequence 618.981 ns 5.3134 ns 4.7102 ns 122.50 1.04 0.2747 576 B NA
LogAnonymous 3,272.722 ns 20.1617 ns 16.8359 ns 647.72 3.58 1.4076 2944 B NA
FormatMessage 95.447 ns 0.4545 ns 0.4251 ns 18.89 0.10 0.0153 32 B NA
Method Mean Error StdDev Ratio RatioSD Gen0 Allocated Alloc Ratio
EmptyTemplate 167.7 ns 2.33 ns 2.18 ns 1.00 0.00 0.1070 224 B 1.00
DefaultConsoleOutputTemplate 1,436.8 ns 13.05 ns 12.20 ns 8.57 0.11 1.0509 2200 B 9.82

After -> This PR

Method Mean Error StdDev Ratio RatioSD Gen0 Allocated Alloc Ratio
LogEmpty 5.056 ns 0.0140 ns 0.0125 ns 1.00 0.00 - - NA
LogEmptyWithEnricher 20.184 ns 0.1148 ns 0.1074 ns 3.99 0.02 - - NA
LogScalar 236.519 ns 1.6767 ns 1.4864 ns 46.78 0.29 0.1721 360 B NA
LogDictionary 2,425.448 ns 32.1892 ns 30.1098 ns 480.11 6.00 1.0567 2216 B NA
LogSequence 621.591 ns 1.9883 ns 1.8599 ns 122.92 0.52 0.2747 576 B NA
LogAnonymous 3,293.746 ns 43.2289 ns 40.4363 ns 651.85 8.00 1.4076 2944 B NA
FormatMessage 94.241 ns 0.7545 ns 0.6689 ns 18.64 0.12 0.0153 32 B NA
Method Mean Error StdDev Ratio RatioSD Gen0 Allocated Alloc Ratio
EmptyTemplate 164.9 ns 0.65 ns 0.55 ns 1.00 0.00 0.1070 224 B 1.00
DefaultConsoleOutputTemplate 1,457.9 ns 7.40 ns 6.92 ns 8.85 0.05 1.0509 2200 B 9.82

So no regression in mem usage, no perf regression generally

@nblumhardt nblumhardt merged commit 2d3e208 into serilog:dev May 22, 2024
@nblumhardt
Copy link
Member

Thank you, @Insomniak47 👍

@Insomniak47
Copy link
Contributor Author

Happy to help!

@Insomniak47 Insomniak47 deleted the fix/message-templates-alignment-compliance branch May 23, 2024 00:38
@nblumhardt nblumhardt mentioned this pull request May 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.
2 participants
@Insomniak47 @nblumhardt