Timing methods in c#, updated

In my previous post on this topic, I did mention that it wasn’t about the code, but the concept. Still, I wrote that code a while back and only really used it that one day. For the code I timed that day, it was fine, but for anything more, it was not, as I found last night when I needed to time an async method that’s called all the time. So here is some more robust code that times methods without accidently interfering with them. It also tracks calls to the methods it times, and logs the timings and averages per method, and at a much better resolution.

Again, the source, for this and a whole bunch of other stuff, is here: RomyView.zip

Here is an example of its results:

2013-01-23 12:09:00.00	Thumbnail.LoadImageAsync	Time: 74.2155ms	Average: 119.179ms
2013-01-23 12:09:00.00	Thumbnail.LoadImageAsync	Time: 74.5946ms	Average: 118.2873ms
2013-01-23 12:09:00.00	Thumbnail.LoadImageAsync	Time: 73.3504ms	Average: 117.4062ms
2013-01-23 12:09:00.02	Thumbnail.LoadImageAsync	Time: 80.4276ms	Average: 116.6951ms
2013-01-23 12:09:00.02	Thumbnail.LoadImageAsync	Time: 81.7943ms	Average: 116.0366ms
2013-01-23 12:09:05.71	BaseForm.LoadTheme	Time: 17.6966ms	Average: 9.7432ms
2013-01-23 12:09:05.71	BaseForm.LoadTheme	Time: 1.4265ms	Average: 6.971ms
2013-01-23 12:09:05.71	BaseForm.LoadTheme	Time: 0.5618ms	Average: 5.3687ms
2013-01-23 12:09:06.66	BaseForm.LoadTheme	Time: 182.235ms	Average: 40.7419ms
2013-01-23 12:09:06.66	BaseForm.LoadTheme	Time: 0.8616ms	Average: 34.0952ms

The timing methods look a little different to before, since the code no longer tries to write a file for every method call. They now just take two parameters: the method to time, and a description (or the method name or whatever you want to pass as a string). According to the Visual Studio 2012 Code Analysis, it commits some sort of mortal sin, because it uses a static constructor. Initialize all of your static fields inline, it tells me… Hello, I did that! But I couldn’t think of another way to save the results file, other than creating an event handler for Application.ApplicationExit, which I did in the constructor. The code now looks like this:

  1. using System;
  2. using System.Collections.Concurrent;
  3. using System.Diagnostics;
  4. using System.IO;
  5. using System.Threading.Tasks;
  6. using System.Windows.Forms;
  7.  
  8. namespace Romy.Core
  9. {
  10.     public static class MethodTimer
  11.     {
  12.         private static ConcurrentDictionary<string, long> counts = new ConcurrentDictionary<string, long>();
  13.  
  14.         private static ConcurrentDictionary<string, TimeSpan> totals = new ConcurrentDictionary<string, TimeSpan>();
  15.  
  16.         private static ConcurrentQueue<string> logLines = new ConcurrentQueue<string>();
  17.  
  18.         private static string logFile = System.IO.Path.Combine(Application.StartupPath, “Timing.log”);
  19.  
  20.         static MethodTimer()
  21.         {
  22.             Application.ApplicationExit += (sender, e) =>
  23.             {
  24.                 if (logLines.Count > 0)
  25.                 {
  26.                     File.WriteAllLines(logFile, logLines.ToArray());
  27.                 }
  28.             };
  29.         }
  30.  
  31.         /// <summary>Time a method and write to a file.</summary>
  32.         /// <param name=”method”>The method to time.</param>
  33.         /// <param name=”description”>Something to describe the method being timed.</param>
  34.         public static void TimeMethod(Action method, string description)
  35.         {
  36.             var stopwatch = new Stopwatch();
  37.             stopwatch.Start();
  38.  
  39.             try
  40.             {
  41.                 method();
  42.             }
  43.             catch (Exception ex) { ex.Log(); }
  44.             finally { stopwatch.Stop(); }
  45.  
  46.             LogTime(description, stopwatch.Elapsed);
  47.         }
  48.  
  49.         /// <summary>Time a method and write to a file.</summary>
  50.         /// <param name=”method”>The method to time.</param>
  51.         /// <param name=”description”>Something to describe the method being timed.</param>
  52.         public static async Task TimeMethodAsync(Func<Task> method, string description)
  53.         {
  54.             var stopwatch = new Stopwatch();
  55.             stopwatch.Start();
  56.  
  57.             try
  58.             {
  59.                 await method();
  60.             }
  61.             catch (Exception ex) { ex.Log(); }
  62.             finally { stopwatch.Stop(); }
  63.  
  64.             LogTime(description, stopwatch.Elapsed);
  65.         }
  66.  
  67.         private static void LogTime(string description, TimeSpan ts)
  68.         {
  69.             TimeSpan total = TimeSpan.Zero;
  70.             totals[description] = totals.TryGetValue(description, out total) ? total.Add(ts) : ts;
  71.  
  72.             if (counts.ContainsKey(description))
  73.                 counts[description] += 1L;
  74.             else
  75.                 counts[description] = 1L;
  76.  
  77.             var callTimeText = “Time: “ + (ts < TimeSpan.FromSeconds(1D) ? ts.TotalMilliseconds.ToString() + “ms” : ts.TotalSeconds.ToString() + “s”);
  78.             var average = TimeSpan.FromTicks(totals[description].Ticks / counts[description]);
  79.             var averageText = “Average: “ + (average < TimeSpan.FromSeconds(1D) ? average.TotalMilliseconds.ToString() + “ms” : average.TotalSeconds.ToString() + “s”);
  80.             var line = DateTime.Now.ToString(“yyyy-MM-dd HH:mm:ss.ff\t”) + description + “\t” + callTimeText + “\t” + averageText;
  81.  
  82.             logLines.Enqueue(line);
  83.         }
  84.     }
  85. }

 

Perhaps it’s worth mentioning that you can’t directly time an async void method. I’m not sure how obvious it is to everyone, but the reason for this (and if you weren’t aware of it, you could get excited for nothing, thinking that your code runs super-fast) is that async void methods return immediately. That’s why they’re also called fire-and-forget methods. The async additions to .Net 4.5 are still new enough that many developers might not realize the difference between async methods that return a Task or Task<Result> and async methods that return void, but it’s a difference you need to understand if you write much async code. The methods that return results require you to use the await keyword, to wait asynchronously on their return values, while async void methods return immediately, promising that their work will be done eventually.

So if I want to time an async void method, I temporarily change it to an async Task method, and add a new temporary async void method that calls it. I did this in the example near the top of this post. LoadImageAsync is called from a property setter, which can’t be declared as async. The code below is from my Thumbnail control. I changed the signature of the LoadImageAsync method as mentioned above, and added the temporary LoadImage method, which is where I called the timing method.

  1. /// <summary>The file name of the referenced file. Setting this sets
  2. /// off the asynchronous fetching of the thumbnail image.</summary>
  3. [Browsable(false)]
  4. public string Path
  5. {
  6.     get { return path; }
  7.     set
  8.     {
  9.         path = value;
  10.  
  11.         if (!string.IsNullOrEmpty(path))
  12.         {
  13.             InitializeSize();
  14.             DisposeTokenSource();
  15.             //LoadImageAsync();
  16.             LoadImage();
  17.         }
  18.         else // Reset
  19.         {
  20.             displayText = null;
  21.             Image = null;
  22.             CacheItem = null;
  23.             Valid = true; // Only set false for invalid thumbnails. This resets it to the initial state.
  24.         }
  25.     }
  26. }
  27.  
  28. private async void LoadImage()
  29. {
  30.     await MethodTimer.TimeMethodAsync(async () => await LoadImageAsync(), “Thumbnail.LoadImageAsync”);
  31. }
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.

One Response to Timing methods in c#, updated

  1. denbrown20 says:

    Thank you for your reference about code development. I’m studying and trying to develop a simple tool for creating 1d/2d barcode image in c#.net, your analysis and code sample give me some idea for my C# project. Thanks a lot.

    Like

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