LogProvider.OpenNestedContext adds visible overhead compared to the direct call

[maxcherednik]

Description

It seems that a call through the LibLog interface introduces visible(15%) overhead, even though there is no actual logging. When I call the serilog PushProperty directly, there is no visible performance hit.

// liblog call
using(var contextDisposable = LogProvider.OpenNestedContext("some value"))
{
 // code here
}

// direct call
using(var contextDisposable = LogContext.PushProperty("NDC", "some value"))
{
 // code here
}

[damianh]

Thanks for the report.

Any details on how you are perf testing? 15% overhead is based on what values?

[maxcherednik]

Let's say I have a code like this:

public void ProcessItem(int itemId)
{
    using(var contextDisposable = LogProvider.OpenNestedContext("some value"))
    {
        // code here
    }
}

This method is called multiple times in the loop and from many threads.

This 15% performance hit is observed for the whole task. So it takes 15% more time.

[snakefoot]

That is the nature of expression-trees. There is performance penalty because of extra security-check (JIT_MethodAccessCheck). Still faster than normal reflection. Usually you only see the penalty if doing a tight loop.

This can be removed by compiling the expression into a dynamic-assembly:

https://stackoverflow.com/questions/5491837/why-is-jit-methodaccessallowedbysecurity-taking-so-much-time/5642774#5642774

Building and loading a dynamic-assembly have some side-effects (and some restrictions) that might not work for all applications. Think you have to call Microsoft to fix this, or provide an alternative solution that is faster than current implementation.

Instead of chasing this optimization, then I would probably focus on reducing the number of context-scope-calls by batching or by providing context directly in the log-message.

[maxcherednik]

@snakefoot thanks for the hint. You mentioned some other restrictions. What are those?

[damianh]

Great response @snakefoot thank you for helping :)

[snakefoot]

@maxcherednik You mentioned some other restrictions. What are those?

Reflection and expressions allows one to pull off the pants of pretty much everything. But when creating the dynamic-assembly then things becomes private again.

Putting code in dynamic-assembly also affect use of dependency-injection-components as they might start scanning them and include them. Also the dynamic-assembly can never be unloaded once created.

But must admit I don't have much experience with this. Only used myself for copy-properties-by-reflection where expression-trees made it very fast, but still 30 pct of the time was spent on JIT_MethodAccessCheck. Using the dynamic assembly-technique removed this overhead.

[damianh]

Reviewing the comments am concluding that there isn't much I can do here. I'm not enamoured adding support for dynamic assembly loading (will it even work for all runtimes / scenarios i.e. AOT?)

Am happy with the guidance that if the context is expensive for your code (which is typically a tight loop only) then reduce usage.

This is simply a trade off of leveraging logging framework portability.

Also @maxcherednik , don't use LibLog in applications; it's for libraries 😉

[maxcherednik]

@damianh could be a good idea to put it somewhere into known limitations

[damianh]

@maxcherednik Sure, stick a page in the wiki!