Timing methods in c# to see which implementation is faster

Update. Don’t use the method timing code posted here. A newer and much better version is here.

I have been working on a “pet” project in c# for the last three years now… It’s an image viewer, video player (DirectShow), zip file viewer, video converter (via ffmpeg) and probably a bunch of other things I’ve forgotten about. It’s basically been my playground in which I’ve learned about lambda expressions, extension methods, and async code. I wrote a few articles about async code on my other blog last year, taking code from the solution, but was not very happy with them, so what I write here will be different.

I will be writing several articles, all referring to code from that solution, starting with a very simple introduction today, mostly just to provide a download link to the source code and introduce the application.

The source code is here: RomyView

The code I’m sharing today is nothing special. It’s just a couple of simple methods to time methods via a Stopwatch. The point here is not the quality of the code, but the concept… If you have two or more implementations of the same method, and you want to know which one is faster, you don’t go and ask a whole bunch of experts which technique is faster, because all you will achieve is annoying them. You time the methods, being sensible about doing so under the same conditions and number of calls, and save the results to a file. Then you read the file and if there is a difference, or not, you see it right away.

My timing method comes in two flavours, because depending on what is being timed, I may or may not need to call the method using the await keyword. This is the synchronous version. (ex.Log() is a call to an extension method. I’m sure you can guess what it does, and it isn’t really relevant to this post.)

  1. /// <summary>Helper method to time a method and write to a file.</summary>
  2. /// <param name=”method”>The method to time.</param>
  3. /// <param name=”description”>Something to describe the method being timed.</param>
  4. /// <param name=”logFile”>The file where we store the result.</param>
  5. public static void TimeMethod(Action method, string description, string logFile)
  6. {
  7.     var stopwatch = new Stopwatch();
  8.     stopwatch.Start();
  9.  
  10.     try
  11.     {
  12.         method();
  13.     }
  14.     catch (Exception ex)
  15.     {
  16.         ex.Log();
  17.     }
  18.  
  19.     stopwatch.Stop();
  20.     var ts = stopwatch.Elapsed;
  21.  
  22.     total = ts.Add(total);
  23.     count++;
  24.     var average = TimeSpan.FromMilliseconds(total.TotalMilliseconds / count);
  25.     var averageFormatted = String.Format(“{0:00}.{1:00}”, average.Seconds, average.Milliseconds / 10);
  26.  
  27.     var formatted = String.Format(“{0:00}:{1:00}:{2:00}.{3:00} – Average: {4}, {5}”, ts.Hours, ts.Minutes, ts.Seconds, ts.Milliseconds / 10, averageFormatted, description);
  28.  
  29.     if (File.Exists(logFile))
  30.         File.AppendAllLines(logFile, new string[] { formatted });
  31.     else
  32.         File.WriteAllLines(logFile, new string[] { formatted });
  33. }

 

And here follows the asynchronous version. Again, I’m not going to explain the extension methods. (But I will get to them in a future post.)

  1. /// <summary>Helper method to time a method and write to a file.</summary>
  2. /// <param name=”method”>The method to time.</param>
  3. /// <param name=”description”>Something to describe the method being timed.</param>
  4. /// <param name=”logFile”>The file where we store the result.</param>
  5. public static async Task TimeMethodAsync(Func<Task> method, string description, string logFile)
  6. {
  7.     var stopwatch = new Stopwatch();
  8.     stopwatch.Start();
  9.  
  10.     try
  11.     {
  12.         await method();
  13.     }
  14.     catch (Exception ex)
  15.     {
  16.         ex.Log();
  17.     }
  18.  
  19.     stopwatch.Stop();
  20.     var ts = stopwatch.Elapsed;
  21.  
  22.     total = ts.Add(total);
  23.     count++;
  24.     var average = TimeSpan.FromMilliseconds(total.TotalMilliseconds / count);
  25.     var averageFormatted = String.Format(“{0:00}.{1:00}”, average.Seconds, average.Milliseconds / 10);
  26.  
  27.     var formatted = String.Format(“{0:00}:{1:00}:{2:00}.{3:00} – Average: {4}, {5}”, ts.Hours, ts.Minutes, ts.Seconds, ts.Milliseconds / 10, averageFormatted, description);
  28.  
  29.     if (File.Exists(logFile))
  30.         await FileAsync.AppendAllLinesAsync(logFile, new string[] { formatted });
  31.     else
  32.         await FileAsync.WriteAllLinesAsync(logFile, new string[] { formatted });
  33. }

 

Using the timer methods

All you do, of course, is pass the method you want to time as a parameter to one of these methods, as well as a description and the path where you want the results saved. Note that I’m giving a stupid example here; I am comparing a synchronous and an asynchronous implementation of the same method. Each one opens a bitmap in the application’s image viewer. The synchronous call, well… opens the image file synchronously. The async call opens the file using asynchronous IO. It’s a stupid example because the synchronous call will obviously be faster.

  1.  
  2. // Synchronous method call
  3. var bmp = IO.OpenBitmap(filename);
  4. string log = @”C:\Users\Jerome\Documents\Visual Studio 2012\Projects\RomyView\test.log”;
  5. // Testing the synchronous call
  6. Romy.Core.Utils.TimeMethod(() => bmp = IO.OpenBitmap(filename), “OpenBitmap”, log);
  7.  
  8. // async method call
  9. var bmp = await IO.OpenBitmapAsync(filename);
  10.  
  11. // Testing the async call
  12. await Romy.Core.Utils.TimeMethodAsync(async () => bmp = await IO.OpenBitmapAsync(filename), “OpenBitmapAsync”, log);

 

Obviously I didn’t include both calls in the code at once. I ran it for a while with the first implementation, then closed the application, commented it out and uncommented the second implementation, and so on.

I find this very handy, as I often implement a piece of code a couple of different ways, and this allows me to see immediately which way is faster, or under which conditions a particular implementation is more suited.

After extracting the zip file, the timing methods can be found in the Romy.Core class library, in Romy.Core.Utils.

I hope this may benefit someone. There is loads more to come.

Advertisements

About Jerome

I am a senior C# developer in Johannesburg, South Africa. I am also a recovering addict, who spent nearly eight years using methamphetamine. I write on my recovery blog about my lessons learned and sometimes give advice to others who have made similar mistakes, often from my viewpoint as an atheist, and I also write some C# programming articles on my programming blog.
This entry was posted in Programming and tagged , , , . Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s