Timer Finetuning, Each Microsecond Counts

 

This is a one day excursus from my present chart posts, which will continue with my next post.

Exact timing is not an issue for most of us. Who cares if something gets executed a few millisecond earlier or later. Well, this blog was started to highlight many issues of “hard-core” programming. Thus I do care!

Back in 1985, when I was hacking on my Commodore 64, there was no such as Context Switching. To wait for a few moments you could run a loop for a number of times. And when you were running the same loop on the same C64 model again, then you had pretty much the same passed amount of time. The emphasis in on the word “same”. But these days don’t work like that. You never face the “same” situation again. Since the invention of multithreading (in fact it was called multitasking on the good old Commodore Amiga) context switching came into place.

(There are Multimedia Timers in the windows core environment. I am not going to use these. High precision inside the standard .Net framework is possible. There is no need to leave robustness behind.)

I was running several small tests to get a feeling for the .Net timing. The first and most simple approach was using PriorityBoostEnabled on the process to boost the process priority. Unfortunately its use is limited. Your priority only gets boosted, when your main window has the focus. And when your process is on a high priority anyway, it obviously won’t change a lot.
Therefore the next step was to increase the process priority to ‘ProcessPriorityClass.RealTime’. This is a dangerous setting and should only be used by skilled programmers. Your application could consume too much privileged time at the expense of the entire system, which would result in a slowed down execution time for ALL processes and services – including your process that you were originally trying to speed-up.

One important aspect is the PrivilegedProcessorTime. We’ll assume 80 milliseconds, just to have a realistic number. This would imply that the windows system was giving your process 80 ms to execute code before it switched to another process. You have to share this order of magnitude amongst all your threads. 10 ms of these are consumed by your GUI update. Make sure to execute any time sensitive code in one piece before the next context switching takes place.

As we talk about timers, it does not help you at all to be precise on one side, but then lose processor execution time to another thread or process.
Let me come up with a short story. You take the train at exactly 1 pm after waiting for 8 hours. You only have 10 minutes left to get from Austria to Belgium. That sucks, right? You obviously have to start your journey without waiting 8 hours beforehand.
The hard-core scenario would be to get changed, pack your suitcase and sleep until 12:45pm … yes, in your business suit! Then suddenly wake up, jump out of your bed, don’t kiss your wife, run to the station and use the full 8 hours for your journey. You only make it, when you arrive in Brussels before the ticket collector kicks you out, because your ticket was only valid for 8 hours.

 

Let’s delve into practice. In the below example you can see that getting the time-stamp does take about half a tick. When you run a long loop and try to get the time-stamp many times, then it seems to slow down. The reason for this is the context switching. Somewhere in the middle the PrivilegedProcessorTime expired. Therefore running only a few loops can show better results.

The system timer is terribly slow. Its delays and reliability are bad as bad can be. It apparently accepts a double for microseconds rather than the usual long. You would expect a higher resolution then, wouldn’t you?

Especially the first run is unpredictable. The reason for this are the CLR runtime compilation operations. Your code gets compiled shortly before the first execution. You will observe this with any timer. Start your code earlier and skip the first callback. This improves the precision for the first callback you are really waiting for.

The thread timer is more precise, but is firing too early sometimes. Its precision is above one millisecond.

The timer with the most potential isn’t really a timer. It is a thread sleep method in a loop. In my opinion that is the most advanced solution to solve the timer precision problem. The loop is running on a thread. This thread is not shared like on a task scheduler. You own that thread and nobody else will use it. You obviously should not run hundreds of threads. Run 5 of them, and you are still in the green zone. The big advantage is that you can change the priority of this thread to ‘Highest’. This gives you the attention that real geeks need. Furthermore, you won’t have any multiple code executions. There is one event running at a time. If you miss one, because the previous event was running too long, then you can still decide to not execute the next run. A general system delay would then not queue up events that you don’t want to execute anymore … as it is too late anyway. You obviously can add this feature for any timer, but this one is the safest way to easily have only one event running at a time.

Check out my MicroTimer class. It waits a little bit less than required and then calls SpinWait multiple times. Once the process thread gets processor time assigned, you most likely won’t face context switching. You wait like a disciple for the one and only messiah, running around a rigid pole.

The MicroTimer class should give you a whopping precision of 1 microsecond …. unless my usual ‘unless’ sentence states something else 😉
The example output shows the delay at the point when the timer was leaving the inner loop to raise an event. And it shows the delay at the time it recorded the data inside the event. Obviously there are some microseconds in between. Measure that time and adjust your schedule accordingly.

 

Computer Specs:
Lenovo Yoga 2 11”
Intel i5-4202Y 1.6 GHz processor
128GB SSD hard disk
4GB memory
Windows 8.1, 64 bit

 

Admittedly, the code is a bit of Spaghetti style today. Tests are really what they are. It was clear that the MicroTimer would win in the end. So my effort for a proper style went into that direction.

 

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Threading;

namespace TimerPrecisionTest {
	class Program {
		private const long _NumDataPoints = 10;
		private static List<long> _DataPoints = new List<long>();
		private static int _CurrentDataPoint = 0;

		private static long[] _Schedule;

		private static long _PeriodInMs = 3 * Stopwatch.Frequency * 1000;
		private static long _PeriodInTicks = 3 * Stopwatch.Frequency;
		private static double _FrequencyAsDouble = (double)Stopwatch.Frequency;

		private static AutoResetEvent _AutoResetEvent = new AutoResetEvent(false);

		static void Main(string[] args) {
			Process p = Process.GetCurrentProcess();
			p.PriorityBoostEnabled = true;  // every little helps
			p.PriorityClass = ProcessPriorityClass.Normal;
			Console.WriteLine("Process with normal priority:");
			Console.WriteLine("Priviledged processor time for process " + p.ProcessName + " is " + p.PrivilegedProcessorTime.TotalMilliseconds.ToString("#,##0.0") + " ms");
			p.PriorityClass = ProcessPriorityClass.RealTime;
			Console.WriteLine("Process with high priority:");
			Console.WriteLine("Priviledged processor time for process " + p.ProcessName + " is " + p.PrivilegedProcessorTime.TotalMilliseconds.ToString("#,##0.0") + " ms");

			Console.WriteLine("IsHighResolution system clock: " + Stopwatch.IsHighResolution);
			Console.WriteLine("Number of ticks per second: " + Stopwatch.Frequency.ToString("#,##0"));

			long a = Stopwatch.GetTimestamp();
			for (int i = 0; i < 100000; i++) {
				long b = Stopwatch.GetTimestamp();
			}
			long c = Stopwatch.GetTimestamp();
			Console.WriteLine("Number of ticks to obtain a timestamp: " + ((c - a) / 100000.0).ToString("#,##0.00"));
			Console.WriteLine();

			UseSystemTimer();

			UseThreadingTimer();

			// a simple loop
			Thread lThread = new Thread(new ThreadStart(UseLoop));
			lThread.Priority = ThreadPriority.Highest;
			lThread.IsBackground = true;
			lThread.Start();

			_AutoResetEvent.WaitOne();

			testSpinWaitPrecision();

			// a proper loop
			UseMicroTimerClass();

			Console.ReadLine();
		} //

	#region MicroTimer
		private static void UseMicroTimerClass() {
			Console.WriteLine("MICRO TIMER CLASS:");
			Init();
			long lMaxDelay = (3L * Stopwatch.Frequency) / 1000L; // 3 ms
			MicroTimer lMicroTimer = new MicroTimer(new Queue<long>(_Schedule), lMaxDelay);
			lMicroTimer.OnMicroTimer += OnMicroTimer;
			lMicroTimer.OnMicroTimerStop += OnMicroTimerStop;
			lMicroTimer.OnMicroTimerSkipped += OnMicroTimerSkipped;
			lMicroTimer.Start();
		} //

		static void OnMicroTimerSkipped(int xSenderThreadId, long xWakeUpTimeInTicks, long xDelayInTicks) {
			Console.WriteLine("MicroTimer for WakeUpTime " + xWakeUpTimeInTicks + " did not run. Delay was: " + xDelayInTicks);
		} //

		static void OnMicroTimerStop(int xSenderThreadId) {
			Console.WriteLine("MicroTimer stopped.");
			PrintStats();
		} //

		static void OnMicroTimer(int xSenderThreadId, long xWakeUpTimeInTicks, long xDelayInTicks) {
			RecordDatapoint();
			Console.WriteLine("(Delay at wakeup time was " + xDelayInTicks.ToString("#,##0" + " tick)"));
		} //
	#endregion

		#region SpinWait precision
		private static void testSpinWaitPrecision() {
			Console.WriteLine();
			Console.WriteLine("SpinWait tests (neglecting PrivilegedProcessorTime):");
			Thread.CurrentThread.Priority = ThreadPriority.Highest;
			Thread.Sleep(0);  // switch context at a good point
			long a = Stopwatch.GetTimestamp();
			Thread.SpinWait(100000);
			long b = Stopwatch.GetTimestamp();
			Console.WriteLine("Number of ticks for a SpinWait: " + (b - a).ToString("#,##0"));

			a = Stopwatch.GetTimestamp();
			Thread.Sleep(0);
			for (int i = 0; i < 100; i++) {
				Thread.SpinWait(100000);
			}
			b = Stopwatch.GetTimestamp();
			double lAverage = (b - a) / 100.0;
			Console.WriteLine("Average ticks for 100x SpinWaits: " + lAverage.ToString("#,##0") + " == " + (lAverage * 1000.0 * 1000.0/ Stopwatch.Frequency).ToString("#,##0.0000") + " microseconds");

		  // now we do get extremly precise
			long lEndTime = Stopwatch.GetTimestamp() + Stopwatch.Frequency; // wake up in one second
			Thread.Sleep(900); // imagine a timer raises an event roughly 100ms too early
			while (Stopwatch.GetTimestamp() < lEndTime) {
				Thread.SpinWait(10);  // no context switching
			}
			a = Stopwatch.GetTimestamp();
			Console.WriteLine("SpinWait caused an error of just: " + ((a - lEndTime) * 1000.0 * 1000.0 / _FrequencyAsDouble).ToString("#,##0.0000") + " microseconds");
			Thread.CurrentThread.Priority = ThreadPriority.Normal;
			Console.WriteLine();
		} //
		#endregion

		#region simple loop
		private static void UseLoop() {
			Thread.CurrentThread.Priority = ThreadPriority.Highest;
			Console.WriteLine("LOOP AND SLEEP:");
			Init();
			Thread.Sleep((int)getTimeMsToNextCall_Long());

			while (_CurrentDataPoint < _NumDataPoints) {
				RecordDatapoint();
				if (_CurrentDataPoint >= _NumDataPoints) break;
				Thread.Sleep((int)getTimeMsToNextCall_Long());
			}

			PrintStats();
			_AutoResetEvent.Set();
			Thread.CurrentThread.Priority = ThreadPriority.Normal;
		} //
		#endregion

		#region SystemTimer
		private static System.Timers.Timer _SystemTimer = null;
		private static void UseSystemTimer() {
			Console.WriteLine("SYSTEM TIMER:");
			Init();
			_SystemTimer = new System.Timers.Timer();
			_SystemTimer.AutoReset = false;
			_SystemTimer.Elapsed += SystemTimer_Elapsed;
			_SystemTimer.Interval = getTimeMsToNextCall_Double();  // do not init in constructor!
			_SystemTimer.Start();

			_AutoResetEvent.WaitOne();
			_SystemTimer.Stop();
			_SystemTimer = null;

			PrintStats();
		} //

		private static void SystemTimer_Elapsed(object sender, System.Timers.ElapsedEventArgs e) {
			RecordDatapoint();

			// calibrate timer (we did not start with the right interval when we launched it)
			System.Timers.Timer lTimer = _SystemTimer;
			if (lTimer == null) return;
			if (_CurrentDataPoint >= _NumDataPoints) return;
			lTimer.Stop();
			lTimer.Interval = getTimeMsToNextCall_Double();
			lTimer.Start();
		} //
		#endregion

		#region ThreadingTimer
		private static System.Threading.Timer _ThreadingTimer = null;

		private static void UseThreadingTimer() {
			Console.WriteLine("THREAD TIMER:");
			Init();

			TimerCallback lCallback = new TimerCallback(ThreadingTimer_Elapsed);
			_ThreadingTimer = new System.Threading.Timer(lCallback, null, getTimeMsToNextCall_Long(), (long)(Timeout.Infinite));

			_AutoResetEvent.WaitOne();
			_ThreadingTimer = null;

			PrintStats();
		} //

		private static void ThreadingTimer_Elapsed(object xState) {
			RecordDatapoint();

			// restart timer
			System.Threading.Timer lTimer = _ThreadingTimer;
			if (lTimer == null) return;
			if (_CurrentDataPoint >= _NumDataPoints) return;
			lTimer.Change(getTimeMsToNextCall_Long(), (long)Timeout.Infinite);
		} //
		#endregion

		#region miscellaneous
		private static void Init() {
			_DataPoints.Clear();
			_CurrentDataPoint = 0;

			// init exact time schedule
			long lOffset = Stopwatch.GetTimestamp() + _PeriodInTicks;  // we start in the future
			_Schedule = new long[_NumDataPoints];
			for (int i = 0; i < _NumDataPoints; i++) {
				_Schedule[i] = lOffset;
				lOffset += _PeriodInTicks;
			}
		} //

		private static void PrintStats() {
			if (_DataPoints.Count < 1) return;

			Console.WriteLine("Average " + _DataPoints.Average());
			long lMin = _DataPoints.Min();
			long lMax = _DataPoints.Max();
			Console.WriteLine("Min     " + lMin);
			Console.WriteLine("Max     " + lMax);
			Console.WriteLine("Range   " + (lMax - lMin));
			Console.WriteLine();
		} //

		private static void RecordDatapoint() {
			long lDifference = Stopwatch.GetTimestamp() - _Schedule[_CurrentDataPoint];  // positive = late, negative = early
			_DataPoints.Add(lDifference);
			Console.WriteLine("Delay in ticks: " + lDifference.ToString("#,##0") + " == " + ((lDifference * 1000000.0) / _FrequencyAsDouble).ToString("#,##0") + " microseconds");
			_CurrentDataPoint++;
			if (_CurrentDataPoint >= _NumDataPoints) _AutoResetEvent.Set();
		} //

		private static long getTimeMsToNextCall_Long() {
			long lTicks = (_Schedule[_CurrentDataPoint] - Stopwatch.GetTimestamp());
			return (1000 * lTicks) / Stopwatch.Frequency;
		} //

		private static double getTimeMsToNextCall_Double() {
			double lTicks = (double)(_Schedule[_CurrentDataPoint] - Stopwatch.GetTimestamp());
			return (1000.0 * lTicks) / _FrequencyAsDouble;
		} //
		#endregion

	} // class
} // namespace

 

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Threading;

namespace TimerPrecisionTest {
	public class MicroTimer {

		private readonly Queue<long> _TickTimeTable;
		private readonly Thread _Thread;
		private readonly long _MaxDelayInTicks;  // do not run if the delay was too long
		private long _NextWakeUpTickTime;

		public delegate void dOnMicroTimer(int xSenderThreadId, long xWakeUpTimeInTicks, long xDelayInTicks);
		public event dOnMicroTimer OnMicroTimer;
		public event dOnMicroTimer OnMicroTimerSkipped;

		public delegate void dQuickNote(int xSenderThreadId);
		public event dQuickNote OnMicroTimerStart;
		public event dQuickNote OnMicroTimerStop;

		public MicroTimer(Queue<long> xTickTimeTable, long xMaxDelayInTicks) {
			_TickTimeTable = xTickTimeTable;
			_Thread = new Thread(new ThreadStart(Loop));
			_Thread.Priority = ThreadPriority.Highest;
			_Thread.Name = "TimerLoop";
			_Thread.IsBackground = true;
			_MaxDelayInTicks = xMaxDelayInTicks;
		} //

		public int Start() {
			if ((_Thread.ThreadState & System.Threading.ThreadState.Unstarted) == 0) return -1;
			_Thread.Start();
			return _Thread.ManagedThreadId;
		} //

		public void Stop() {
			_Thread.Interrupt();
		} //

		private void Loop() {
			dQuickNote lOnStart = OnMicroTimerStart;
			if (lOnStart != null) lOnStart(_Thread.ManagedThreadId);

			try {
				while (true) {
					if (_TickTimeTable.Count < 1) break;
					_NextWakeUpTickTime = _TickTimeTable.Dequeue();
					long lMilliseconds = _NextWakeUpTickTime - Stopwatch.GetTimestamp();
					if (lMilliseconds < 0L) continue;
					lMilliseconds = (lMilliseconds * 1000) / Stopwatch.Frequency;
					lMilliseconds -= 50;  // we want to wake up earlier and spend the last time using SpinWait
					Thread.Sleep((int)lMilliseconds);

					while (Stopwatch.GetTimestamp() < _NextWakeUpTickTime) {
						Thread.SpinWait(10);
					}
					long lWakeUpTimeInTicks = Stopwatch.GetTimestamp();
					long lDelay = lWakeUpTimeInTicks - _NextWakeUpTickTime;
					if (lDelay < _MaxDelayInTicks) {
						dOnMicroTimer lHandler = OnMicroTimer;
						if (lHandler == null) continue;
						lHandler(_Thread.ManagedThreadId, lWakeUpTimeInTicks, lDelay);
					}
					else {
						dOnMicroTimer lHandler = OnMicroTimerSkipped;
						if (lHandler == null) continue;
						lHandler(_Thread.ManagedThreadId, lWakeUpTimeInTicks, lDelay);
					}
				}
			}
			catch (ThreadInterruptedException) { }
			catch (Exception) { Console.WriteLine("Exiting timer thread."); }

			dQuickNote lOnStop = OnMicroTimerStop;
			if (lOnStop != null) lOnStop(_Thread.ManagedThreadId);
		} //

	} // class
} // namespace

Example output:

Process with normal priority:
Priviledged processor time for process TimerPrecisionTest.vshost is 109.4 ms
Process with high priority:
Priviledged processor time for process TimerPrecisionTest.vshost is 109.4 ms
IsHighResolution system clock: True
Number of ticks per second: 1,558,893
Number of ticks to obtain a timestamp: 0.27

SYSTEM TIMER:
Delay in ticks: 65,625 == 42,097 microseconds
Delay in ticks: 1,414 == 907 microseconds
Delay in ticks: 1,663 == 1,067 microseconds
Delay in ticks: 1,437 == 922 microseconds
Delay in ticks: 25,829 == 16,569 microseconds
Delay in ticks: 1,532 == 983 microseconds
Delay in ticks: 14,478 == 9,287 microseconds
Delay in ticks: 14,587 == 9,357 microseconds
Delay in ticks: 14,615 == 9,375 microseconds
Delay in ticks: 14,650 == 9,398 microseconds
Average 15583
Min 1414
Max 65625
Range 64211

THREAD TIMER:
Delay in ticks: 18,890 == 12,118 microseconds
Delay in ticks: 17,493 == 11,221 microseconds
Delay in ticks: 11,750 == 7,537 microseconds
Delay in ticks: 11,824 == 7,585 microseconds
Delay in ticks: 11,914 == 7,643 microseconds
Delay in ticks: 11,858 == 7,607 microseconds
Delay in ticks: 11,935 == 7,656 microseconds
Delay in ticks: 12,049 == 7,729 microseconds
Delay in ticks: 12,108 == 7,767 microseconds
Delay in ticks: 24,953 == 16,007 microseconds
Average 14477.4
Min 11750
Max 24953
Range 13203

LOOP AND SLEEP:
Delay in ticks: 7,346 == 4,712 microseconds
Delay in ticks: 7,367 == 4,726 microseconds
Delay in ticks: 7,423 == 4,762 microseconds
Delay in ticks: 7,494 == 4,807 microseconds
Delay in ticks: 7,542 == 4,838 microseconds
Delay in ticks: 7,408 == 4,752 microseconds
Delay in ticks: 20,249 == 12,989 microseconds
Delay in ticks: 20,275 == 13,006 microseconds
Delay in ticks: 20,351 == 13,055 microseconds
Delay in ticks: 20,383 == 13,075 microseconds
Average 12583.8
Min 7346
Max 20383
Range 13037

SpinWait tests (neglecting PrivilegedProcessorTime):

Number of ticks for a SpinWait: 4,833
Average ticks for 100x SpinWaits: 1,422 == 912.0831 microseconds
SpinWait caused an error of just: 0.0000 microseconds

MICRO TIMER CLASS:
Delay in ticks: 772 == 495 microseconds
(Delay at wakeup time was 1 tick)
Delay in ticks: 34 == 22 microseconds
(Delay at wakeup time was 1 tick)
Delay in ticks: 6 == 4 microseconds
(Delay at wakeup time was 1 tick)
Delay in ticks: 5 == 3 microseconds
(Delay at wakeup time was 1 tick)
Delay in ticks: 6 == 4 microseconds
(Delay at wakeup time was 1 tick)
Delay in ticks: 6 == 4 microseconds
(Delay at wakeup time was 1 tick)
Delay in ticks: 6 == 4 microseconds
(Delay at wakeup time was 1 tick)
Delay in ticks: 5 == 3 microseconds
(Delay at wakeup time was 1 tick)
Delay in ticks: 6 == 4 microseconds
(Delay at wakeup time was 1 tick)
Delay in ticks: 7 == 4 microseconds
(Delay at wakeup time was 2 tick)
MicroTimer stopped.
Average 85.3
Min 5
Max 772
Range 767