Only case sensitive check for minimumLevel override

[Phil91]

Description
Serilog currently only supports case sensitive matches when overriding the log level for a specific namespace, when for example using Serilog with Serilog.Settings.Configuration and setting env variables for a docker image the Namespaces can't be all upper case.

Reproduction
Setting up a test project with Serilog and Serilog.Settings.Configuration installed, configure Serilog for example like this:

host.UseSerilog((context, configuration) =>
        {
            configuration
                .WriteTo.Console(new JsonFormatter())
                .ReadFrom.Configuration(context.Configuration);
        })

add a appsettings file with the following configuration:

"Serilog": {
    "Using":  [ "Serilog.Sinks.Console" ],
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Test.Nmspc": "Information"
      }
    },
    "WriteTo": [
      { "Name": "Console" }
    ],
    "Enrich": [
      "FromLogContext"
    ],
    "Properties": {
      "Application": "Org.Eclipse.TractusX.Portal.Backend.Administration.Service"
    }
  },

Then execute the application with the following env var: SERILOG__MINIMUMLEVEL__OVERRIDE__TEST.NMSPC=Debug

The minimum logLevel for Loggers within that namespace will be Information

If needed I can provide an example repo.

Expected behavior
The minimum log level for logger instances creates within the Test.Nmspc Namespace should be Debug.

Relevant package, tooling and runtime versions

• Serilog 3.0.1
• Serilog.Settings.Configuration 3.4.0
• aspnet core 6 & 7 (both tested)
• docker image with environment variables (tested locally with a secret file as well on a win 10 machine)

Additional context
I've already provided a PR with a change for the case insensitive check.

[tillig]

Duplicate #1335 - would still love to see a case-insensitive match.

[Phil91]

Duplicate #1335 - would still love to see a case-insensitive match.

@tillig didn't saw that. thanks for linking.

[tillig]

Somewhat related - serilog/serilog-settings-configuration#386 found that the parser for the log level enum in configuration was inconsistently case-sensitive and case-insensitive, and that got resolved to be case-insensitive everywhere. That makes things just slightly more inconsistent: enum parsing is case-insensitive, but the keys are case-sensitive.

[PureKrome]

Why can't this be a 'flag' ? Give the developer the option?

[nblumhardt]

Does anyone have comparative perf numbers for performing the level check in case-insensitive vs sensitive mode? I think that's the place we're most likely to hit issues.

I don't think it's a matter of preference, I'd guess (almost?) everyone would be fine with insensitive matches if they performed identically, so keen to steer clear of flags/options at this stage.

v4 is open now, so a good time to look at this if we think it's got a chance :)

[tillig]

Was going to look at this, just coming up with some simple benchmarks, but wanted to verify I'm benchmarking the right thing.

It appears the case-sensitivity comes in when checking if there is a level override for a particular context.

So that means Serilog.Core.Logger.ForContext() which calls Serilog.Core.LevelOverrideMap.GetEffectiveLevel() and checks context.StartsWith(). The thing we want to see is if case sensitivity meaningfully impacts the context.StartsWith() call.

If I'm not mistaken, that boils down to just determining the difference in perf between

• For systems that don't have ReadOnlySpan<char>, String.StartsWith(String) and String.StartsWith(String, StringComparison.OrdinalIgnoreCase)
• For systems that have ReadOnlySpan<char>, ReadOnlySpan<char>.StartsWith(ReadOnlySpan<char>) and ReadOnlySpan<char>.StartsWith(ReadOnlySpan<char>, StringComparison.OrdinalIgnoreCase)

Does that sound right? Is there some other string comparison or larger path that needs to be benchmarked? Would benchmarks simply comparing those two methods be enough to inform a decision?

[nblumhardt]

Thanks for the follow-up @tillig. I think there's a bug in the current version, that StartsWith() should really be specifying StringComparison.Ordinal. I think we'd be comparing the ordinal vs ordinal-ignore-case versions.

It would be good to know the difference in raw perf across those four variants; I think we'd still want to know what the difference is in the context of logging with a suppressed override, e.g.:

var log = new LoggerConfiguration()
    .MinimumLevel.Override("Microsoft.AspNetCore.Hosting", LogEventLevel.Warning)
    .CreateLogger();

var scoped = log.ForContext("Microsoft.AspNetCore.Hosting");

// Bench this bit:
scoped.Information("Hello");

Perf will vary based on the number of overrides, so there would still be some extrapolation to do, but if there's no significant difference we'd be good-to-go.

[tillig]

Oh, looks like there's already a nice benchmark set up for source context matching, so I can add to that.

[tillig]

Hmmm. I'm going to have to work this one out. Having trouble with BenchmarkDotNet.

dotnet test -c Release -f net8.0 --filter "FullyQualifiedName=Serilog.PerformanceTests.Harness.SourceContextMatch"

Trying to run that, I get a bunch of errors about how the autogenerated benchmark assembly is tareting netcoreapp2.1 and that there's a security vulnerability in Microsoft.NETCore.App 2.1.0.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
No test matches the given testcase filter `FullyQualifiedName=Serilog.PerformanceTests.Harness.SourceContextMatch` in /Users/travis.illig/dev/tillig/serilog/test/Serilog.ApprovalTests/bin/Release/net8.0/Serilog.ApprovalTests.dll

No test matches the given testcase filter `FullyQualifiedName=Serilog.PerformanceTests.Harness.SourceContextMatch` in /Users/travis.illig/dev/tillig/serilog/test/Serilog.Tests/bin/Release/net8.0/Serilog.Tests.dll

// Validating benchmarks:
// ***** BenchmarkRunner: Start   *****
// ***** Found 6 benchmark(s) in total *****
// ***** Building 2 exe(s) in Parallel: Start   *****
// ***** Done, took 00:00:01 (1.3 sec)   *****
// ***** Failed to build in Parallel, switching to sequential build   *****
// ***** Done, took 00:00:01 (1.98 sec)   *****
// Found 6 benchmarks:
//   SourceContextMatchBenchmark.Filter_MatchingFromSource: .NET Core 2.1(Runtime=.NET Core 2.1)
//   SourceContextMatchBenchmark.Logger_ForContext: .NET Core 2.1(Runtime=.NET Core 2.1)
//   SourceContextMatchBenchmark.LevelOverrideMap_GetEffectiveLevel: .NET Core 2.1(Runtime=.NET Core 2.1)
//   SourceContextMatchBenchmark.Filter_MatchingFromSource: .NET Core 3.1(Runtime=.NET Core 3.1)
//   SourceContextMatchBenchmark.Logger_ForContext: .NET Core 3.1(Runtime=.NET Core 3.1)
//   SourceContextMatchBenchmark.LevelOverrideMap_GetEffectiveLevel: .NET Core 3.1(Runtime=.NET Core 3.1)

// Build Error: Standard output:

 Standard error:
   Determining projects to restore...
/Users/travis.illig/dev/tillig/serilog/test/Serilog.PerformanceTests/bin/Release/net8.0/b43c468c-6c15-4641-87cb-afcb8321e852/BenchmarkDotNet.Autogenerated.csproj : warning NU1903: Package 'Microsoft.NETCore.App' 2.1.0 has a known high severity vulnerability, https://github.com/advisories/GHSA-2xjx-v99w-gqf3

That causes the benchmark to fail to compile and run. I may need to change this to use the BenchmarkSwitcher in my branch.

[tillig]

Oh, I see why this is. It's the [SimpleJob(RuntimeMoniker.NetCoreApp21, baseline: true)] on the SourceContextMatchBenchmark job. Might need to update that to run something newer as the baseline.

[tillig]

Rather than stick the .StartsWith methods in a tight loop, I just went straight for the SourceContextMatchBenchmark because that already had the test for LevelOverrideMap.GetEffectiveLevel in place. I ran it three times on the dev branch.

• Serilog code unmodified - case insensitive search, but not explicitly specified.
• Use context.StartsWith(str, StringComparison.Ordinal) - explicitly specify case-sensitivity.
• Use context.StartsWith(str, StringComparison.OrdinalIgnoreCase) - explicitly specify case-insensitivity.

Case Comparison	Method	Job	Runtime	Mean	Error	StdDev
Case Sensitive/Default (Current)	Filter_MatchingFromSource	.NET 6.0	.NET 6.0	1,629.12 ns	17.992 ns	16.829 ns
Case Sensitive/Default (Current)	Filter_MatchingFromSource	.NET 8.0	.NET 8.0	1,177.59 ns	13.127 ns	12.279 ns
Ordinal (Explicit)	Filter_MatchingFromSource	.NET 6.0	.NET 6.0	1,554.08 ns	25.342 ns	23.705 ns
Ordinal (Explicit)	Filter_MatchingFromSource	.NET 8.0	.NET 8.0	1,182.60 ns	13.657 ns	12.775 ns
OrdinalIgnoreCase (Proposed)	Filter_MatchingFromSource	.NET 6.0	.NET 6.0	1,627.5 ns	15.69 ns	14.68 ns
OrdinalIgnoreCase (Proposed)	Filter_MatchingFromSource	.NET 8.0	.NET 8.0	1,146.3 ns	14.48 ns	13.54 ns
Case Sensitive/Default (Current)	Logger_ForContext	.NET 6.0	.NET 6.0	460.96 ns	4.398 ns	4.113 ns
Case Sensitive/Default (Current)	Logger_ForContext	.NET 8.0	.NET 8.0	313.29 ns	2.276 ns	2.129 ns
Ordinal (Explicit)	Logger_ForContext	.NET 6.0	.NET 6.0	468.31 ns	5.497 ns	5.142 ns
Ordinal (Explicit)	Logger_ForContext	.NET 8.0	.NET 8.0	320.15 ns	4.472 ns	4.183 ns
OrdinalIgnoreCase (Proposed)	Logger_ForContext	.NET 6.0	.NET 6.0	485.5 ns	4.53 ns	4.02 ns
OrdinalIgnoreCase (Proposed)	Logger_ForContext	.NET 8.0	.NET 8.0	325.0 ns	2.09 ns	1.74 ns
Case Sensitive/Default (Current)	LevelOverrideMap_GetEffectiveLevel	.NET 6.0	.NET 6.0	106.44 ns	0.851 ns	0.796 ns
Case Sensitive/Default (Current)	LevelOverrideMap_GetEffectiveLevel	.NET 8.0	.NET 8.0	73.03 ns	0.602 ns	0.503 ns
Ordinal (Explicit)	LevelOverrideMap_GetEffectiveLevel	.NET 6.0	.NET 6.0	116.05 ns	1.100 ns	1.029 ns
Ordinal (Explicit)	LevelOverrideMap_GetEffectiveLevel	.NET 8.0	.NET 8.0	88.33 ns	0.886 ns	0.829 ns
OrdinalIgnoreCase (Proposed)	LevelOverrideMap_GetEffectiveLevel	.NET 6.0	.NET 6.0	136.5 ns	1.49 ns	1.39 ns
OrdinalIgnoreCase (Proposed)	LevelOverrideMap_GetEffectiveLevel	.NET 8.0	.NET 8.0	102.1 ns	1.18 ns	1.11 ns

Things to notice:

• I'm on a Mac, so I can't benchmark .NET desktop framework. I also couldn't get netcoreapp3.1 or lower to work for reasons I can get into at another time. I'll submit a PR to update a few things in the build and explain it there.
• .NET 8 is definitely faster than .NET 6, consistently.
• Explicitly specifying case-sensitivity doesn't change anything.
• Specifying case-insensitivity has a non-zero perf impact, but it's only really obvious the closer you get to GetEffectiveLevel, and it's on the order of 20ns. The benchmark runs GetEffectiveLevel on nine different contexts, so that's about 2ns per lookup, averaged out.

If my logic is sound, that basically means it's a question of whether case-insensitivity is worth a 2ns hit per level lookup.

My opinion is that it's a pretty negligible hit to make this consistent across config and logging, but it is a microperf (nanoperf?) hit, so that may make a difference.

Let me know if I should still look at benchmarks for just the string methods.

[nblumhardt]

Awesome, thanks for doing this @tillig.

It's a bit tricky to draw precise conclusions from the benchmark because it mixes results from a variety of cases (some where the logger triggers an override immediately - which bails out of the check early - some where it doesn't, or will trigger further down the list).

It thus might be that the ~20ns you mention is attributable to one or two of the cases, and not across the board. Just making a note of this, and thinking we might want to tweak the benchmark in the future, but at first glance the difference isn't enough to rule out the change 👍

There's also the possibility that we might be able to improve the performance of the level override map with some other tricks, such as computing a pre-filter based on the first character or two from the context name.

E.g. if my overrides are System.... and Microsoft...., Serilog could potentially skip the lookup for any context that doesn't start with s or m. Regex has some optimizations for doing these kinds of things that could be leveraged - we'd probably have to go that far to beat the vectorized string ops that are likely being used behind StartsWith and friends 🤔

I wouldn't suggest trying to roll this into the case-insensitivity PR, but could be worth keeping up our sleeves.