runtime: Perf: DateTime.Now 3x slower on Linux

Perf test:

[Benchmark]
public void GetNow()
{
    DateTime dt;
    foreach (var iteration in Benchmark.Iterations)
        using (iteration.StartMeasurement())
            for (int i = 0; i < 10000; i++)
            {
                dt = DateTime.Now; dt = DateTime.Now; dt = DateTime.Now;
                dt = DateTime.Now; dt = DateTime.Now; dt = DateTime.Now;
                dt = DateTime.Now; dt = DateTime.Now; dt = DateTime.Now;
            }
}

Linux results:

        <performance runid="System.Runtime.Tests.Perf_DateTime.GetNow-Linux" etl="/home/ianha/uptonogood/results/System.Runtime.Tests.Perf_DateTime.GetNow-Linux.csv">
          <metrics>
            <Duration displayName="Duration" unit="msec" />
          </metrics>
          <iterations>
            <iteration index="0" Duration="65.38629999756813" />
            <iteration index="1" Duration="61.40879999101162" />
            <iteration index="2" Duration="64.916299998760223" />
            <iteration index="3" Duration="55.876999989151955" />
            <iteration index="4" Duration="55.115500003099442" />
            <iteration index="5" Duration="59.215800002217293" />
            <iteration index="6" Duration="55.531300008296967" />
            <iteration index="7" Duration="55.105000004172325" />
            <iteration index="8" Duration="56.883499994874" />
            <iteration index="9" Duration="56.871900007128716" />
            <iteration index="10" Duration="55.777700006961823" />
            <iteration index="11" Duration="54.972599998116493" />
            <iteration index="12" Duration="54.644500002264977" />
            <iteration index="13" Duration="91.604200005531311" />
            <iteration index="14" Duration="56.039199993014336" />
            <iteration index="15" Duration="59.405699998140335" />
            <iteration index="16" Duration="59.423000007867813" />
            <iteration index="17" Duration="60.069600000977516" />
          </iterations>
        </performance>

Windows results:

        <performance runid="System.Runtime.Tests.Perf_DateTime.GetNow-WindowsCore" etl="D:\git\corefx\bin\tests\Windows_NT.AnyCPU.Release\system.runtime.tests\dnxcore50\System.Runtime.Tests.Perf_DateTime.GetNow-WindowsCore.etl">
          <metrics>
            <Duration displayName="Duration" unit="msec" />
          </metrics>
          <iterations>
            <iteration index="0" Duration="20.669701876065005" />
            <iteration index="1" Duration="22.393721341775745" />
            <iteration index="2" Duration="20.51631631751502" />
            <iteration index="3" Duration="20.602132401387848" />
            <iteration index="4" Duration="19.901348566971251" />
            <iteration index="5" Duration="19.689801941610312" />
            <iteration index="6" Duration="19.730571709031551" />
            <iteration index="7" Duration="19.689801941610312" />
            <iteration index="8" Duration="19.4235154886627" />
            <iteration index="9" Duration="20.746394655340168" />
            <iteration index="10" Duration="19.552097062837674" />
            <iteration index="11" Duration="19.373622416643684" />
            <iteration index="12" Duration="19.429217554036313" />
            <iteration index="13" Duration="19.524442045775572" />
            <iteration index="14" Duration="19.493935996026721" />
            <iteration index="15" Duration="19.33256754595368" />
            <iteration index="16" Duration="19.180322400478303" />
            <iteration index="17" Duration="19.447179059963219" />
            <iteration index="18" Duration="19.438911065171396" />
            <iteration index="19" Duration="19.340550437476736" />
            <iteration index="20" Duration="19.799281596783544" />
            <iteration index="21" Duration="19.912752697718361" />
            <iteration index="22" Duration="19.690657251416269" />
            <iteration index="23" Duration="20.093223066793144" />
            <iteration index="24" Duration="20.79058566198546" />
            <iteration index="25" Duration="20.538269269203283" />
            <iteration index="26" Duration="19.73883970382326" />
            <iteration index="27" Duration="20.204128238309977" />
            <iteration index="28" Duration="19.688946631804129" />
            <iteration index="29" Duration="19.661291614742368" />
            <iteration index="30" Duration="19.702916691969449" />
            <iteration index="31" Duration="19.440906788052189" />
            <iteration index="32" Duration="19.573194704719981" />
            <iteration index="33" Duration="19.61653040155943" />
            <iteration index="34" Duration="20.462716903002956" />
            <iteration index="35" Duration="19.710044273686663" />
            <iteration index="36" Duration="19.620806950589667" />
            <iteration index="37" Duration="19.614534678678638" />
            <iteration index="38" Duration="19.191156324688109" />
            <iteration index="39" Duration="19.816957999441911" />
            <iteration index="40" Duration="23.061433197025508" />
            <iteration index="41" Duration="21.294363137743858" />
            <iteration index="42" Duration="21.79243854812853" />
            <iteration index="43" Duration="20.098069822360685" />
            <iteration index="44" Duration="20.516031214246368" />
            <iteration index="45" Duration="21.206551330990351" />
            <iteration index="46" Duration="20.443900087270094" />
            <iteration index="47" Duration="20.521448176351214" />
            <iteration index="48" Duration="20.199281482742435" />
            <iteration index="49" Duration="20.074121147791629" />
            <iteration index="50" Duration="19.988305063918688" />
          </iterations>
        </performance>

About this issue

  • Original URL
  • State: closed
  • Created 9 years ago
  • Comments: 22 (22 by maintainers)

Commits related to this issue

Most upvoted comments

I spent some time in the last few days investigating this issue. I implemented the optimization I discussed above, but it didn’t have any affect on the perf I was seeing.

Using America/Chicago time zone, I still saw:

MacBook Pro
142
143
143
142
143
143
143
143
142
146
142
143
146
142
143
146
142
141
142

Which didn’t affect it at all. So I decided it was time to profile the scenario (which I probably should have done in the beginning to start with).

Here is the trace log from running it on my ubuntu machine. sampleTrace.trace.zip

Very quickly the issue shows itself:

image

So it looks like a lot of time is spent calling AdjustmentRule::Equals and TimeZoneInfo::GetPreviousAdjustmentRule. On Unix, there are many cases when determining if a time is daylight savings, we need to get the “previous rule”.

So I made a simple change to GetPreviousRule to use object.ReferenceEquals and the time dropped dramatically.

MacBook Pro
43
39
40
43
44
44
40
44
43
39
40
39
44
39
39
41
42
39
55

I plan on investigating a full fix tomorrow, but I wanted to get my investigation notes out here, in case someone else wants to look at the perf data, and do some investigation themselves.

Using the above investigation data, I decided to try remembering the AdjustmentRule index whenever calling into GetPreviousAdjustmentRule. See https://github.com/eerhardt/coreclr/commit/1316543e5f1833cf6557db62f03658931e56c4cd.

Running the same micro-benchmark above on my MacBookPro using America/Chicago time zone produces the following:

MacBook Pro
31
28
27
27
27
27
27
32
31
27
29
31
27
29
28
27
27
27
27
27

Which gets us into the range of Windows, which is between 19-22ms on both my machine and @ianhays’s above.

See https://github.com/dotnet/coreclr/pull/10948. With that PR, I think we can declare this bug fixed since we are much closer to Windows perf.