RSS

Monthly Archives: April 2014

The curious case of System.Timers.Timer

Basically there are 3 Timer classes in .NET: WinForms timer, System.Timers.Timer and System.Threading timer. For a non-WinForms your choice is between the two latter timers. For years I have been working with System.Timers.Timer simply because I preferred it’s object model over the alternative.

The pattern that I choose to work with the Timer is always one of AutoReset=false. The reason is because except for rare cases, I do not require the same operation to be concurrently carried out. Therefore I do not require a concurrent re-entrant timer. So this is probably what my usual timer code looks like:

static void Main(string[] args)
{
    System.Timers.Timer t = new System.Timers.Timer();
    t.AutoReset = false;
    t.Interval = 100;
    t.Elapsed += delegate
    {
        try
        {
            DoSomething();
        }
        catch (Exception ex)
        {
            // TODO log exception
        }
        finally
        {
            t.Start();
        }
    };
    t.Start();

    Console.ReadKey();
}

private static void DoSomething()
{
    Thread.Sleep(1000);
}
  • Line 21: First Start of timer.
  • Line 18: When the logic is done, the Elapsed restarts the timer.

The try-catch-finally structure ensures that no exceptions will crash the process and that the timer will restart regardless of problems. This works well and as expected. However, recently I needed to run the code first time immediately and not await the first interval to fire the Elapsed event. Usually that’s also not a problem because you can call DoSomething before the invocation of the first timer Start like so:

static void Main(string[] args)
{
    System.Timers.Timer t = new System.Timers.Timer();
    t.AutoReset = false;
    t.Interval = 100;
    t.Elapsed += delegate
    {
        try
        {
            DoSomething();
        }
        catch (Exception ex)
        {
            // TODO log exception
        }
        finally
        {
            t.Start();
        }
    };

    DoSomething();
    
    t.Start();

    Console.ReadKey();
}

By calling DoSomething() before the first timer, we run the code once and only then turn the timer on. Thus the business code runs immediately which is great. But the problem here is that the first invocation of the DoSomething() is blocking. If the running code takes too long, the remaining code in a real-world app will be blocked. So in this case I needed the first DoSomething() invocation to run in parallel. “No problem” I thought: let’s make the first interval 1ms so that DoSomething() runs on a separate thread [almost] immediately. Then we can change the timer interval within the Elapsed event handler back to the desired 100ms:

static void Main(string[] args)
{
    System.Timers.Timer t = new System.Timers.Timer();
    t.AutoReset = false;
    t.Interval = 1;
    t.Elapsed += delegate
    {
        try
        {
            t.Interval = 100;

            DoSomething();
        }
        catch (Exception ex)
        {
            // TODO log exception
        }
        finally
        {
            t.Start();
        }
    };

    t.Start();

    Console.ReadKey();
}
  • Line 5: First time interval is set to 1ms to allow an immediate first time invocation of DoSometing() on a separate non-blocking thread.
  • Line 10: Changed the interval back to the desired 100ms as before.

I thought that this solves it. First run after 1ms followed by non re-entrant intervals of 100ms. Luckily I had logs in DoSomething() that proved me wrong. It seems like that the Elapsed event handler did in fact fire more than once at a time! I added a reference counter-like mechanism to demonstrate:

static int refCount=0;
static void Main(string[] args)
{
    System.Timers.Timer t = new System.Timers.Timer();
    t.AutoReset = false;
    t.Interval = 1;
    t.Elapsed += delegate
    {
        Interlocked.Increment(ref refCount);
        try
        {
            t.Interval = 100;

            DoSomething();
        }
        catch (Exception ex)
        {
            // TODO log exception
        }
        finally
        {
            Interlocked.Decrement(ref refCount);
            t.Start();
        }
    };

    t.Start();

    Console.ReadKey();
}

private static void DoSomething()
{
    Console.WriteLine(refCount);
    Thread.Sleep(1000);
}

As can be seen below, the reference counter clearly shows that DoSomething() is called concurrently several times.
ref1

As a workaround this behavior can be blocked using a boolean that will be set to true in the beginning of the Elapsed event and back to false at the finally clause, and testing that bool at the start of the Elapsed. If already true, not to proceed to DoSomething(). But this is ugly.

In the real world app things aren’t as clear as in a sample code and I was certain that the problem was with my code. I was absolutely confident that some other activity instantiated more than one class that contained this timer code and therefore I was witnessing multiple timers instantiated and fired. As this wasn’t expected I set out to find the other timers and instances that cause this but found none, which made me somewhat happy because I didn’t expect additional instances, but it also made me frustrated because the behavior was irrational and contradicts what I had known about timers. Finally (and after several hours of debugging!) I decided to google for it and after a while I came across a stackoverflow thread that quoted from MSDN the following (emphasis is mine):

Note If Enabled and AutoReset are both set to false, and the timer has previously been enabled, setting the Interval property causes the Elapsed event to be raised once, as if the Enabled property had been set to true. To set the interval without raising the event, you can temporarily set the AutoReset property to true.

Impossible!

OK, let’s remove the interval change within the Elapsed event handler. And behold, the timer works as expected:
ref2

WTF!? Are the writers of this Timer from Microsoft serious?? Is there any logical reason for this behavior?? This sounds like a bug that they decided not to fix but just document this behavior as if it was “by design” (and if anyone can come up with a good reason for this behavior, please comment).

Solution
Despite the MSDN doc, I wasn’t even going to see if setting “AutoReset property to true” temporarily solves it. This is even uglier than having a boolean to test if Elapsed has already fired and is working.

After considering switching to the Threading timer and see if this will provide the desired behavior, I decided to revert to what I consider as a more comfortable solution: I will not change the Interval but set it only once, and simply invoke DoSomething() for the first time in a separate thread:

static int refCount = 0;
static void Main(string[] args)
{
    System.Timers.Timer t = new System.Timers.Timer();
    t.AutoReset = false;
    t.Interval = 100;
    t.Elapsed += delegate
    {
        Interlocked.Increment(ref refCount);
        try
        {
            DoSomething();
        }
        catch (Exception ex)
        {
            // TODO log exception
        }
        finally
        {
            Interlocked.Decrement(ref refCount);
            t.Start();
        }
    };

    Task.Factory.StartNew(() =>
    {
        DoSomething();
        t.Start();
    }, TaskCreationOptions.LongRunning);

    Console.ReadKey();
}

In this solution I simply start a new long running thread, invoke DoSomething() first time and only then start the timer for the other invocations. Here’s the result:
ref3
The first run doesn’t use the timer so the ref counter is 0. The other invocations of Timer’s Elapsed event set the ref count as expected and run only once.

Advertisements
 
Leave a comment

Posted by on 25/04/2014 in Software Development

 

Tags: