My 3 Recent Stupid Mistakes
As a developer I often make various bugs in my code. It’s inherent in our job, we all do that, we’re humans after all. It’s no wonder that in some companies you even got asked about your favorite mistakes you made, if you didn’t make any means you didn’t write code enough. On the other hand it is a good practice to think about bugs you made, why that happened and how can you prevent them in the future. You’ll become a substantially better programmer after any single mistake you made if only you investigate it afterwards. So don’t be afraid of making one, you still will at some point of time, it’s inevitable in process of becoming better.
I definitely not afraid of my errors that’s why I decided to share them with you. Those a recent ones, I made them in a course of last couple of weeks of writing C# code and I novice in .NET, so enjoy.
TimeSpan.Milliseconds
This one isn’t really my fault. It’s Intellisense’s one and style of programming it imposes on. But let’s see from the beginning.
So one sunny morning I was tasked to make some research on how fast application would run in multi-threaded environment given that one crucial resource should work only in single-threaded manner. So I made a little test application, span couple of threads and time function calls I want to have results for. How do you usually do that? Of course, call Date.now before and after the call and then subtract former from the latter. Usually (that is, what I’ve got on every platform I have ever worked before) what you get after that is a number of milliseconds call took. But in .NET for some reason you get an TimeSpan object. After a couple of seconds of frustration I called an Intellisense to see if there is a method to get number of milliseconds this object is represent. So I typed a letter “m”, and I saw a really nice property named “Milliseconds” there. “Ok”, I thought, “looks like the one” and I put it there. After a couple of tests with different number of threads I noticed something suspicious. Whatever the number of threads was, the average time always stays around 500ms and max time was always 984ms. At first I thought that is a good news, that means application is good written and we’re not going to have any performance problems whatsoever. I even told that to management and they were happy. But my intuition was telling me that something is wrong here. Calculations of average time was taking so long given that average is half a second. I mean common, function was called 12500 times but it would take only about 1.7 hours to run and it took like 4 of them. Something was really wrong.
There were couple of additional locks in the code that were for collecting statistics and so weren’t timed so I decided to eliminate them and I did. Then after every operation I put a code that writes a “.” in a console to see how fast a progress goes. And even though there weren’t any untimed locks and average time stays half a second and max time 984ms still I could really see sometimes progress stops for about 5 seconds doing nothing. That’s why I decided to check my timing code. Magical 984ms was obvious error. After couple of minutes staring at the simplest code I ever wrote I decided to go check what MSDN knows about TimeSpan. And there it was, somewhere in the end of an article about TimeSpan.Milliseconds was a remark that it could take a values from -999 to 999 only, and was for a fact just a component of interval whole length. That’s why average stays 500, just in the middle of possible values (negative values weren’t possible in my situation). No link to correct method though, quality of MSDN is really low these days. But luckily there was a sample code right in the article with calls to all possible TimeSpan functions and results they return. That’s how I found the right property for a job, TotalMilliseconds. And yes, correct performance values were never near the 500ms, more like 40s. Sad news but a different story.
new Random()
This is a really funny story. The most unexpected error I ever got with random numbers. Here it goes.
As a part of fighting with TimeSpan.Milliseconds bug I decided to run all my threads at the same time. Just to make sure none of them finishes before the full set of them run. At the same time I used a lot of random stuff around, to choose values for function calls, to create a users (I was actually test client to some kind of special purpose database, not a fancy one though), to choose what to do with database (that is, create something or just get data from it). After the session each thread was deleting users it created to clean a DB for the next round. And I’ve started to get strange results here, while deleting a user DB sometimes would complain it doesn’t have that one. Hm. It was created before after all, where did it go. It was late and I was tired from Milliseconds story already so I just ignored that complains and removed a code that checks it. Which leads to even more strange results, sometimes in a function user was created, uploaded to DB, everything was fine and then just a couple lines later it couldn’t be found. Not a nice stuff.
The next day I fired up a debugger to see why that happened. After couple of runs when I couldn’t find out a reason for such a strange behavior, I decided to put checks in cleaning code back since those issues probably was related. And when the check failed and I was looking at what other threads doing I found out couple of them were cleaning as well. Sadly, VS 2008 couldn’t show a collections while thread is paused so I couldn’t look up what they were cleaning but luckily one of them have value cached in local variable. And you know what? There was the same value in a collection of a thread I was examining.
So random were broken. How could that happen? And then a lucky guess, could it be that… I put a breakpoint just after a first random value was generated and, you guess it, for every thread it was the same. Yeah, random get seeded by the time, apparently it uses not high resolution clocks and threads which runs simultaneously even on single core computer and under .NET VM could get the same seed. Really nice. Adding Thread.CurrentThread.ManagedThreadId to the (int)DateTime.Now.Ticks and seed randoms with this value cured the bug instantly. This going to be my favorite bug with Random values for a long time, I don’t really know what could beat it.
System.Threading.Timer vs. System.Windows.Forms.Timer
This is the bug from a different application. This one shows how bad MSDN is.
So I was making application that should every couple of minutes do some work and notify user after it’s done. Application was working silently in the background so as a notify facility I chose TaskbarNotifier, it does a great job of informing user without disturbing her.
So, how do you run a task every couple of minutes? You going to use timers of course. What the first thing you see if you look for “timer” in MSDN? System.Threading.Timer, which is, and I cite, “a simple, lightweight timer that uses callback methods and is served by threadpool threads. You might also consider System.Windows.Forms.Timer for use with Windows forms, and System.Timers.Timer for server-based timer functionality. These timers use events and have additional features.” Apart from threadpool reference is what I wanted, simple and lightweight. So I ignored that sign and go coding. Implementing was easy, everything worked just fine until I finally got to the point where I wanted to notify user. Notification just wasn’t working at all.
I saw a demo and knew it should work so I start debugging. Got into library code and noticed that timer callback that lib uses to slide window slowly just doesn’t fire. I found this thread but I thought it doesn’t apply to my situation, I do all my stuff in a single thread. After minutes of frustration and googling I decided to rewrite TaskbarNotifier a little with System.Threading.Timer since I knew it work well. And I did, and it crashed with the exception saying some GUI control was used in a thread different from where it was created. And then it hit me, “Threading” is all about threads, isn’t it? And I read documentation carefully and yes, this timer spans a new thread for callback. Not sure how this is “lightweight” but here you go. Yes, changing System.Threading.Timer to System.Windows.Forms.Timer made everything work just fine. But hell, this line about new thread should be right there, in one-line description of a class, that’s what I read after all. And yes, it’s not near simple or lightweight, so it shouldn’t be stated there. And yes, the first class in search should be most used one, System.Windows.Forms.Timer, what’s wrong with relevancy there?
That’s it. I didn’t make any more mistakes those couple of weeks. I did much more in my life of course but well, as I already said it’s inevitable. Be proud of your mistakes, they make you better.