Here’s something I did wrong this week. And, after realizing I’d done it wrong, I remembered that I’d made the same exact mistake in the past. So I’m going to write up a blog post in the hopes that maybe it’ll help me hammer the right way into my head, so I don’t screw up next time.
If you want to do a little quick and dirty performance logging in an application, you can use the Stopwatch class. Just create a new Stopwatch, then stop it when you’re done and check the elapsed time. Easy, right?
Well, here’s what I did wrong: The Elapsed property is a TimeSpan structure, which has a lot of nice properties on it, like Days, Hours, Milliseconds, and so on. For my purposes, I wanted to know how many milliseconds had elapsed. So I showed sw.Elapsed.Milliseconds. Looks good, right? Except that the Milliseconds property is not the whole span in milliseconds. It’s the milliseconds part of the span. If you want total milliseconds, then you need to get sw.Elapsed.TotalMilliseconds.
This is one of those pernicious little bugs that doesn’t cause anything to fail, but instead causes the programmer to make bad decisions. “Hey, it looks like all my web service calls execute in less than a second! Great! I can go home early!” Nope. Turns out some of them were taking more like 20 seconds.
Here’s a little code snippet showing the wrong way and the right way.
Stopwatch sw = Stopwatch.StartNew();
TimeSpan elapsed;
Thread.Sleep(1500);
sw.Stop();
elapsed = sw.Elapsed;
Console.WriteLine("Wrong: {0}", elapsed.Milliseconds);
Console.WriteLine("Right: {0}", elapsed.TotalMilliseconds);
Simple enough, but I’ve done this wrong at least twice so far in my life. Here’s hoping I can remember to do it right next time!