Performance regression in regex matching from RC1 to RC2

[JurjenBiewenga]

Description

Hi,
We've ran into a performance regression in the regex matching/resolving of long strings. The improvements in RC1 great reduced the time to run our log parser (from .net core 3.1) however when running on RC2 the performance seems to be the same or similar to that of .net core 3.1.

This appears to be a runtime regression as the same binary compiled by the RC1 sdk has drastically different results when ran with the RC1 runtime vs the RC2 runtime (using a docker container).

I've included the results of a benchmark.net repro as well as the repository of this repro case.

https://github.com/seriously-digital-entertainment-ltd/Regex-Performance-Regression

RC1

// * Detailed results *
RegexParsingBenchmark.Parse: .NET Core 5.0(Runtime=.NET Core 5.0)
Runtime = .NET Core 5.0.0 (CoreCLR 5.0.20.45114, CoreFX 5.0.20.45114), X64 RyuJIT; GC = Concurrent Workstation
Mean = 1.079 ms, StdErr = 0.001 ms (0.06%), N = 14, StdDev = 0.002 ms
Min = 1.075 ms, Q1 = 1.078 ms, Median = 1.080 ms, Q3 = 1.081 ms, Max = 1.081 ms
IQR = 0.003 ms, LowerFence = 1.074 ms, UpperFence = 1.085 ms
ConfidenceInterval = [1.076 ms; 1.082 ms] (CI 99.9%), Margin = 0.003 ms (0.24% of Mean)
Skewness = -0.76, Kurtosis = 1.9, MValue = 2
-------------------- Histogram --------------------
[1.074 ms ; 1.083 ms) | @@@@@@@@@@@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.12.1, OS=macOS Catalina 10.15.6 (19G2021) [Darwin 19.6.0]
Intel Core i7-9750H CPU 2.60GHz, 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=5.0.100-rc.1.20452.10
  [Host]        : .NET Core 5.0.0 (CoreCLR 5.0.20.45114, CoreFX 5.0.20.45114), X64 RyuJIT
  .NET Core 5.0 : .NET Core 5.0.0 (CoreCLR 5.0.20.45114, CoreFX 5.0.20.45114), X64 RyuJIT

Job=.NET Core 5.0  Runtime=.NET Core 5.0  

| Method |     Mean |     Error |    StdDev |
|------- |---------:|----------:|----------:|
|  Parse | 1.079 ms | 0.0026 ms | 0.0023 ms |

// * Hints *
Outliers
  RegexParsingBenchmark.Parse: .NET Core 5.0 -> 1 outlier  was  removed (1.09 ms)

RC2

// * Detailed results *
RegexParsingBenchmark.Parse: .NET Core 5.0(Runtime=.NET Core 5.0)
Runtime = .NET Core 5.0.0 (CoreCLR 5.0.20.47505, CoreFX 5.0.20.47505), X64 RyuJIT; GC = Concurrent Workstation
Mean = 2.716 s, StdErr = 0.013 s (0.48%), N = 17, StdDev = 0.054 s
Min = 2.635 s, Q1 = 2.694 s, Median = 2.708 s, Q3 = 2.756 s, Max = 2.817 s
IQR = 0.062 s, LowerFence = 2.601 s, UpperFence = 2.849 s
ConfidenceInterval = [2.663 s; 2.768 s] (CI 99.9%), Margin = 0.053 s (1.94% of Mean)
Skewness = 0.23, Kurtosis = 1.97, MValue = 2
-------------------- Histogram --------------------
[2.617 s ; 2.673 s) | @@@@
[2.673 s ; 2.744 s) | @@@@@@@@
[2.744 s ; 2.844 s) | @@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.12.1, OS=macOS Catalina 10.15.6 (19G2021) [Darwin 19.6.0]
Intel Core i7-9750H CPU 2.60GHz, 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=5.0.100-rc.2.20479.15
  [Host]        : .NET Core 5.0.0 (CoreCLR 5.0.20.47505, CoreFX 5.0.20.47505), X64 RyuJIT
  .NET Core 5.0 : .NET Core 5.0.0 (CoreCLR 5.0.20.47505, CoreFX 5.0.20.47505), X64 RyuJIT

Job=.NET Core 5.0  Runtime=.NET Core 5.0  

| Method |    Mean |    Error |   StdDev |
|------- |--------:|---------:|---------:|
|  Parse | 2.716 s | 0.0526 s | 0.0540 s |

// * Hints *
Outliers
  RegexParsingBenchmark.Parse: .NET Core 5.0 -> 3 outliers were removed (2.96 s..3.22 s)

Regression?

Regression from dotnet 5 RC1 to dotnet 5 RC2

[Dotnet-GitSync-Bot]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[stephentoub]

Your regex begins with .*, so this is likely due to the removal of an invalid optimization: #42408. We aim to fix it and put it back in .NET 6 (#42447), but in the meantime, you can do the same thing yourself just by putting a ^ anchor at the beginning of your regex pattern (potentially in combination with using RegexOptions.Multiline, depending on your needs), which is all that optimization was doing for you on your behalf.

Tagging subscribers to this area: @eerhardt, @pgovind, @jeffhandley
See info in area-owners.md if you want to be subscribed.

[stephentoub]

Yeah, I just tried your repro. Your LogParserConfig.txt contains:

warning /.* validate error:/

and with that the test takes ~2.9s. But if I add a ^ so that it contains instead:

warning /^.* validate error:/

then the test takes ~1ms. The cited optimization was just trying to do this automatically for you.

[JurjenBiewenga]

Thanks @stephentoub, a colleague confirmed that does work as well.