Types and Programming Languages Part 5 – Sleeping and measuring time

This is the fifth part of the Types and Programming Languages series. For your convenience you can find other parts in the table of contents in Part 1 — Do not return in finally

How do you sleep in your application? There are multiple solutions, most of the times similar to Thread.Sleep which synchronously blocks the thread or Thread.SleepAsync which returns a promise to indicate when the given time passed.

What they have in common is they are based on the wall clock. And while it makes sense and is simple to understand, we need to keep in mind it’s not the only “sleeping” we can imagine. Instead of sleeping for a “real time passing by” we may want to sleep for “time consumed by our application”. Is there a difference? Let’s take this C# code:

using System;
using System.Diagnostics;
using System.Threading;

namespace ThreadSleepRuntime
{
	class Program
    {
        static void Main(string[] args)
        {
			Thread workerThread = new Thread(() =>
			{
				try
				{
					while (true)
					{
						for (int i = 0; i < 1000000; ++i) { }
						Thread.Sleep(1);
					}
				}catch(Exception e)
				{
					Console.WriteLine(e);
				}
			});
			workerThread.Name = "Custom sleeping thread";

			var sleepTime = TimeSpan.FromSeconds(1);



			Console.WriteLine($"Start: {DateTime.UtcNow}");
			Console.WriteLine($"Start work time: {GetCurrentTimes()}");

			workerThread.Start();
			Thread.Sleep(sleepTime);


			Console.WriteLine($"End: {DateTime.UtcNow}");
			Console.WriteLine($"End work time: {GetCurrentTimes()}");

			Environment.Exit(0);
		}

		private static TimeSpan GetCurrentTimes()
		{
			TimeSpan currentTimes = new TimeSpan();

			ProcessThreadCollection currentThreads = Process.GetCurrentProcess().Threads;

			foreach (ProcessThread thread in currentThreads)
			{
				currentTimes += thread.TotalProcessorTime;
			}

			return currentTimes;
		}
	}
}

using System;

using System.Diagnostics;

using System.Threading;

namespace ThreadSleepRuntime

{

class Program

{

static void Main(string[] args)

{

Thread workerThread = new Thread(() =>

{

try

{

while (true)

{

for (int i = 0; i < 1000000; ++i) { }

Thread.Sleep(1);

}

}catch(Exception e)

{

Console.WriteLine(e);

}

});

workerThread.Name = "Custom sleeping thread";

var sleepTime = TimeSpan.FromSeconds(1);

Console.WriteLine($"Start: {DateTime.UtcNow}");

Console.WriteLine($"Start work time: {GetCurrentTimes()}");

workerThread.Start();

Thread.Sleep(sleepTime);

Console.WriteLine($"End: {DateTime.UtcNow}");

Console.WriteLine($"End work time: {GetCurrentTimes()}");

Environment.Exit(0);

}

private static TimeSpan GetCurrentTimes()

{

TimeSpan currentTimes = new TimeSpan();

ProcessThreadCollection currentThreads = Process.GetCurrentProcess().Threads;

foreach (ProcessThread thread in currentThreads)

{

currentTimes += thread.TotalProcessorTime;

}

return currentTimes;

}

We create a thread which does some busy loop and then sleeps physically for a millisecond. In the main thread we measure not only the wall clock time but also the time consumed by all threads in the application. Sample results:

Start: 8/18/2020 12:25:46 AM
Start work time: 00:00:00.0312500
End: 8/18/2020 12:25:47 AM
End work time: 00:00:00.3281250

Start: 8/18/2020 12:25:46 AM

Start work time: 00:00:00.0312500

End: 8/18/2020 12:25:47 AM

End work time: 00:00:00.3281250

You can see that we waited for a second but actual work time was around 300 milliseconds. Can we do better?

We can, let’s take this function:

private static void WorkSleep(TimeSpan timeout)
{
	TimeSpan start = GetCurrentTimes();
	TimeSpan howMuchLeft = timeout;

	while(howMuchLeft > TimeSpan.Zero)
	{
		Thread.Sleep(timeout);
		howMuchLeft = timeout - (GetCurrentTimes() - start);
	}
}

private static void WorkSleep(TimeSpan timeout)

{

TimeSpan start = GetCurrentTimes();

TimeSpan howMuchLeft = timeout;

while(howMuchLeft > TimeSpan.Zero)

{

Thread.Sleep(timeout);

howMuchLeft = timeout - (GetCurrentTimes() - start);

}

So we take current times and then sleep for long enough (possibly many times). Output:

Start: 8/18/2020 12:29:37 AM
Start work time: 00:00:00.0468750
End: 8/18/2020 12:29:39 AM
End work time: 00:00:01.0625000

Start: 8/18/2020 12:29:37 AM

Start work time: 00:00:00.0468750

End: 8/18/2020 12:29:39 AM

End work time: 00:00:01.0625000

This time you can see that we physically slept for 2 seconds while our threads worked for around 1016 milliseconds.

And this is just the beginning — we used only one worker thread. What if we create many of them?

ThreadStart lambda = () =>
{
	try
	{
		while (true)
		{
			for (int i = 0; i 
{
	Thread workerThread = new Thread(lambda);
	workerThread.Name = $"Custom sleeping thread {i}";
	workerThread.Start();
	return workerThread;
}).ToArray();

ThreadStart lambda = () =>

{

try

{

while (true)

{

for (int i = 0; i

{

Thread workerThread = new Thread(lambda);

workerThread.Name = $"Custom sleeping thread {i}";

workerThread.Start();

return workerThread;

}).ToArray();

WorkSleep(sleepTime);

1	WorkSleep(sleepTime);

Start: 8/18/2020 12:31:38 AM
Start work time: 00:00:00.2812500
End: 8/18/2020 12:31:39 AM
End work time: 00:00:04.2812500

Start: 8/18/2020 12:31:38 AM

Start work time: 00:00:00.2812500

End: 8/18/2020 12:31:39 AM

End work time: 00:00:04.2812500

So this time we slept for a physical second but we actually did 4 seconds of work. Let’s try this one:

private static void WorkSleepParallel(TimeSpan timeout)
{
	TimeSpan start = GetCurrentTimes();
	TimeSpan howMuchLeft = timeout;

	while (howMuchLeft > TimeSpan.Zero)
	{
		Thread.Sleep((int)(timeout.TotalMilliseconds / Process.GetCurrentProcess().Threads.Count));
		howMuchLeft = timeout - (GetCurrentTimes() - start);
	}
}

private static void WorkSleepParallel(TimeSpan timeout)

{

TimeSpan start = GetCurrentTimes();

TimeSpan howMuchLeft = timeout;

while (howMuchLeft > TimeSpan.Zero)

{

Thread.Sleep((int)(timeout.TotalMilliseconds / Process.GetCurrentProcess().Threads.Count));

howMuchLeft = timeout - (GetCurrentTimes() - start);

}

This time we divide the time by threads count to “not oversleep”. However, we get this:

Start: 8/18/2020 12:34:15 AM
Start work time: 00:00:00.1718750
End: 8/18/2020 12:34:15 AM
End work time: 00:00:01.4687500

Start: 8/18/2020 12:34:15 AM

Start work time: 00:00:00.1718750

End: 8/18/2020 12:34:15 AM

End work time: 00:00:01.4687500

So we worked for 1300 thread milliseconds but actually 0 seconds of the wall clock time!

And here we come to another important thing: it’s hard to measure time with high precision. Method I presented above relies on GetThreadTimes function which is known for low precision. There are other solutions like QueryThreadCycleTime based on QueryPerformanceCounter. And it’s important to understand that these things are very hardware dependent.

However, there is yet another issue — what does it mean to “measure the time” for a multithreaded algorithm? Are we interested in the “wall clock” time from start till the end or maybe the actual “threads time” spent on working? And these methods give different results.

It’s no surprise that benchmarking libraries do a lot of black magic, like measuring CPU frequency (which changes over time) increasing the frequency forcefully (by running empty loops), or just execute the same thing many times to make sure noise is minimized. It’s not simple.