Fix to get the correct value for Environment.TickCount in OSX #1269

Sridhar-MS · 2015-07-22T01:57:14Z

On linux monotonic clock API clock_gettime is available. But on OSX the PAL implementation falls back to gettimeofday. This always retured the time elapsed since Unix Epoch (1970/01/01). I fixed it by using the mach API clock_get_time on OSX to get the time elapsed since system start.

Fixes #2441
https://github.com/dotnet/corefx/issues/2441

CC: @stephentoub

On linux monotonic clock API clock_gettime is available. But on OSX the PAL implementation falls back to gettimeofday. This always retured the time elapsed since Unix Epoch (1970/01/01). I fixed it by using the mach API clock_get_time on OSX to get the time elapsed since system start. Fixes #2441 https://github.com/dotnet/corefx/issues/2441

dnfclas · 2015-07-22T01:57:18Z

Hi @Sridhar-MS, I'm your friendly neighborhood .NET Foundation Pull Request Bot (You can call me DNFBOT). Thanks for your contribution!

In order for us to evaluate and accept your PR, we ask that you sign a contribution license agreement. It's all electronic and will take just minutes. I promise there's no faxing. https://cla2.dotnetfoundation.org.

TTYL, DNFBOT;

dnfclas · 2015-07-22T02:05:16Z

@Sridhar-MS, Thanks for signing the contribution license agreement so quickly! Actual humans will now validate the agreement and then evaluate the PR.

Thanks, DNFBOT;

kangaroo · 2015-07-22T09:55:07Z

src/pal/src/misc/time.cpp

+        clock_serv_t clock;
+        mach_timespec_t mts;
+
+        host_get_clock_service(mach_host_self(), SYSTEM_CLOCK, &clock);


This leaks the host port, no? Also, why are you not checking the return value here?

Yes. I missed checking the return value here. But I am deallocating the host port using 'mach_port_deallocate' a bunch of lines below. I need to make it better to deallocate the host port even in case of failing return values. I am working on the fix.

- Add return value check for "host_get_clock_service". - Fix host port leaks in GetTickCount64 and GlobalMemoryStatusEx.

Sridhar-MS · 2015-07-22T19:59:10Z

I did some reference counting experiment on host ports. I discovered that there is one more place in the PAL layer (src/pal/src/misc/sysinfo.cpp) where the host port is leaking. I have fixed it too.

jkotas · 2015-07-22T21:12:03Z

src/pal/src/misc/time.cpp

+        mach_timespec_t mts;
+        host_t host = mach_host_self();
+
+        if((machRet = host_get_clock_service(host, SYSTEM_CLOCK, &clock)) != KERN_SUCCESS)


GetTickCount is expected to be very fast API. Acquiring/releasing the clock service for each call looks pretty expensive. Could you please do some quick performance measuments, and maybe consider caching the clock service?

@jkotas I did some crude performance measurements around Environment.TickCount.
With my changes (no caching) - Average time 3.0 microseconds
Without my changes (using gettimeofday) - Average time 0.13 microseconds.
I am not sure if perf cost is within acceptable level of tolerance. Meanwhile I am also trying to get perf measurements with caching the clock service.

It did my testing on release builds and got the average from 10 million iterations.

const long tccSecondsToMicroSeconds = 1000000; [Fact] public static void TickCountPerf() { int iterations = 10000000; long totalTime = 0; for (int i = 0; i < iterations; i++) { long startTime = GetTimeofDay(); int tick = Environment.TickCount; totalTime += GetTimeofDay() - startTime; } float average = (float)totalTime / iterations; Console.WriteLine("totalTime - {0} usecs", totalTime); Console.WriteLine("Average - {0} usecs", average); } public static long GetTimeofDay() { timeval tv = new timeval(); int result = gettimeofday(ref tv, IntPtr.Zero); return (tv.tv_sec * tccSecondsToMicroSeconds) + tv.tv_usec; } [DllImport("libc")] // provides microsecond level resolution private static extern int gettimeofday(ref timeval tv, IntPtr tz);

@jkotas I also got the results with caching the clock service.
With my changes (no caching) - Average time 3.0 microseconds.
With my changes (with caching) - Average time 0.9 microseconds.
Without my changes (using gettimeofday) - Average time 0.13 microseconds.

There is a minor increase in perf cost even with caching enabled.

The microbenchmark is not right. GetTimeofDay() method should not be called for every iteration because of it is about as expensive as Environment.TickCount that you are trying to measure. It should be called only once before and after the loop:

public static void TickCountPerf() { int iterations = 10000000; long startTime = GetTimeofDay(); for (int i = 0; i < iterations; i++) { int tick = Environment.TickCount; } long totalTime = GetTimeofDay() - startTime; ... }

Once you fix the microbenchmark, I expect that you will get numbers ~0.03 microseconds without your change, and ~3 microseconds with your change. Making Environment.TickCount 100x slower is certainly not within acceptable level of tolerance.

For reference, Environment.TickCount takes less than 0.01 microseconds on Windows.

Thanks for the feedback @jkotas! I updated the benchmark and got the results which are close to the numbers you predicted.

With my changes (no caching) - Average time 2.86 microseconds.
With my changes (with caching) - Average time 0.82 microseconds.
Without my changes (using gettimeofday) - Average time 0.05 microseconds.

So with caching enabled it is around it is around 16.4x slower.

Here is the updated microbench mark

const long tccSecondsToMicroSeconds = 1000000; [Fact] public static void TickCountPerf() { int iterations = 10000000; long startTime = GetTimeofDay(); for (int i = 0; i < iterations; i++) { int tick = Environment.TickCount; } long totalTime = GetTimeofDay() - startTime; float average = (float)totalTime / iterations; Console.WriteLine("totalTime -- {0} usecs", totalTime); Console.WriteLine("Average -- {0} usecs", average); } public static long GetTimeofDay() { timeval tv = new timeval(); int result = gettimeofday(ref tv, IntPtr.Zero); return (tv.tv_sec * tccSecondsToMicroSeconds) + tv.tv_usec; } [DllImport("libc")] private static extern int gettimeofday(ref timeval tv, IntPtr tz); } struct timeval { public long tv_sec; /* seconds since Jan. 1, 1970 */ public long tv_usec; /* and microseconds */ }

caching enabled it is around it is around 16.4x slower

It is better than before, but still ~100x slower compared to Windows...

I have looked around for what is available ... have you considered using mach_absolute_time()? It seems to be the fastest way to get what you want.

Also, I am wondering whether we need to make similar change in other places like https://github.com/dotnet/coreclr/blob/master/src/pal/src/synchmgr/synchmanager.cpp#L4881 to be robust around clock time adjustment (e.g. day light switch). This can be tracked as separate issue.

I am also looking into mach_absolute_time(). I did some initial perf test and I got the Average time down to 0.04 vs 0.05 without my changes. I will keep you updated on that.

mach_absolute_time uses rdtsc

…ach_absolute_time' in GetTickCount64. Monotonic clock function 'clock_get_time' was causing perf regression in 'Environment.TickCount'. So replacing it with 'mach_absolute_time' which gives considerable performance gains. Here are the perf numbers Using 'clock_get_time' (without caching host ports) - Average time 2.86 microseconds. Using 'clock_get_time' (with caching host ports) - Average time 0.82 microseconds. Using 'gettimeofday' (original implementation) - Average time 0.05 microseconds. Using 'mach_absolute_time' - Average time 0.04 microseconds.

Sridhar-MS · 2015-07-24T21:32:06Z

@jkotas Here are the final perf numbers
Using 'clock_get_time' (without caching host ports) - Average time 2.86 microseconds.
Using 'clock_get_time' (with caching host ports) - Average time 0.82 microseconds.
Using 'gettimeofday' (original implementation) - Average time 0.05 microseconds.
Using 'mach_absolute_time' - Average time 0.04 microseconds.

I was initially was not sure if 'mach_absolute_time' was monotonic, so I went ahead with 'clock_get_time'. Now I verified that both 'clock_get_time' and 'mach_absolute_time' return the exact same time elapsed. With that said I replaced the implementation with 'mach_absolute_time' because of the better performance numbers.

jkotas · 2015-07-24T22:45:40Z

src/pal/src/misc/time.cpp

@@ -298,4 +320,4 @@ GetTickCount64()
 #endif // HAVE_CLOCK_MONOTONIC 
 EXIT:    
    return retval;
-}
+}


Could you please add new line at the end of the file?

…nd resolution support for StopWatch in OSX. OSX provides nanosecond timer capabilities. But the PAL was not using it and falling back to microsecond-level resolution.

jkotas · 2015-07-25T03:14:31Z

src/pal/src/misc/time.cpp

 SET_DEFAULT_DEBUG_CHANNEL(MISC);

+static BOOL s_TimeInitialized = FALSE;


This variable should not be needed.

I am new to the PAL source code, so I am trying to follow existing conventions. Example - https://github.com/dotnet/coreclr/blob/master/src/pal/src/exception/machexception.cpp#L74.

So I believe that if you are not freeing any resources in cleanup you dont need an 'init' variable.

jkotas · 2015-07-25T03:19:29Z

LGTM modulo comments

kangaroo · 2015-07-25T03:25:13Z

I mentioned this in a now outdated comment, but mach_absolute_time uses rdtsc. My understanding is TickCount is supposed to be monotonic?

Sridhar-MS · 2015-07-27T17:25:33Z

@kangaroo I had the same concern initially. But in the code we are rounding off nanosecond measurement into milliseconds. This makes the TickCount value to be non-decreasing ie. any jump back and forth by mach_absolute_time is offset by this rounding off.

As an experiment, I ran both mach_absolute_time and monotonic function clock_get_time in a loop for 10 million times and rounding off both values to milliseconds. The value returned by mach_absolute_time was always non-decreasing and same as the value returned by clock_get_time.

kangaroo · 2015-07-27T19:08:03Z

@Sridhar-MS Did you force core migrations, cpu frequency scaling, and S3 power switching?

…in terms of ticks) in OSX. Reference: https://developer.apple.com/library/ios/qa/qa1643/_index.html

Sridhar-MS · 2015-07-27T21:04:25Z

@jkotas Made fixes based on your feedback.
@kangaroo Thanks for the feedback. I have filed an issue #1300 to track it.

Fix to get the correct value for Environment.TickCount in OSX

dotnet-bot added the 2 - In Progress label Jul 22, 2015

dnfclas added the cla-required label Jul 22, 2015

dnfclas added cla-signed and removed cla-required labels Jul 22, 2015

kangaroo reviewed Jul 22, 2015
View reviewed changes

Fix Mach host port leaks in OSX

6bfb7c3

- Add return value check for "host_get_clock_service". - Fix host port leaks in GetTickCount64 and GlobalMemoryStatusEx.

jkotas reviewed Jul 22, 2015
View reviewed changes

jkotas reviewed Jul 24, 2015
View reviewed changes

Move 's_TimebaseInfo' intialization to PAL intialization and nanoseco…

661dd3c

…nd resolution support for StopWatch in OSX. OSX provides nanosecond timer capabilities. But the PAL was not using it and falling back to microsecond-level resolution.

jkotas reviewed Jul 25, 2015
View reviewed changes

Fix to return the right frequency (in ticks per second) and counter (…

d2086d6

…in terms of ticks) in OSX. Reference: https://developer.apple.com/library/ios/qa/qa1643/_index.html

Sridhar-MS added a commit that referenced this pull request Jul 28, 2015

Merge pull request #1269 from Sridhar-MS/osx-tickcount

9553016

Fix to get the correct value for Environment.TickCount in OSX

Sridhar-MS merged commit 9553016 into dotnet:master Jul 28, 2015

dotnet-bot removed the 2 - In Progress label Jul 28, 2015

Sridhar-MS mentioned this pull request Jan 30, 2020

Verify the monotonic nature of Environment.TickCount under various conditions in OSX dotnet/runtime#4394

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix to get the correct value for Environment.TickCount in OSX #1269

Fix to get the correct value for Environment.TickCount in OSX #1269

Sridhar-MS commented Jul 22, 2015

dnfclas commented Jul 22, 2015

dnfclas commented Jul 22, 2015

kangaroo Jul 22, 2015

Sridhar-MS Jul 22, 2015

Sridhar-MS commented Jul 22, 2015

jkotas Jul 22, 2015

Sridhar-MS Jul 24, 2015

Sridhar-MS Jul 24, 2015

jkotas Jul 24, 2015

Sridhar-MS Jul 24, 2015

jkotas Jul 24, 2015

Sridhar-MS Jul 24, 2015

kangaroo Jul 25, 2015

Sridhar-MS commented Jul 24, 2015

jkotas Jul 24, 2015

jkotas Jul 25, 2015

Sridhar-MS Jul 27, 2015

jkotas commented Jul 25, 2015

kangaroo commented Jul 25, 2015

Sridhar-MS commented Jul 27, 2015

kangaroo commented Jul 27, 2015

Sridhar-MS commented Jul 27, 2015

		SET_DEFAULT_DEBUG_CHANNEL(MISC);

		static BOOL s_TimeInitialized = FALSE;

Fix to get the correct value for Environment.TickCount in OSX #1269

Fix to get the correct value for Environment.TickCount in OSX #1269

Conversation

Sridhar-MS commented Jul 22, 2015

dnfclas commented Jul 22, 2015

dnfclas commented Jul 22, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Sridhar-MS commented Jul 22, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Sridhar-MS commented Jul 24, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jkotas commented Jul 25, 2015

kangaroo commented Jul 25, 2015

Sridhar-MS commented Jul 27, 2015

kangaroo commented Jul 27, 2015

Sridhar-MS commented Jul 27, 2015