Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

System.Tests.Perf_DateTime.GetNow gets slower every summer due to daylight savings #67932

Open
dakersnar opened this issue Apr 12, 2022 · 11 comments
Assignees
Labels
area-System.DateTime help wanted [up-for-grabs] Good issue for external contributors tenet-performance Performance related issue
Milestone

Comments

@dakersnar
Copy link
Contributor

System.Tests.Perf_DateTime.GetNow has regressed across multiple configurations.

Reporting System:

image

Looking at the commit diff, #66282 seems to be to blame.

Repro:

git clone https://github.com/dotnet/performance.git
py .\performance\scripts\benchmarks_monthly.py net7.0-preview2 net7.0-preview3 --filter System.Tests.Perf_DateTime.GetNow 
## System.Tests.Perf_DateTime.GetNow
Result Base Diff Ratio Operating System Bit Processor Name
Same 112.05 114.53 0.98 Windows 10 X64 Intel Xeon CPU E5-1650 v4 3.60GHz
Same 93.72 99.81 0.94 Windows 11 X64 AMD Ryzen Threadripper PRO 3945WX 12-Cores
Slower 73.98 83.75 0.88 Windows 11 X64 AMD Ryzen 9 5900X
Same 131.78 149.14 0.88 Windows 11 X64 Intel Core i5-4300U CPU 1.90GHz (Haswell)
Same 118.61 116.32 1.02 Windows 11 X64 Unknown processor
Same 88.62 86.35 1.03 Windows 11 X64 Intel Core i7-8700 CPU 3.20GHz (Coffee Lake)
Same 103.63 99.92 1.04 Windows 11 X64 Intel Core i9-9900T CPU 2.10GHz
Same 372.20 380.11 0.98 alpine 3.13 X64 Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)
Same 66.48 65.91 1.01 centos 7 X64 Intel Xeon CPU E5530 2.40GHz
Slower 416.66 472.23 0.88 debian 11 X64 Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)
Slower 70.55 139.81 0.50 ubuntu 18.04 X64 Intel Xeon CPU E5-1650 v4 3.60GHz
Same 198.80 190.36 1.04 ubuntu 18.04 X64 Intel Core i7-2720QM CPU 2.20GHz (Sandy Bridge)
Same 240.11 241.49 0.99 alpine 3.12 Arm64 Unknown processor
Same 243.79 242.33 1.01 ubuntu 18.04 Arm64 Unknown processor
Slower 169.90 191.41 0.89 Windows 10 Arm64 Microsoft SQ1 3.0 GHz
Slower 169.84 194.79 0.87 Windows 11 Arm64 Microsoft SQ1 3.0 GHz
Same 403.45 402.18 1.00 Windows 10 X86 Intel Xeon CPU E5-1650 v4 3.60GHz
Slower 244.43 272.36 0.90 Windows 11 X86 AMD Ryzen Threadripper PRO 3945WX 12-Cores
Same 669.31 771.68 0.87 Windows 11 X86 Intel Core i7-10510U CPU 1.80GHz
Same 294.33 296.09 0.99 Windows 7 SP1 X86 Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)
Same 766.67 714.33 1.07 ubuntu 18.04 Arm ARMv7 Processor rev 3 (v7l)
Slower 1358.46 1709.54 0.79 Windows 10 Arm Microsoft SQ1 3.0 GHz
Slower 94.22 169.26 0.56 macOS Monterey 12.2.1 X64 Intel Core i7-5557U CPU 3.10GHz (Broadwell)
Same 162.60 158.64 1.02 macOS Monterey 12.3.1 X64 Intel Core i7-4870HQ CPU 2.50GHz (Haswell)
@dakersnar dakersnar added the tenet-performance Performance related issue label Apr 12, 2022
@dotnet-issue-labeler
Copy link

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.

@dotnet-issue-labeler dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label Apr 12, 2022
@EgorBo
Copy link
Member

EgorBo commented Apr 12, 2022

This is expected, DateTime.Now regresses and improves once a year at fixed dates due to DST ;-) https://twitter.com/EgorBo/status/1460697206667763714

@danmoseley
Copy link
Member

danmoseley commented Apr 12, 2022

this code only runs when we're in DST: https://github.com/dotnet/runtime/blob/67761043f1b0e1514a1b8c1c6d99a353737a24a1/src/libraries/System.Private.CoreLib/src/System/TimeZoneInfo.cs#L1383-L1412

But, that doesn't seem like much. would need profiling.

@EgorBo
Copy link
Member

EgorBo commented Apr 12, 2022

@danmoseley I don't think it executes that code as part of DateTime.Now, I assume the regression is internal in kernel32

@EgorBo
Copy link
Member

EgorBo commented Apr 12, 2022

oh, or maybe it does?
image

@danmoseley
Copy link
Member

danmoseley commented Apr 13, 2022

Is that with DST, or without? If GetDatePart is larger in DST, then it's perhaps because it's getting Year out of the DateTime in that block. The code before already gets Day and Month and Year, though. I wonder if there is opportunity to have GetDatePart() return all of those together rather than repeat its work. (Edit - I see that's GetDate())

is the codegen for GetDatePart() reasonable?

@EgorBo
Copy link
Member

EgorBo commented Apr 13, 2022

Ah, ignore my flamegraph - it's for my local time where we don't have daylight savings. When I change my tz to the pacific one I now see a different picture - it seems there are quite a few things to optimize
image

is the codegen for GetDatePart() reasonable?

more or less, but we might need to extract it for Year separately since it's on a hot path and inline into Year property.
Also, it's executed from 3 different places in this flamegraph

@EgorBo EgorBo added this to the 7.0.0 milestone Apr 13, 2022
@ghost
Copy link

ghost commented Apr 13, 2022

Tagging subscribers to this area: @dotnet/area-system-runtime
See info in area-owners.md if you want to be subscribed.

Issue Details

System.Tests.Perf_DateTime.GetNow has regressed across multiple configurations.

Reporting System:

image

Looking at the commit diff, #66282 seems to be to blame.

Repro:

git clone https://github.com/dotnet/performance.git
py .\performance\scripts\benchmarks_monthly.py net7.0-preview2 net7.0-preview3 --filter System.Tests.Perf_DateTime.GetNow 
## System.Tests.Perf_DateTime.GetNow
Result Base Diff Ratio Operating System Bit Processor Name
Same 112.05 114.53 0.98 Windows 10 X64 Intel Xeon CPU E5-1650 v4 3.60GHz
Same 93.72 99.81 0.94 Windows 11 X64 AMD Ryzen Threadripper PRO 3945WX 12-Cores
Slower 73.98 83.75 0.88 Windows 11 X64 AMD Ryzen 9 5900X
Same 131.78 149.14 0.88 Windows 11 X64 Intel Core i5-4300U CPU 1.90GHz (Haswell)
Same 118.61 116.32 1.02 Windows 11 X64 Unknown processor
Same 88.62 86.35 1.03 Windows 11 X64 Intel Core i7-8700 CPU 3.20GHz (Coffee Lake)
Same 103.63 99.92 1.04 Windows 11 X64 Intel Core i9-9900T CPU 2.10GHz
Same 372.20 380.11 0.98 alpine 3.13 X64 Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)
Same 66.48 65.91 1.01 centos 7 X64 Intel Xeon CPU E5530 2.40GHz
Slower 416.66 472.23 0.88 debian 11 X64 Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)
Slower 70.55 139.81 0.50 ubuntu 18.04 X64 Intel Xeon CPU E5-1650 v4 3.60GHz
Same 198.80 190.36 1.04 ubuntu 18.04 X64 Intel Core i7-2720QM CPU 2.20GHz (Sandy Bridge)
Same 240.11 241.49 0.99 alpine 3.12 Arm64 Unknown processor
Same 243.79 242.33 1.01 ubuntu 18.04 Arm64 Unknown processor
Slower 169.90 191.41 0.89 Windows 10 Arm64 Microsoft SQ1 3.0 GHz
Slower 169.84 194.79 0.87 Windows 11 Arm64 Microsoft SQ1 3.0 GHz
Same 403.45 402.18 1.00 Windows 10 X86 Intel Xeon CPU E5-1650 v4 3.60GHz
Slower 244.43 272.36 0.90 Windows 11 X86 AMD Ryzen Threadripper PRO 3945WX 12-Cores
Same 669.31 771.68 0.87 Windows 11 X86 Intel Core i7-10510U CPU 1.80GHz
Same 294.33 296.09 0.99 Windows 7 SP1 X86 Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)
Same 766.67 714.33 1.07 ubuntu 18.04 Arm ARMv7 Processor rev 3 (v7l)
Slower 1358.46 1709.54 0.79 Windows 10 Arm Microsoft SQ1 3.0 GHz
Slower 94.22 169.26 0.56 macOS Monterey 12.2.1 X64 Intel Core i7-5557U CPU 3.10GHz (Broadwell)
Same 162.60 158.64 1.02 macOS Monterey 12.3.1 X64 Intel Core i7-4870HQ CPU 2.50GHz (Haswell)
Author: dakersnar
Assignees: -
Labels:

area-System.Runtime, tenet-performance, untriaged

Milestone: 7.0.0

@EgorBo EgorBo self-assigned this Apr 13, 2022
@EgorBo
Copy link
Member

EgorBo commented Apr 13, 2022

I'll take a look when I have some spare time 🙂

@EgorBo EgorBo modified the milestones: 7.0.0, Future Apr 13, 2022
@ghost ghost removed the untriaged New issue has not been triaged by the area owner label Apr 13, 2022
@danmoseley danmoseley added the help wanted [up-for-grabs] Good issue for external contributors label Aug 16, 2022
@danmoseley danmoseley changed the title System.Tests.Perf_DateTime.GetNow has regressed across multiple configurations System.Tests.Perf_DateTime.GetNow gets slower every summer due to daylight savings Aug 17, 2022
@danmoseley
Copy link
Member

danmoseley commented Aug 20, 2022

I measured the impact locally, including old frameworks for interest. Difference is only about 4% now, in .NET 6 it was 9% which is what the graph above shows from earlier. The recent #72712 will have contributed to that, because the DST path adds calls to Year, Month, Day.

@tarekgh it is OK to assume that timezone rules aren't changing during the lifetime of the process, right? So possibly the current rule and timezone can be cached, and if the timezone matches what was cached, we can continue to use that rule, and maybe short circuit simple cases. I'll leave as help wanted in case someone wants to take a look at some kind of caching of that sort. But otherwise I am not sure it is worth further attention.

BenchmarkDotNet=v0.13.1, OS=Windows 10.0.19044.1889 (21H2)
Intel Core i7-7700 CPU 3.60GHz (Kaby Lake), 1 CPU, 8 logical and 4 physical cores
.NET SDK=7.0.100-rc.2.22419.24
  [Host]     : .NET 7.0.0 (7.0.22.41112), X64 RyuJIT
  Job-CERAHN : .NET 8.0.0 (42.42.42.42424), X64 RyuJIT
  Job-SZEXDU : .NET 6.0.8 (6.0.822.36306), X64 RyuJIT
  Job-BHYKGQ : .NET Core 3.1.28 (CoreCLR 4.700.22.36202, CoreFX 4.700.22.36301), X64 RyuJIT
  Job-NYWNMR : .NET Framework 4.8 (4.8.4510.0), X64 RyuJIT


|            Method |        Job |            Runtime |                                Toolchain |      Mean |    Error |   StdDev | Ratio | RatioSD | Allocated |
|------------------ |----------- |------------------- |----------------------------------------- |----------:|---------:|---------:|------:|--------:|----------:|
| DateTimeNow_NoDST | Job-CERAHN |           .NET 7.0 |                        \main\corerun.exe |  81.67 ns | 1.479 ns | 1.311 ns |  1.00 |    0.00 |         - |
|   DateTimeNow_DST | Job-CERAHN |           .NET 7.0 |                        \main\corerun.exe |  85.09 ns | 0.479 ns | 0.448 ns |  1.04 |    0.02 |         - |
| DateTimeNow_NoDST | Job-SZEXDU |           .NET 6.0 |                                  Default |  94.49 ns | 0.640 ns | 0.567 ns |  1.16 |    0.02 |         - |
|   DateTimeNow_DST | Job-SZEXDU |           .NET 6.0 |                                  Default | 103.12 ns | 0.512 ns | 0.479 ns |  1.26 |    0.02 |         - |
| DateTimeNow_NoDST | Job-BHYKGQ |      .NET Core 3.1 |                                  Default | 215.65 ns | 1.004 ns | 0.890 ns |  2.64 |    0.05 |         - |
|   DateTimeNow_DST | Job-BHYKGQ |      .NET Core 3.1 |                                  Default | 226.76 ns | 1.080 ns | 0.902 ns |  2.78 |    0.04 |         - |
| DateTimeNow_NoDST | Job-NYWNMR | .NET Framework 4.8 |                                  Default | 217.80 ns | 0.855 ns | 0.800 ns |  2.67 |    0.04 |         - |
|   DateTimeNow_DST | Job-NYWNMR | .NET Framework 4.8 |                                  Default | 229.96 ns | 0.847 ns | 0.751 ns |  2.82 |    0.04 |         - |
benchmark
using System;
using System.ComponentModel;
using System.Runtime.InteropServices;
using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Configs;
using BenchmarkDotNet.Environments;
using BenchmarkDotNet.Jobs;
using BenchmarkDotNet.Running;

[MemoryDiagnoser]
public class Program
{
    // run as admin 
    public static void Main(string[] args)
    {
        var config = DefaultConfig.Instance
        .AddJob(Job.Default.WithRuntime(CoreRuntime.Core31))
        .AddJob(Job.Default.WithRuntime(CoreRuntime.Core60))
        .AddJob(Job.Default.WithRuntime(CoreRuntime.CreateForNewVersion("net7.0", ".NET 7.0")))
        .AddJob(Job.Default.WithRuntime(ClrRuntime.Net48));
        BenchmarkSwitcher.FromAssembly(typeof(Program).Assembly).Run(args, config);
    }

    [GlobalSetup(Target = nameof(DateTimeNow_NoDST))]
    public void NoDST() => SetSystemTime(new DateTime(2022, 12, 1)); // assuming US

    [GlobalSetup(Target = nameof(DateTimeNow_DST))]
    public void DST() => SetSystemTime(new DateTime(2022, 6, 1)); // assuming US

    [Benchmark(Baseline = true)]
    public DateTime DateTimeNow_NoDST() => DateTime.Now;

    [Benchmark]
    public DateTime DateTimeNow_DST() => DateTime.Now;

    public void SetSystemTime(DateTime dt)
    {
        SYSTEMTIME st = new SYSTEMTIME();
        st.wYear = (short)dt.Year;
        st.wMonth = (short)dt.Month;
        st.wDay = (short)dt.Day;
        SetSystemTime(ref st);
        int errorCode = Marshal.GetLastWin32Error();
        if (errorCode != 0)
            throw new Win32Exception(errorCode);
    }
    [DllImport("kernel32.dll", SetLastError = true)]
    private static extern bool SetSystemTime(ref SYSTEMTIME st);
}

[StructLayout(LayoutKind.Sequential)]
public struct SYSTEMTIME
{
    public short wYear;
    public short wMonth;
    public short wDayOfWeek;
    public short wDay;
    public short wHour;
    public short wMinute;
    public short wSecond;
    public short wMilliseconds;
}

Here's an idea of where the time is spent. There's not a clear "single place".
image

@tarekgh
Copy link
Member

tarekgh commented Aug 20, 2022

it is OK to assume that timezone rules aren't changing during the lifetime of the process, right?

Not really, users can change the local time zone and clear the cached Local TZ. But we can handle flushing the current rule if the local TZ cache is flushed. By the way, on Windows, we already cache the rule

OffsetAndRule match = s_cachedData.GetOneYearLocalFromUtc(timeYear);

The better idea here is not catching the rule and only cache the UTC offset and when the daylight will change. Doing that will make calculation of the Now much faster and simpler to handle too. I can try that when I get some chance.

@danmoseley danmoseley removed the help wanted [up-for-grabs] Good issue for external contributors label Aug 20, 2022
@danmoseley danmoseley added the help wanted [up-for-grabs] Good issue for external contributors label May 25, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-System.DateTime help wanted [up-for-grabs] Good issue for external contributors tenet-performance Performance related issue
Projects
None yet
Development

No branches or pull requests

5 participants