EventLoopScheduler Hotspot

Question

Hi guys

We've been using the EventLoopScheduler on a .NET 4.0 project where Schedule() is being called extremely quickly and extremely often with no offset.  What we're seeing using a profiler is that the EventLoopScheduler has a massive hotspot when it works out the dueTime, it uses EventLoopScheduler.Now which internally calls DateTimeOffSet.Now:

publicDateTimeOffsetNow { get { returnDateTimeOffset.Now; } }

In one run of the app we're building, this call took 95% of the total CPU time that the app used.  Is this a known problem?  Is there any reason Rx doesn't use DateTimeOffSet.UtcNow which is orders of magnitude faster?

Thanks

Ray

Answer 1

Hi Ray,

I didn't believe it, but you're right - UtcNow is much faster.  It even seems that perhaps in some circumstances the difference could prove to be noticeable given a large number of notifications to process.

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

namespace ConsoleApplication1
{
	class Program
	{
		static void Main(string[] args)
		{
			var watch = new Stopwatch();
			var results = new List<TimeSpan>();

			for (int i = 0; i < 10; i++)
			{
				watch.Restart();

				for (int x = 0; x < 100 * 1000; x++)
				{
					var _ = DateTimeOffset.Now;
				}

				watch.Stop();

				results.Add(watch.Elapsed);

				Console.WriteLine(watch.Elapsed);
			}

			Console.WriteLine("Avg: {0}", TimeSpan.FromTicks((long) results.Average(t => t.Ticks)));
			Console.WriteLine();

			results.Clear();

			for (int i = 0; i < 10; i++)
			{
				watch.Restart();

				for (int x = 0; x < 100 * 1000; x++)
				{
					var _ = DateTimeOffset.UtcNow;
				}

				watch.Stop();

				results.Add(watch.Elapsed);

				Console.WriteLine(watch.Elapsed);
			}

			Console.WriteLine("Avg: {0}", TimeSpan.FromTicks((long) results.Average(t => t.Ticks)));
		}
	}
}

Results:

00:00:00.5278564
00:00:00.5497243
00:00:00.5127593
00:00:00.5031145
00:00:00.5043352
00:00:00.5040351
00:00:00.5049378
00:00:00.5013051
00:00:00.5196445
00:00:00.5303349
Avg: 00:00:00.5158047

00:00:00.0111582
00:00:00.0112926
00:00:00.0119740
00:00:00.0116525
00:00:00.0116730
00:00:00.0115350
00:00:00.0118569
00:00:00.0117702
00:00:00.0113261
00:00:00.0117165
Avg: 00:00:00.0115955

- Dave

---

http://davesexton.com/blog

Answer 2

We're aware of hotspots in the Rx codebase and are working on improvements for future releases. Stay tuned!

---

using (Microsoft.Sql.Cloud.DataProgrammability.Rx) { Signature.Emit("Bart De Smet"); }

Answer 3

Reflector --> EventLoopScheduler --> Cut --> Visual Studio --> Paste --> Change .Now to .UtcNow.

:)

You are welcome Ray. Dont mention it, really. Anytime.

:p

---

Lee Campbell http://LeeCampbell.blogspot.com

Answer 4

This has been fixed in Rx v2.0 Beta and we'll continue to look into performance enhancements going forward. Let us know if you notice other odd behavior.

---

using (Microsoft.Sql.Cloud.DataProgrammability.Rx) { Signature.Emit("Bart De Smet"); }