Why do unexpected Timer Elapsed Events fire in my application? [Josh Free]
General Timer Background Information
The System.Timers.Timer class provides a convenient way for .NET programmers to create a timer thread that fires events after elapsed time intervals. For more details on using System.Timers.Timer please refer to the MSDN Timer Class documentation: https://msdn.microsoft.com/library/default.asp?url=/library/en-us/cpref/html/frlrfsystemtimerstimerclasstopic.asp.
Scenario
Earlier this year, we were contacted by a programmer who was experiencing weird Timer behavior in their application. This person wanted to use timers to have their application continuously execute a time-intensive task with a four (4) second pause between tasks. However, their application behaved very strangely – firing elapsed events at seemingly random intervals. It turned out that the odd behavior was caused by two factors:
1. The Interval was reset near the start of the ElapsedEventHandler method – which started the next four (4) second countdown
2. The time-intensive task was started after the Interval was set and it sometimes ran longer than four seconds.
(Buggy) Code Example
Here’s a sample C# application that creates a Timer to fire after four (4) seconds. After the initial four seconds, the BuggyHandler ElapsedEventHandler is called to handle the ElapsedEvent:
using System; using System.Timers; // Timer using System.Threading; // Thread.Sleep & Interlocked.Increment public class Timer1 { static int count = 0; static System.Timers.Timer aTimer; public static void Main() { aTimer = new System.Timers.Timer(); aTimer.Elapsed += new ElapsedEventHandler(BuggyHandler); aTimer.AutoReset = false; // set the initial timer interval to 4 seconds aTimer.Interval = 4000; DateTime now = DateTime.Now; Console.WriteLine("Main: " + now + " " + now.Millisecond); aTimer.Enabled = true; Console.WriteLine("Hit [Return] to quit."); Console.Read(); } // This Elapsed Time Event Handler has a bug – the Timer Interval // is set near the beginning of the method right before a // long-running task occurs. The reset timer fires again // before this event handler has a chance to finish! private static void BuggyHandler(object source, ElapsedEventArgs e) { DateTime now = DateTime.Now;
Console.WriteLine("BuggyHandler[" + count + "]: " + now + " " + now.Millisecond); // the timer countdown begins as soon as Interval is set aTimer.Interval = 4000; // sleep for 7 seconds to simulate an event handler that // performs a long-running task. While the handler works // on its “task” the 4 second interval expires... Thread.Sleep(7000); // calling Start() resets the timer to 4 seconds aTimer.Start(); Interlocked.Increment(ref count); } } |
Buggy Program Output
Here is the output from the program above. There are two things you should notice about this output:
- The first two lines both have zero (0) for their printed “count”
- The time between events is oscillating between four (4) and seven (7) seconds
Main : 3/31/2006 2:41:30 PM 262 Hit [Return] to quit. BuggyHandler[0]: 3/31/2006 2:41:34 PM 284 BuggyHandler[0]: 3/31/2006 2:41:38 PM 291 BuggyHandler[1]: 3/31/2006 2:41:45 PM 302 BuggyHandler[2]: 3/31/2006 2:41:49 PM 309 BuggyHandler[3]: 3/31/2006 2:41:56 PM 321 BuggyHandler[4]: 3/31/2006 2:42:00 PM 328 BuggyHandler[5]: 3/31/2006 2:42:07 PM 339 BuggyHandler[6]: 3/31/2006 2:42:11 PM 346 BuggyHandler[7]: 3/31/2006 2:42:18 PM 358 BuggyHandler[8]: 3/31/2006 2:42:22 PM 364 BuggyHandler[9]: 3/31/2006 2:42:29 PM 376 BuggyHandler[10]: 3/31/2006 2:42:33 PM 383 |
Corrected Code Example
Here is the fixed ElapsedEventHandler. Instead of setting the Interval near the beginning of the method, the Interval is set at the very end.
// This Elapsed Time Event Handler does not have // Re-entrancy problems because the AutoReset=false and // the Interval is not set until the very end of the method private static void FixedHandler(object source, ElapsedEventArgs e) { DateTime now = DateTime.Now;
Console.WriteLine("FixedHandler[" + count + "]: " + now + " " + now.Millisecond); // sleep for 7 seconds to simulate an event handler that // performs a long-running task. Thread.Sleep(7000); // the timer countdown begins as soon as Interval is set aTimer.Interval = 4000; Interlocked.Increment(ref count); } |
Corrected Program Output
Here is the output using the fixed ElapsedEvent handler from the code sample above. In this example, the first two lines now correctly print zero and one in brackets ([0] [1]) instead of zero and zero ([0] [0]). Also the time between events is now always eleven (11) seconds (because of the 7 second sleep followed by the 4 second Interval).
Main : 3/31/2006 2:44:20 PM 30 Hit [Return] to quit. FixedHandler[0]: 3/31/2006 2:44:24 PM 53 FixedHandler[1]: 3/31/2006 2:44:35 PM 71 FixedHandler[2]: 3/31/2006 2:44:46 PM 89 FixedHandler[3]: 3/31/2006 2:44:57 PM 108 FixedHandler[4]: 3/31/2006 2:45:08 PM 126 FixedHandler[5]: 3/31/2006 2:45:19 PM 145 FixedHandler[6]: 3/31/2006 2:45:30 PM 163 FixedHandler[7]: 3/31/2006 2:45:41 PM 182 FixedHandler[8]: 3/31/2006 2:45:52 PM 200 FixedHandler[9]: 3/31/2006 2:46:03 PM 219 FixedHandler[10]: 3/31/2006 2:46:14 PM 237 FixedHandler[11]: 3/31/2006 2:46:25 PM 255 |
Comments
- Anonymous
April 24, 2006
Looks like a bug in Timer to me. The MSDN docs for Timer.AutoReset say:
If the Timer is already enabled when the Start method is called, the interval is reset. If AutoReset is false, the Start method must be called in order to start the count again.
Since BuggyHandler didn't call Start until after its 7-seconds work, it shouldn't have received another callback until (7 + 4) 13 seconds later. - Anonymous
April 24, 2006
Make that 11 seconds :) - Anonymous
April 25, 2006
ok - Anonymous
June 18, 2009
PingBack from http://firepitidea.info/story.php?id=566