Runtime: Performance regression: DateTime.UtcNow and DateTimeOffset.UtcNow 2.5x slower

[adamsitnik]

DateTime.UtcNow and DateTimeOffset.UtcNow are 2.5x slower compared to 2.2

[Benchmark]
public DateTimeOffset GetUtcNow() => DateTimeOffset.UtcNow;

[Benchmark]
public DateTime GetUtcNow() => DateTime.UtcNow;

Repro

git clone https://github.com/dotnet/performance.git
cd performance
# if you don't have cli installed and want python script to download the latest cli for you
py .\scripts\benchmarks_ci.py -f netcoreapp2.2 netcoreapp3.0 --filter *GetUtcNow*
# if you do
dotnet run -p .\src\benchmarks\micro\MicroBenchmarks.csproj -c Release -f netcoreapp2.2 --filter *GetUtcNow* --runtimes netcoreapp2.2 netcoreapp3.0 --join

BenchmarkDotNet=v0.11.3.1003-nightly, OS=Windows 10.0.18362
Intel Xeon CPU E5-1650 v4 3.60GHz, 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=3.0.100-preview8-013262
   [Host]     : .NET Core 2.2.6 (CoreCLR 4.6.27817.03, CoreFX 4.6.27818.02), 64bit RyuJIT
   Job-BYJCMJ : .NET Core 2.2.6 (CoreCLR 4.6.27817.03, CoreFX 4.6.27818.02), 64bit RyuJIT
   Job-JSSCYO : .NET Core 3.0.0-preview8-27916-02 (CoreCLR 4.700.19.36302, CoreFX 4.700.19.36514), 64bit RyuJIT

| Type | Method | Toolchain | Mean |
|-------------------- |---------- |-------------- |---------:|
| Perf_DateTime | GetUtcNow | netcoreapp2.2 | 25.12 ns |
| Perf_DateTime | GetUtcNow | netcoreapp3.0 | 70.91 ns |
| | | | |
| Perf_DateTimeOffset | GetUtcNow | netcoreapp2.2 | 38.19 ns |
| Perf_DateTimeOffset | GetUtcNow | netcoreapp3.0 | 91.96 ns |

/cc @danmosemsft

[EgorBo]

I guess it's a cost of https://github.com/dotnet/coreclr/pull/21420 (leap seconds support)

[adamsitnik]

/cc @billwert @DrewScoggins

[stephentoub]

I guess it's a cost of dotnet/coreclr#21420 (leap seconds support)

It is. You can see this pretty clearly by just setting s_systemSupportsLeapSeconds to false.

On my machine it ends up being true:

| Method | Toolchain | Mean | Error | StdDev | Ratio |
|------------------------ |-------------- |---------:|----------:|----------:|------:|
| GetDateTimeOffsetUtcNow | netcoreapp2.1 | 32.22 ns | 0.1057 ns | 0.0989 ns | 1.00 |
| GetDateTimeOffsetUtcNow | netcoreapp3.0 | 71.98 ns | 0.5065 ns | 0.4490 ns | 2.24 |

and when I set it to false:

| Method | Toolchain | Mean | Error | StdDev | Ratio |
|------------------------ |-------------- |---------:|----------:|----------:|------:|
| GetDateTimeOffsetUtcNow | netcoreapp2.1 | 32.18 ns | 0.0193 ns | 0.0180 ns | 1.00 |
| GetDateTimeOffsetUtcNow | netcoreapp3.0 | 31.91 ns | 0.0373 ns | 0.0349 ns | 0.99 |

I think that probably makes this "by design", but @tarekgh should comment.

[danmosemsft]

Might be worth seeing whether we can reduce the cost though, if that wasn't already done at the time.

[tarekgh]

Yes this is expected because of the leap seconds support.

Might be worth seeing whether we can reduce the cost though, if that wasn't already done at the time.

I already looked at that before and what we have the best we can have now till we get more new Windows APIs which may help.

[danmosemsft]

Fair enough.

[tarekgh]

@stephentoub also reminded me about, there is a way to disable the leap seconds handling on the machine. That should give the perf back if anyone really sensitive to that.

https://techcommunity.microsoft.com/t5/Networking-Blog/Leap-Seconds-for-the-IT-Pro-What-you-need-to-know/ba-p/339811

However, if you have a heterogenous time-sensitive environment you can revert to the prior operating system behavior and disable leap seconds across the board by adding the following registry key:

HKLM:\SYSTEM\CurrentControlSet\Control\LeapSecondInformation

 Type : "REG_DWORD"
Name : Enabled
Value : 0 Disables the system-wide setting
Value : 1 Enables the system-wide setting

[EgorBo]

@tarekgh maybe these two calls can be merged into a single internal call? https://github.com/dotnet/coreclr/blob/master/src/System.Private.CoreLib/shared/System/DateTime.Windows.cs#L21-L22

[tarekgh]

@EgorBo I don't think this will make much difference. The second call is inlined anyway.

https://github.com/dotnet/coreclr/blob/7f1dd83ddb159e2469b85145f228fa60ab3682e2/src/System.Private.CoreLib/shared/System/DateTime.Windows.cs#L67

[tarekgh]

I moved this to future milestone for now. feel free to bring it back if you feel otherwise.

[EgorBo]

Also, maybe it makes sense to introduce a COMPlus_LeapSecondsSupport env variable to be able to turn that behavior off for a specific app?

[tarekgh]

Also, maybe it makes sense to introduce a COMPlus_LeapSecondsSupport env variable to be able to turn that behavior off for a specific app?

That is will not be good because if the system support leap seconds and we disable the handling in the framework, you will start seeing time difference between what we report and what the system report (when calling Now functionality). the framework has to comply with what the system is doing.

[adamsitnik]

Just to make sure I confirm that OSes other than Windows are not affected:

System.Tests.Perf_DateTime.GetUtcNow

| conclusion | Base | Diff | Base/Diff | Modality | Base Runtime | Diff Runtime | Arch | Processor Name | Operating System |
| ---------- | -----:| ------:| ---------:| -------- | --------------- | --------------------------------- | ----- | ------------------------------------------- | -------------------- |
| Same | 20.13 | 20.02 | 1.01 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Xeon CPU E5-1650 v4 3.60GHz | ubuntu 18.04 |
| Slower | 23.90 | 68.20 | 0.35 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Xeon CPU E5-1650 v4 3.60GHz | Windows 10.0.18362 |
| Same | 38.28 | 37.29 | 1.03 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-01 | 64bit | Intel Xeon CPU E5-2673 v4 2.30GHz | ubuntu 16.04 |
| Same | 39.22 | 38.84 | 1.01 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-01 | 64bit | Intel Xeon CPU E5-2673 v4 2.30GHz | ubuntu 18.04 |
| Same | 34.76 | 34.66 | 1.00 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Core i7-5557U CPU 3.10GHz (Broadwell) | macOS Mojave 10.14.5|
| Slower | 25.93 | 77.56 | 0.33 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Core i7-5557U CPU 3.10GHz (Broadwell) | Windows 10.0.18362 |
| Slower | 21.10 | 63.59 | 0.33 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Core i7-7700 CPU 3.60GHz (Kaby Lake) | Windows 10.0.18362 |
| Slower | 34.39 | 81.64 | 0.42 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | AMD Ryzen 7 1800X | Windows 10.0.18362 |
| Slower | 33.98 | 136.04 | 0.25 | several? | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 32bit | Intel Xeon CPU E5-1650 v4 3.60GHz | Windows 10.0.18362 |

System.Tests.Perf_DateTimeOffset.GetUtcNow

| conclusion | Base | Diff | Base/Diff | Modality | Base Runtime | Diff Runtime | Arch | Processor Name | Operating System |
| ---------- | -----:| ------:| ---------:| --------:| --------------- | --------------------------------- | ----- | ------------------------------------------- | -------------------- |
| Same | 40.62 | 38.68 | 1.05 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Xeon CPU E5-1650 v4 3.60GHz | ubuntu 18.04 |
| Slower | 36.06 | 79.45 | 0.45 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Xeon CPU E5-1650 v4 3.60GHz | Windows 10.0.18362 |
| Same | 69.96 | 69.97 | 1.00 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-01 | 64bit | Intel Xeon CPU E5-2673 v4 2.30GHz | ubuntu 16.04 |
| Faster | 73.01 | 68.54 | 1.07 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-01 | 64bit | Intel Xeon CPU E5-2673 v4 2.30GHz | ubuntu 18.04 |
| Same | 59.95 | 57.15 | 1.05 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Core i7-5557U CPU 3.10GHz (Broadwell) | macOS Mojave 10.14.5|
| Slower | 40.69 | 92.05 | 0.44 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Core i7-5557U CPU 3.10GHz (Broadwell) | Windows 10.0.18362 |
| Slower | 31.87 | 74.86 | 0.43 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | Intel Core i7-7700 CPU 3.60GHz (Kaby Lake) | Windows 10.0.18362 |
| Slower | 47.93 | 97.43 | 0.49 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 64bit | AMD Ryzen 7 1800X | Windows 10.0.18362 |
| Slower | 66.75 | 158.34 | 0.42 | | .NET Core 2.2.6 | .NET Core 3.0.0-preview8-27919-09 | 32bit | Intel Xeon CPU E5-1650 v4 3.60GHz | Windows 10.0.18362 |

[adamsitnik]

@tarekgh I am currently profiling all the issues that I've reported in the last few weeks and I want to get a better understanding of how we've implemented leap second support. Please excuse me if my questions are dummy ;)

In the profiles for 3.0 the most expensive method is FileTimeToSystemTime which is a mapping from FileTime to SystemTime:

In 2.2 this method was not used.

From the callstack and the code I can see that:

1. The FileTime is obtained from a call to kernelbase!GetSystemTimePreciseAsFileTime which internally calls ntdll!RtlGetSystemTimePrecise
2. FileTime is mapped to SystemTime using kernelbase!FileTimeToSystemTime. This is very expensive
3. If systemTime.wSecond > 59 then it's the leap second case and few important fields are set to some certain values (this is fast)

My questions:

1. Why don't we just call ntdll!RtlGetSystemTimePrecise which presumably returns a SystemTime and would allow us to avoid the expensive mapping? Does the mapping itself contains the expensive leap second support logic?
2. Would calling GetSystemTime instead getting the FileTime and mapping it to a SystemTime reduce the time it takes to get it? I can see that today it's a fallback when the mapping fails.
3. Would it be possible to move the > 59 seconds check to managed code and move the edge case (user calls DateTime.UtcNow exactly when the leap second happens) from the hot path?

public static DateTime UtcNow
{
    get
    {
        long ticks = 0;
        ticks = GetSystemTimeAsFileTime();

        DateTime result = new DateTime(((ulong)(ticks + FileTimeOffset)) | KindUtc);

        int second = result.Second;
        if (second > 59)
        {
            result = result.AddSeconds(-second + 59);
        }

        return result;
    }
}

[tarekgh]

@adamsitnik

Here is some clarifications may help explaining why we did what that. there are 2 conditions we need to do when reporting the time through UtcNow:

• The reported time has to be precise (up to 100-nanoseconds)
• The reported time has to be exact with the underlying system.

DateTime in general encapsulate the time as ticks which are the number of the 100 nanoseconds with the notion the minutes are always 60 seconds ( 0 to 59). i.e. we never have second dotnet/runtime#3880 at all. This design we cannot change because many apps today depends on that and they use ticks directly and always assuming the minute is 60 seconds when doing any manual conversion to time parts (hours, minutes, seconds...etc.). changing this design will be a major app compat concern and systems interacting with each others will be no longer can exchange the time because one system can be enabled for leap seconds and other is not. we already discussed that with .NET ship room.

Windows introduced the leap seconds support, which means when any Windows system enable the leap seconds, the reported time will include the leap seconds. in other word, the minutes can have 61 seconds when we encounter a leap second. That means when we read the time from system, we have to map that to our DateTime which require the minutes always 60 seconds.

Before we did the leap seconds support in .NET, what we used to do is we just call GetSystemTimePreciseAsFileTime which return the time 100 nanoseconds that we just use directly in DateTime (as the ticks) and there is no any conversion needed. When you run on a system support leap seconds and there is already some leap seconds reported in this system, you will start see some shift in the reported .NET time because we converted the ticks came from GetSystemTimePreciseAsFileTime assuming every minute is 60 seconds while this is not the case any more.

To make .NET work with systems have leap seconds enabled, we had 2 options:

• Instead of calling GetSystemTimePreciseAsFileTime we can just call GetSystemTime which will report the time in (hours, minutes, seconds) and then we can convert it to the tick values that can be used in DateTime. obviously the problem here is we are going to lose the precision. our max precision would be milliseconds (compared to current precision which is 100 nanoseconds)
• Or we keep the precision but we'll have some perf hit we take that we convert the reported system ticks to system time (hours, minutes, second) and we still keep the 100 nanoseconds fraction precision. we did that by using FileTimeToSystemTime.

We have chosen the second solution because users cared more about the precision. you can see that on the issue which required us to use GetSystemTimePreciseAsFileTime instead of using GetSystemTimeAsFileTime which we use in the .NET desktop.

Here is the answers for your questions:

Why don't we just call ntdll!RtlGetSystemTimePrecise which presumably returns a SystemTime and would allow us to avoid the expensive mapping? Does the mapping itself contains the expensive leap second support logic?

First, RtlGetSystemTimePrecise is undocumented API which we cannot use. but even if we can use it will not help much because this will give use the time as ticks anyway and we'll still need to convert it. so this is not buying us anything.

Would calling GetSystemTime instead getting the FileTime and mapping it to a SystemTime reduce the time it takes to get it? I can see that today it's a fallback when the mapping fails.

Yes, that is possible but we'll lose the precision which we have tried to not do that in the first place.

Would it be possible to move the > 59 seconds check to managed code and move the edge case (user calls DateTime.UtcNow exactly when the leap second happens) from the hot path?

No, this condition has to be done anyway either in native or manager code, so I don't believe this will make any difference. Also, in the code you are suggesting
C# if (second > 59)

This condition is always false because DateTime never reprot second number greater than 59.

We are asking Windows to expose some API to us something like GetSystemTimePrecise() and return the system time directly with the high precision. That is what I mentioned in my previous comments till we get more new Windows APIs which may help..

[adamsitnik]

@tarekgh thanks for the explanation!