Huge performance difference in string.StartsWith and EndsWith between Linux and Windows for non Invariant, non en-US.

[jskeet]

Very simple code:

using System;
using System.Diagnostics;

namespace ConsoleApplication
{
    public class Program
    {
        public static void Main(string[] args)
        {
            Time(1);
            Time(1000000);
        }

        private static void Time(int iterations)
        {
            var stopwatch = Stopwatch.StartNew();
            for (int i = 0; i < iterations; i++)
            {
                "abcfeg".EndsWith("123");
            }
            stopwatch.Stop();
            Console.WriteLine(stopwatch.Elapsed);
        }
    }
}

The project.json is mostly the default from dotnet new:

{
  "buildOptions": {
    "emitEntryPoint": true,
    "optimize": true
  },
  "frameworks": {
    "netcoreapp1.0": {
      "dependencies": {
        "Microsoft.NETCore.App": {
          "type": "platform",
          "version": "1.0.0-*"
        }
      },
      "imports": "dnxcore50"
    }
  }
}

On both Linux (Ubuntu 15.10 and Ubuntu 16.04) the output is something like:

00:00:00.0003456
00:00:05.2664877

On Windows, on the same hardware, it's:

00:00:00.0000506
00:00:00.1633352

Version info: .NET Command Line Tools (1.0.0-preview1-002702) on Windows and Ubuntu 15.10; 1.0.0-preview2-002886 on Ubuntu 16.04.

Note that under NUnit, every equality assertion involves three EndsWith calls, making NUnit assertions basically horrifically expensive on Linux...

[stephentoub]

cc: @ellismg

Interesting. I don't have that exact set up handy, but on Ubuntu 14.04 with CLI 1.0.0-preview2-002853 and relatively recent rc3 builds, I see:

stoub@stoublinux2:~/tmp3$ dotnet run
Project tmp3 (.NETCoreApp,Version=v1.0) was previously compiled. Skipping compilation.
00:00:00.0002493
00:00:00.0464325
stoub@stoublinux2:~/tmp3$ dotnet run
Project tmp3 (.NETCoreApp,Version=v1.0) was previously compiled. Skipping compilation.
00:00:00.0002399
00:00:00.0572944
stoub@stoublinux2:~/tmp3$ dotnet run
Project tmp3 (.NETCoreApp,Version=v1.0) was previously compiled. Skipping compilation.
00:00:00.0002480
00:00:00.0502375
stoub@stoublinux2:~/tmp3$ dotnet run
Project tmp3 (.NETCoreApp,Version=v1.0) was previously compiled. Skipping compilation.
00:00:00.0004543
00:00:00.0643471
stoub@stoublinux2:~/tmp3$ dotnet run
Project tmp3 (.NETCoreApp,Version=v1.0) was previously compiled. Skipping compilation.
00:00:00.0002738
00:00:00.0627142

so much faster than what you're seeing, and actually faster than what I'm seeing on the Windows host, e.g.

00:00:00.0076654
00:00:00.1033137

But... my LANG is en-US. If I do:

export LANG=en-GB

and then run it again, I get numbers much closer to yours:

00:00:00.0002939
00:00:04.8001375

Not a real solution, but as an experiment, @jskeet, if you change your LANG to en-US, do you see a perf improvement?

[ellismg]

If the problem is the LANG setting, then what's happening is that our fast paths for ASCII StartsWith/EndsWith are specific today to en-US and Invariant (see the code here.)

Unlike Windows, having to do a full linguistic StartsWith or EndsWith is slow because we have to construct some ICU searching objects which we can't cache across runs (since the object is specific to a target string you are searching for, and we don't maintain a cache of searcher objects).

For 1.1 we should look at expanding the fast path to work for ASCII strings if the collation rules for the current locale don't tailor anything in the ASCII range, which would allow this fast path to be hit for locales like en-GB.

We could also consider trying to re-implement IndexOf in terms of some lower level ICU primitives that we might be able to cache across calls.

[jskeet]

@stephentoub: Bingo! Yes, with

$ LANG=en-US dotnet run

I get:

00:00:00.0003087
00:00:00.0630077

Applying the same workaround to running my Noda Time tests halves the total test time, too... (That's where all this started.)

[ellismg]

@jskeet Another option (and I'm not sure if this is possible via the interfaces NUnit exposes, a quick glance over the source doesn't give me much hope) is to use Ordinal or OrdinalIgnoreCase, which will ignore all the ICU gunk.

[jskeet]

@ellismg: The checks here are deep in the bowels of NUnit - but could be fixed very easily with a patch. It's unfortunate that it's necessary, but it feels like a good practical solution to a very real issue. Will file a feature request now...

[ellismg]

@jskeet Thanks! I very much expect we will do the extension of the ASCII fast paths for 1.1, but we may be in a world where linguistic StartsWith and EndsWith are slower for non ASCII strings or strings where collation for ASCII characters differs (e.g tr-TR) because of how this stuff is implemented in terms of ICU, so if we can upstream general goodness changes to force ordinal comparisions when you don't need linguistic behavior that would be great.

[jskeet]

Yup. Would be good if every call to Assert.AreEqual didn't need to do so much work in general, but that's a matter for another day :) Fingers crossed we can get this into NUnit quickly - it seems about as trivial a fix as one could wish for given the crazy perf benefits. (Admittedly Noda Time may be slightly unusual in its number of assertions...)

[wpostma]

Given how disgusting and unexpected such ICU regressions are likely to be, could there be a syntax added to .net core that lets you specify ie StartsWith(arg, forceAscii:true) ?

[jskeet]

@wpostma: What would forceAscii do? There's already string.StartsWith(string, StringComparison) so you can specify an ordinal comparison, which is precisely what I'm proposing in NUnit.

[wpostma]

Um, forget I suggested that. :-)

[gkhanna79]

@ellismg Is this actionable for 1.1.0?

[mazong1123]

Anyone working on this issue? If not I have time to take a look.

[janvorli]

@mazong1123 that would be great! Thank you. No-one is assigned, so that means no-one is working on this. I've just assigned you.

[mazong1123]

Today I investigate a little bit of the related source code. Just put my learning here:

There're two path for the EndsWith comparison:

• Slow path: https://github.com/dotnet/coreclr/blob/master/src/mscorlib/src/System/Globalization/CompareInfo.Unix.cs#L283 It would call https://github.com/dotnet/coreclr/blob/master/src/mscorlib/shared/Interop/Unix/System.Globalization.Native/Interop.Collation.cs#L38 Ultimately goes to native function GlobalizationNative_EndsWith https://github.com/dotnet/coreclr/blob/ce9bc942510fc9608c24e938f6d043c39fd0085d/src/corefx/System.Globalization.Native/collation.cpp#L634 It has some search operations which slow down the performance.

• Fast path: https://github.com/dotnet/coreclr/blob/master/src/mscorlib/src/System/Globalization/CompareInfo.Unix.cs#L280 The fast path would not go to GlobalizationNative_EndsWith. It either goes to https://github.com/dotnet/coreclr/blob/ce9bc942510fc9608c24e938f6d043c39fd0085d/src/mscorlib/src/System/String.Comparison.cs#L798 or https://github.com/dotnet/coreclr/blob/ce9bc942510fc9608c24e938f6d043c39fd0085d/src/mscorlib/src/System/String.Comparison.cs#L801 Ultimately goes to https://github.com/dotnet/coreclr/blob/9a405f2f61e477fc8964ded0788d4c20a1abd8da/src/classlibnative/bcltype/stringnative.cpp#L283 or https://github.com/dotnet/coreclr/blob/master/src/mscorlib/src/System/Globalization/CompareInfo.cs#L476 It avoids the search operations in the slow path so its performance is better.

[danmoseley]

@mazong1123 have you had a chance to look further?

[mazong1123]

@danmosemsft sorry I'm afraid I don't have so much time for working on this issue right now. I'm busy with my day job and for .NET Core I'm only focusing on https://github.com/dotnet/coreclr/pull/14646

However, I can support anyone who wants to work on this issue in my spare time.

[ghost]

I have noticed this issue when running netcore code along side mono:

var x = System.IO.File.ReadAllText("/tmp/test/random25charstring.txt");
for (int i=0; i< 900000; i++) {
    if (x.StartsWith("notlong/")) { Console.WriteLine("Yes");}

The above code takes 6 seconds on my PC with 2.1.300-preview1-008174, and 370 milliseconds on mono. Interestingly, when I change my LANG to en-US, it takes 7 seconds (my default is en_AU.UTF-8).

The fix as mentioned above is to add Ordinal as the string comparison option:

if (x.StartsWith("notlong/",StringComparison.Ordinal))

This brings it back down to an acceptable 31 milliseconds on my PC.

[mikes-gh]

Just scratched my head for hours on this. Was running a console app with a 30,000 record iteration with multiple string.EndsWith checks. on windows it was fine on linux it killed the CPU and was much slower.

CentOS 7.7-1908

# echo $LANG
en_GB.UTF-8
# 

[adamsitnik]

@mikes-gh which version of .NET Core are you using?

[mikes-gh]

<TargetFramework>netcoreapp3.1</TargetFramework>

# dotnet --info
  It was not possible to find any installed .NET Core SDKs
  Did you mean to run .NET Core SDK commands? Install a .NET Core SDK from:
      https://aka.ms/dotnet-download

Host (useful for support):
  Version: 3.1.1
  Commit:  a1388f194c

.NET Core SDKs installed:
  No SDKs were found.

.NET Core runtimes installed:
  Microsoft.AspNetCore.App 3.1.1 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.2.8 [/usr/share/dotnet/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.1 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
  https://aka.ms/dotnet-download
# 

[iSazonov]

I think the issue should be re-reviewed since we moved to ICU on Windows.

[adamsitnik]

dotnet/coreclr#26759 and dotnet/coreclr#26621 combined together have fixed this issue. The PRs were merged in September and October 2019 so they did not make it to .NET Core 3.1, but they are part of the 5.0 release.

I've run these benchmarks from the dotnet/performance repository to verify that:

git clone https://github.com/dotnet/performance
cd performance
python3 ./scripts/benchmarks_ci.py -f netcoreapp3.1 --filter '*StringSearch*Is*'
python3 ./scripts/benchmarks_ci.py -f netcoreapp5.0 --filter '*StringSearch*Is*'

BenchmarkDotNet=v0.12.1, OS=ubuntu 18.04
Intel Xeon CPU E5-1650 v4 3.60GHz, 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=5.0.100-preview.6.20318.15
  [Host]     : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT
  Job-OKAAXU : .NET Core 3.1.5 (CoreCLR 4.700.20.26901, CoreFX 4.700.20.27001), X64 RyuJIT
  Job-QELOCB : .NET Core 5.0.0 (CoreCLR 5.0.20.30506, CoreFX 5.0.20.30506), X64 RyuJIT

Method	Runtime	Options	Mean	Ratio	Allocated
IsPrefix_FirstHalf	.NET Core 3.1	(pl-PL, None, False)	17,821.369 ns	1.00	-
IsPrefix_FirstHalf	.NET Core 5.0	(pl-PL, None, False)	3,723.045 ns	0.21	-
IsPrefix_DifferentFirstChar	.NET Core 3.1	(pl-PL, None, False)	30,629.231 ns	1.000	-
IsPrefix_DifferentFirstChar	.NET Core 5.0	(pl-PL, None, False)	287.086 ns	0.009	-
IsSuffix_SecondHalf	.NET Core 3.1	(pl-PL, None, False)	19,515.456 ns	1.00	-
IsSuffix_SecondHalf	.NET Core 5.0	(pl-PL, None, False)	5,292.733 ns	0.27	-
IsSuffix_DifferentLastChar	.NET Core 3.1	(pl-PL, None, False)	35,581.039 ns	1.00	-
IsSuffix_DifferentLastChar	.NET Core 5.0	(pl-PL, None, False)	385.417 ns	0.01	-

The pl-PL culture is just sample culture that is not using the en* cultures execution path. For cases where there is a match, the code is on average 4-5 times faster. For cases where there is a mismatch in first|last character, the code is up to 100 times faster.