Unittests testing timers fail indeterministically on TFS

Question

We do have a bunch of UnitTests for our projects which run during CheckIn on a TFS 2012 buildserver too. While locally they behave quite like expected, some weird behaviour occurrs with unittests using timers on TFS occassionally. Finally we wrote a class and a test to isolate that behaviour.

The class:

public class TestTimerOnServer    
{    
    Timer _MyTimer = new Timer(100);    
    int _CountsToDo = 100;    
    public int TimerElapsedCounter = 0;

    public TestTimerOnServer()    
    {    
        _MyTimer.Elapsed += _MyTimer_Elapsed;    
    }

    public void StartCounting(int argNumberOfCounts, int argIntervalInMs)    
    {    
        _MyTimer.Stop();    
        _MyTimer.Interval = argIntervalInMs;    
        TimerElapsedCounter = 0;    
        _CountsToDo = argNumberOfCounts;    
        _MyTimer.Start();    
    }

    void _MyTimer_Elapsed(object sender, System.Timers.ElapsedEventArgs e)    
    {    
        if (_CountsToDo > TimerElapsedCounter)    
            TimerElapsedCounter++;    
        else    
            _MyTimer.Stop();    
    }    
}

The test running against it:

private void TestTimerServerBehaviour()   
{   
   TestTimerOnServer ttos = new TestTimerOnServer();   
   ttos.StartCounting(10, 100); // should lead 1000 ms

   // we wait 1100 MS   
   Thread.Sleep(1100);

   Assert.AreEqual(ttos.TimerElapsedCounter, 10,"We should have 10 
   samples, but only " + ttos.TimerElapsedCounter + " have been generated.!"); 

   ttos.StartCounting(50, 100); // should lead 5000 ms

   // we wait 6000 MS   
   Thread.Sleep(6000);

   Assert.AreEqual(ttos.TimerElapsedCounter, 50, "We should have 50 
   samples, but only " + ttos.TimerElapsedCounter + " have been generated.!");   
}

Most of the time this test passes, occassionally it fails on TFS - firing the event just e.g. twice instead of 50 times. So the question is do we suffer a general unittest design flaw here or are the problems rather to be found in running the test by the TFS build service?

EDIT: The TFS is running on a VM - might this be the origin of our problems?

EDIT2 - final investigation results The problem obviously was the combination of Testing-Context and VMware. I wrote small application using the code posted by @allen, a test using the same code and another one to cause load on the cpu:

void CPULoader()
{
    var action = new Action(() => { while (true);});

    Parallel.Invoke(action, action, action, action, action, action, action, action); 
}

Quite primitive though efficient.

On my hardware machine running the application and the CPU-Loader causes the timer event to occur a little later, e.g. 1100 ms instead of 1000. That's fine so far, Win7 is no realtime-system after all.

On a VMware the some combination causes delays up to 5000 ms where there should be one second... - much worse of course, but still the event occurs.

The real fun starts when running the test (I've packed the code into an infinite loop for that purpose) and then firing up the CPU-Loader. The whole system is very slow then until I stop loading the CPU and the event does not occur before in the test.

Hope this can give someone some hints - we have fixed our tests by using a Timer abstraction and mocking the timing behaviour while unittesting. As a side effect the tests run faster now :)

Yes, indeed - the TFS server is running on a VM - i will add that to the question. — ChriPf, Feb 27 '13 at 10:05
Which Timer class is this? Forms, Timers, or Threading? http://msdn.microsoft.com/en-us/magazine/cc164015.aspx — bryanbcook, Feb 27 '13 at 23:46
It is System.Timers.Timer wich is the only one with a constructor Timer(double interval) by the way. But I see i should have pointed that out. — ChriPf, Mar 01 '13 at 03:00

score 1 · Accepted Answer · answered Feb 26 '13 at 10:48

System calls to sleep and relatives often interact with signal handlers and abort their sleep early. The phenomenon is best documented for the Unix sleep(3) function, but I suspect it applies to your API as well. You should guard against short sleeps by checking the current time after sleeping.

Generally, you want to decouple your timer unit tests from the system clock as far as possible. I've had very good experience when working on queue-based timers and a heartbeat function that could be called externally, but you should always be able to dummy out the calls to sleep and time-fetching functions and then test without calling the real functions.

score 1 · Answer 2 · edited May 23 '17 at 12:12

My suspicion is on the VM. With a VM you can encounter issues related to time sync that can cause timing related functionality to run into problems. One way to verify this is by writing a simple piece of code and run it on the same VM.

Stopwatch watch = new Stopwatch();
System.Timers.Timer timer = new System.Timers.Timer();
timer.Interval = 30*60 * 1000;
timer.Elapsed += timer_Elapsed;
watch.Start();
timer.Start();

static void timer_Elapsed(object sender, ElapsedEventArgs e)
{
    watch.Stop();
    Console.WriteLine("Stopwatch value - {0}", watch.Elapsed);
    watch.Restart();
}

Another example is here on stackoverflow too System.Diagnostics.Stopwatch returns negative numbers in Elapsed... properties

Some of the factors that can cause this is a) disabled time sync service on the VM b) lack of resources on the host eg. too many VMs

My suggestion is to setup a new VM on a host with more resources dedicated to this VM

Lack of resources did not seem to be the problem - i moved the build service to a dedicated machine and the problems still occured. So more resources seem to make the problem more rare, but still not disappear. — ChriPf, Mar 07 '13 at 07:01

Unittests testing timers fail indeterministically on TFS

2 Answers2