Sunday, May 27, 2018

(A)Synchronicity

Back in the day, "The Police" sang a song about Synchronicity. Today, I'm writing a blog about Asynchronicity.  ;0)

To be more precise, this blog post will explore whether or not there are performance differences between the various ways to write asynchronous code. I will be looking specifically at the code needed for a multi-threaded application, where the threads just do their thing, and we don't care what they're doing (in other words, kind of a Fire-And-Forget type of thing). I will explore these three methodologies:

  • System.Threading.Thread.Start()
  • System.Threading.ThreadPool.QueueUserWorkItem()
  • System.Threading.Tasks.Task.Run()

I'm betting that the latter two methods are simply syntactic sugar on top of the original Thread.Start() ... let's see if we can get some numerical evidence of that. And, just for the heck of it, I'm going to throw in a freebie ... I'm going to compare the Task.Run() both without and with a .ConfigureAwait(false) ... (not that it matters for this discussion). So, here's the code I used for testing this (called from a Button Click so I could easily run it again):

private System.Diagnostics.Stopwatch stopWatchThread;
private System.Diagnostics.Stopwatch stopWatchQueueUserWork;
private System.Diagnostics.Stopwatch stopWatchTask;
private System.Diagnostics.Stopwatch stopWatchTaskAwaitFalse; private void CompareThreeAsyncMethods()
{
this.stopWatchThread = new Stopwatch();
Console.WriteLine("Start Thread at {0}", DateTime.Now);
this.stopWatchThread.Start();
ThreadStart threadStart = new ThreadStart(RunThread);
Thread myThread = new Thread(threadStart);
myThread.Start(); this.stopWatchQueueUserWork = new Stopwatch();
Console.WriteLine("Start QueueUserWork at {0}", DateTime.Now);
stopWatchQueueUserWork.Start();
ThreadPool.QueueUserWorkItem(WorkToDo, new WorkSettings() { stopWatch = stopWatchQueueUserWork, WorkName = "QueueUserWork" }); this.stopWatchTask = new Stopwatch();
Console.WriteLine("Start Task at {0}", DateTime.Now);
stopWatchTask.Start();
Task.Run(() =>
{
WorkToDo(new WorkSettings() {stopWatch = stopWatchTask, WorkName = "Task" });
}); this.stopWatchTaskAwaitFalse = new Stopwatch();
Console.WriteLine("Start Task AwaitFalse at {0}", DateTime.Now);
stopWatchTaskAwaitFalse.Start();
Task.Run(() =>
{
WorkToDo(new WorkSettings() { stopWatch = stopWatchTaskAwaitFalse, WorkName = "TaskAwaitFalse" });
}).ConfigureAwait(false); Console.WriteLine("Show results as threads complete ... {0}\r\n", DateTime.Now);
}
public class WorkSettings
{
public System.Diagnostics.Stopwatch stopWatch { get; set; }
public string WorkName { get; set; }
}
// Need this only for the Thread option
private void RunThread()
{
this.WorkToDo(new WorkSettings() { stopWatch = this.stopWatchThread, WorkName = "Thread" });
} private void WorkToDo(object obj)
{
WorkSettings work = (WorkSettings)obj;
for (int i = 0; i < 2147483647; i++) // largest int 2,147,483,647
{
//Thread.Sleep(500);
}

work.stopWatch.Stop();
Console.WriteLine("{0} Stopped at {1}. Elapsed Time {2} milliseconds\r\n", work.WorkName, DateTime.Now, work.stopWatch.ElapsedMilliseconds);
}

By starting a StopWatch before I start running its Asynchronous method, I take into account any "prep" work that might be involved in starting the call to the method. If there is any, it should be reflected in the overall time to complete a method. Here are the results:

Start Thread at 5/26/2018 5:13:38 PM
Start QueueUserWork at 5/26/2018 5:13:38 PM
Start Task at 5/26/2018 5:13:38 PM
Start Task AwaitFalse at 5/26/2018 5:13:38 PM
Show results as threads complete ... 5/26/2018 5:13:38 PM Thread Stopped at 5/26/2018 5:13:44 PM. Elapsed Time 5669 milliseconds
Task Stopped at 5/26/2018 5:13:44 PM. Elapsed Time 5775 milliseconds
TaskAwaitFalse Stopped at 5/26/2018 5:13:44 PM. Elapsed Time 5836 milliseconds
QueueUserWork Stopped at 5/26/2018 5:13:44 PM. Elapsed Time 5859 milliseconds // last (10th) time
Thread Stopped at 5/26/2018 5:18:14 PM. Elapsed Time 5890 milliseconds
TaskAwaitFalse Stopped at 5/26/2018 5:18:15 PM. Elapsed Time 5978 milliseconds
QueueUserWork Stopped at 5/26/2018 5:18:15 PM. Elapsed Time 5982 milliseconds
Task Stopped at 5/26/2018 5:18:15 PM. Elapsed Time 6008 milliseconds

// Average
Average for Thread: 5986 milliseconds
Average for Task: 5964 milliseconds
Average for TaskAwaitFalse: 5973 milliseconds
Average for QueueUserWork: 6048 milliseconds

Judging by those results, I think that the minuscule difference might be attributed to them all running at once & taking up CPU resources. But, we can test that as well. I'm going to run them individually. Run one. Let it complete. Run another. Let it complete. I wonder if the times will be *exact* then! Let's re-work the code to look like this:

private CompareAsync methodIs = CompareAsync.Begin;
private CompareAsync currentMethodRunning = CompareAsync.Begin;
private void CompareThreeAsyncMethodsIndividually()
{
while (methodIs != CompareAsync.Done)
{
if (methodIs == CompareAsync.Begin)
methodIs = CompareAsync.Thread;
if (methodIs == currentMethodRunning)
continue;
switch (methodIs)
{
case CompareAsync.Thread:
currentMethodRunning = methodIs;
this.stopWatchThread = new Stopwatch();
Console.WriteLine("Start Thread at {0}", DateTime.Now);
this.stopWatchThread.Start();
ThreadStart threadStart = new ThreadStart(RunThread);
Thread myThread = new Thread(threadStart);
myThread.Start();
break;
case CompareAsync.QueueUserWork:
currentMethodRunning = methodIs;
this.stopWatchQueueUserWork = new Stopwatch();
Console.WriteLine("Start QueueUserWork at {0}", DateTime.Now);
stopWatchQueueUserWork.Start();
ThreadPool.QueueUserWorkItem(WorkToDo, new WorkSettings() { stopWatch = stopWatchQueueUserWork, WorkName = "QueueUserWork" });
break;
case CompareAsync.Task:
currentMethodRunning = methodIs;
this.stopWatchTask = new Stopwatch();
Console.WriteLine("Start Task at {0}", DateTime.Now);
stopWatchTask.Start();
Task.Run(() =>
{
WorkToDo(new WorkSettings() { stopWatch = stopWatchTask, WorkName = "Task" });
});
break;
case CompareAsync.TaskAwaitFalse:
currentMethodRunning = methodIs;
this.stopWatchTaskAwaitFalse = new Stopwatch();
Console.WriteLine("Start Task AwaitFalse at {0}", DateTime.Now);
stopWatchTaskAwaitFalse.Start();
Task.Run(() =>
{
WorkToDo(new WorkSettings() { stopWatch = stopWatchTaskAwaitFalse, WorkName = "TaskAwaitFalse" });
}).ConfigureAwait(false);
break;
default:
break;
}
}
}


And added an extra bit at the end of the WorkToDo() method such that it would be able to determine which method would run next:

private void WorkToDo(object obj)
{
WorkSettings work = (WorkSettings)obj;
for (int i = 0; i < 2147483647; i++) // largest int 2,147,483,647
{
//Thread.Sleep(500);
}
work.stopWatch.Stop();
Console.WriteLine("{0} Stopped at {1}. Elapsed Time {2} milliseconds\r\n", work.WorkName, DateTime.Now, work.stopWatch.ElapsedMilliseconds);

// ADDED THIS
// Set it to the next one
switch (methodIs)
{
case CompareAsync.Thread:
methodIs = CompareAsync.QueueUserWork;
break;
case CompareAsync.QueueUserWork:
methodIs = CompareAsync.Task;
break;
case CompareAsync.Task:
methodIs = CompareAsync.TaskAwaitFalse;
break;
case CompareAsync.TaskAwaitFalse:
methodIs = CompareAsync.Done;
break;
}
}

And now the results are this:

Start Thread at 5/26/2018 5:29:32 PM
Thread Stopped at 5/26/2018 5:29:37 PM. Elapsed Time 4877 milliseconds

Start QueueUserWork at 5/26/2018 5:29:37 PM
QueueUserWork Stopped at 5/26/2018 5:29:42 PM. Elapsed Time 4850 milliseconds

Start Task at 5/26/2018 5:29:42 PM
Task Stopped at 5/26/2018 5:29:47 PM. Elapsed Time 4918 milliseconds

Start Task AwaitFalse at 5/26/2018 5:29:47 PM
TaskAwaitFalse Stopped at 5/26/2018 5:29:52 PM. Elapsed Time 4978 milliseconds

// last time (10th)
Thread Stopped at 5/26/2018 5:32:37 PM. Elapsed Time 4910 milliseconds
QueueUserWork Stopped at 5/26/2018 5:32:42 PM. Elapsed Time 4821 milliseconds
Task Stopped at 5/26/2018 5:32:46 PM. Elapsed Time 4894 milliseconds
TaskAwaitFalse Stopped at 5/26/2018 5:32:51 PM. Elapsed Time 4924 milliseconds

// Average
Average for Thread: 4986 milliseconds
Average for QueueUserWork: 4975 milliseconds
Average for Task: 4966 milliseconds
Average for TaskAwaitFalse: 4962 milliseconds

Well now ... there's still a difference between the 4 methods, isn't there? However, it is still teeny. Running each of these individually (instead of starting all 4 methods at the same time, as I did in the first test) produces the same results pretty much, the difference being that each is about 1000 milliseconds faster than the first test.

The difference between the fastest & slowest averages for the second test is only about .2% and that's in milliseconds! I'd say that these various methodologies for running asynchronous threads, aren't really any different (statistically speaking). Hey, I just like to mess around with numbers.  ;0)

Happy coding!  =0)