Bug 44132 - Thread.Sleep () overhead too big
Summary: Thread.Sleep () overhead too big
Status: RESOLVED FIXED
Alias: None
Product: Runtime
Classification: Mono
Component: io-layer (show other bugs)
Version: unspecified
Hardware: PC Mac OS
: --- normal
Target Milestone: ---
Assignee: Bugzilla
URL:
Depends on:
Blocks:
 
Reported: 2016-09-09 01:24 UTC by Zoltan Varga
Modified: 2016-09-14 00:49 UTC (History)
4 users (show)

See Also:
Tags:
Is this bug a regression?: ---
Last known good build:


Attachments

Description Zoltan Varga 2016-09-09 01:24:44 UTC
From:

http://lists.dot.net/pipermail/mono-devel-list/2016-September/043813.html

Testcase:

<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
using System;
using System.Threading;
using System.Diagnostics;
using System.Threading.Tasks;
using System.Reflection;

namespace TestSleep
{
	class MainClass
	{
		public static void Main (string[] args)
		{
			Console.WriteLine (GetMonoVersion ());
			Console.WriteLine ("Sleep performance test. Press enter to exit.");

			using(var performanceCounter = new PerformanceCounter ("Process", "% Processor Time", GetInstanceName(Process.GetCurrentProcess()), false))
			using(var ctSource = new CancellationTokenSource ())
			{
				var thread = new Thread (RunWithSleep) 
				{
					Name = "Dummy Sleep Thread"
				};
				thread.Start (ctSource.Token);

				var readLine = Task.Run (() => Console.ReadLine());
				while (!readLine.IsCompleted)
				{ 
					Console.Write("\rCPU Time: " + performanceCounter.NextValue() + "%");
					Thread.Sleep(TimeSpan.FromSeconds(1));
				}

				ctSource.Cancel ();
				thread.Join ();
			}
		}

		/**
		 * This Thread starts to sleep for one millisecond continously 
		 * and cause high CPU usage in Mono version >= 4.4.
		 */
		static void RunWithSleep(object cancellationToken)
		{
			Console.WriteLine ("Starting 'Dummy Sleep Thread'");
			var cancel = (CancellationToken)cancellationToken;
			while(!cancel.IsCancellationRequested)
			{
				Thread.Sleep(1);
			}

			Console.WriteLine ("'Dummy Sleep Thread' done");
		}

		static string GetInstanceName(Process process)
		{
			PerformanceCounterCategory processCategory = new PerformanceCounterCategory("Process");
			string[] instanceNames = processCategory.GetInstanceNames();
			foreach (string name in instanceNames)
			{
				if (name.StartsWith(process.Id.ToString()))
				{
					return name;
				}
			}

			throw new Exception ("Failed to find instance name");
		}

		static string GetMonoVersion()
		{
			Type type = Type.GetType("Mono.Runtime");
			if (type != null)
			{
				MethodInfo displayName = type.GetMethod("GetDisplayName", BindingFlags.NonPublic | BindingFlags.Static);
				if (displayName != null)
					return displayName.Invoke (null, null).ToString();
			}

			return "Unknown Version";
		}
	}
}
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
Comment 1 Zoltan Varga 2016-09-09 01:28:40 UTC
The overhead of the current interruptable sleep code is probably too big for short waits.
Comment 2 Emil 2016-09-09 11:24:43 UTC
I found the commit that is causing this bug:
https://github.com/mono/mono/commit/089c47f1c07bf250d76c36e04675569fc6f5b4ba#diff-e7e458b6256eaa730c145f14a666652aR1141

I tried to revert the commit, and that fixed the bug in my example.

The reasoning behind it, is that this line compares 100ns ticks https://github.com/mono/mono/commit/089c47f1c07bf250d76c36e04675569fc6f5b4ba#diff-e7e458b6256eaa730c145f14a666652aR1144

While the '(end - now) / 10 / 1000' expression may result in 0 ms if 'end - now' is less than a ms. 
https://github.com/mono/mono/commit/089c47f1c07bf250d76c36e04675569fc6f5b4ba#diff-e7e458b6256eaa730c145f14a666652aR1155

So what happens, is that the last millisecond of a sleep, is spin waited, since 'mono_coop_cond_timedwait' is called with zero as the time to wait. Theoretically the worst case is 10000 iterations. So this isn't only a problem for small waits, it's a general problem, where long sleeps also may get a CPU spike in the near end of its wait.
Comment 3 Emil 2016-09-09 14:36:35 UTC
Made a pull-request with the most simple approach
https://github.com/mono/mono/pull/3544
Comment 4 Rodrigo Kumpera 2016-09-14 00:49:30 UTC
PR was merged, I think it's safe to close this bug.

Note You need to log in before you can comment on or make changes to this bug.