Donkblog

A little early, but who is keeping score? Timers!

I ran into a problem the other day at work where I had put in an assert to verify that a timer I was using was not being called back too early.  The timer interval was adjusted depending on user interaction and I just wanted to make sure interval was always being set correctly.

For the most part everything was fine, however I started to get reports that the assert started to show up every once and a while.   I ended up removing the assert because the callback time and the expected callback time were so close it didn’t matter in my case.

This intrigued me though. So I wrote a little test program to make sure that it wasn’t a problem with my code, and I copied the relevant part of the that test application here:

DateTime _startTime;
Timer _currentTimer;
private void button1_Click(object sender, EventArgs e)
{
    StartTimer();
}

public void StartTimer()
{
    _currentTimer = new Timer();
    _startTime = DateTime.Now;
    _currentTimer.Interval = 1000;
    _currentTimer.Tick += new EventHandler(t_Tick);
    _currentTimer.Start();
}

void t_Tick(object sender, EventArgs e)
{
    // What time is it now?
    DateTime now = DateTime.Now;

    // Add the interval to the time when we started the timer, 
    // this is the earliest possible
    // time we should be called back
    DateTime minCallbackTime = _startTime.AddMilliseconds(1000);

    // Check to see if the time we though was 
    // first possible to call back is greater then
    // the current time we were called back to make 
    // sure it isnt in the future.
    if (minCallbackTime > now)
    {
        String output = String.Format("The minimum callback time was {0} but the current time is {1} with a total difference of {2}", 
                                       minCallbackTime, 
                                       now, 
                                       minCallbackTime.Subtract(now).TotalMilliseconds);
        Debug.WriteLine(output);
    }
    else
    {
        Debug.WriteLine("All is quiet on the western front.");
    }

    _currentTimer.Dispose();

    // Start the process again
    StartTimer();
} 

The log looked like:

The minimum callback time was 4/27/2008 5:09:21 PM but the current time is 4/27/2008 5:09:21 PM with a total difference of 2.9935
The minimum callback time was 4/27/2008 5:09:22 PM but the current time is 4/27/2008 5:09:22 PM with a total difference of 1.0405
All is quiet on the western front.
All is quiet on the western front.
The minimum callback time was 4/27/2008 5:09:25 PM but the current time is 4/27/2008 5:09:25 PM with a total difference of 10.8055
The minimum callback time was 4/27/2008 5:09:26 PM but the current time is 4/27/2008 5:09:26 PM with a total difference of 0.064
The minimum callback time was 4/27/2008 5:09:27 PM but the current time is 4/27/2008 5:09:27 PM with a total difference of 1.0405