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
- Remember AdjustementRule index Profiling TimeZoneInfo scenarios on Unix shows most of the time being spent in GetPreviousAdjustmentRule. This is because we need to scan all of the AdjustmentRules, lo... — committed to eerhardt/coreclr by eerhardt 7 years ago
- Remember AdjustementRule index Profiling TimeZoneInfo scenarios on Unix shows most of the time being spent in GetPreviousAdjustmentRule. This is because we need to scan all of the AdjustmentRules, lo... — committed to eerhardt/coreclr by eerhardt 7 years ago
- Remember AdjustementRule index Profiling TimeZoneInfo scenarios on Unix shows most of the time being spent in GetPreviousAdjustmentRule. This is because we need to scan all of the AdjustmentRules, lo... — committed to eerhardt/coreclr by eerhardt 7 years ago
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: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:
So it looks like a lot of time is spent calling
AdjustmentRule::Equals
andTimeZoneInfo::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.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: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.