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)

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

Notice (2018-05-24): bugzilla.xamarin.com is now in read-only mode.

Please join us on Visual Studio Developer Community and in the Xamarin and Mono organizations on GitHub to continue tracking issues. Bugzilla will remain available for reference in read-only mode. We will continue to work on open Bugzilla bugs, copy them to the new locations as needed for follow-up, and add the new items under Related Links.

Our sincere thanks to everyone who has contributed on this bug tracker over the years. Thanks also for your understanding as we make these adjustments and improvements for the future.


Please create a new report on GitHub or Developer Community with your current version information, steps to reproduce, and relevant error messages or log files if you are hitting an issue that looks similar to this resolved bug and you do not yet see a matching new report.

Related Links:
Status:
RESOLVED FIXED

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.