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

Cache parsed message templates #166

Merged
merged 2 commits into from
May 14, 2020

Conversation

nblumhardt
Copy link
Member

This integrates the well-tested template cache from serilog/serilog. In general, this will reduce allocations and speed up logging when events use templates properly (16 GB T470p):

Before

Method Mean Error StdDev Ratio RatioSD Gen 0 Gen 1 Gen 2 Allocated
Native 370.5 ns 7.067 ns 6.265 ns 1.00 0.00 0.0887 - - 280 B
NoId 1,017.8 ns 10.906 ns 9.107 ns 2.75 0.04 0.2785 - - 880 B
LowNumbered 1,318.5 ns 11.772 ns 10.435 ns 3.56 0.06 0.3529 - - 1112 B
HighNumbered 1,363.2 ns 20.672 ns 18.325 ns 3.68 0.07 0.3777 - - 1192 B

After

Method Mean Error StdDev Ratio RatioSD Gen 0 Gen 1 Gen 2 Allocated
Native 362.2 ns 3.419 ns 3.031 ns 1.00 0.00 0.0887 - - 280 B
NoId 604.3 ns 11.431 ns 10.133 ns 1.67 0.03 0.1421 - - 448 B
LowNumbered 843.9 ns 12.429 ns 11.018 ns 2.33 0.04 0.2155 - - 680 B
HighNumbered 878.3 ns 17.330 ns 16.211 ns 2.43 0.03 0.2413 - - 760 B

Performance might regress in apps that (mis)use string concatenation to construct log messages, but the benefits for carefully-written have been found to outweigh this downside in our experiences with Serilog to date.

// activities.

if (_templates.Count == MaxCacheItems)
_templates.Clear();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This line gives race condition with var result = (MessageTemplate)_templates[messageTemplate];

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for taking a look, @sungam3r.

The two lines above mention this:

            // ReSharper disable once InconsistentlySynchronizedField
            // ignored warning because this is by design
            var result = (MessageTemplate)_templates[messageTemplate];

Although there may be undocumented bugs in Hashtable, it was originally intended to be used in this manner, and we've not observed any problems with this particular pattern in several years of very heavy usage in Serilog.

There's a little more discussion here: JamesNK/Newtonsoft.Json#1163 (comment) (it's never been clear which of the Hashtable APIs have threading bugs, unfortunately).

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ok

@skomis-mm
Copy link

skomis-mm commented May 13, 2020

Oops, sorry, didn't know it auto close referenced PRs too 😄

@skomis-mm skomis-mm reopened this May 13, 2020
@skomis-mm
Copy link

LGTM 👍

@nblumhardt nblumhardt merged commit a2e70ee into serilog:dev May 14, 2020
@nblumhardt nblumhardt mentioned this pull request Nov 1, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants