Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

Last post 05-16-2008 22:28 by sgifford. 15 replies.
Page 1 of 2 (16 items) 1 2 Next >
Sort Posts: Previous Next
  • 05-13-2008 15:32

    Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

     Hello,

    I am using a LargeIntervalTimer  for an event that should occur every 30 seconds, or when a user requests it be performed right now (think of a POP mail checker).  The event may take longer than 30 seconds, and should be run again 30 seconds after it completes not 30 seconds after it starts (otherwise it can run continually, eating up the device's battery).

     I put together a test class with these member variables.  It uses log4net to log its progress.

            int sleepTime = 45000;
            int timerInterval = 30000;
            LargeIntervalTimer timer = new LargeIntervalTimer();
            private static readonly log4net.ILog log = log4net.LogManager.GetLogger(typeof(Form1));

    This code in the Form's Load event sets up the event handler:

                // Set up the timer
                log.Debug("Running with timer_Tick1");
                timer.Tick += new EventHandler(timer_Tick1);

    And these methods set the timer and simulate the work:

            private void setTimer()
            {
                log.Debug("Set timer for " + timerInterval + " ms");
                timer.Enabled = false;
                timer.Interval = TimeSpan.FromMilliseconds(timerInterval);
                timer.OneShot = true;
                timer.Enabled = true;
            }

            void doWork()
            {
                log.Debug("doing work for " + sleepTime + " ms");
                Thread.Sleep(sleepTime);
                log.Debug("done with work");
            }

    I initially implemented this by simply having the Tick event handler disable the timer (so if the user requested the action a timer won't start a second action when it expires), do the work, then set up the timer again.  This ran the first time, but not after that.  Here is the code:

            void timer_Tick1(object sender, EventArgs e)
            {
                log.Debug("timer ticked");
                timer.Enabled = false;
                doWork();
                setTimer();
            }

    My next implementation ran the work and set the timer in a seperate thread.  Its success seemed to depend on scheduling; if the Tick handler completed before the thread started it would work OK, otherwise it would not.  When it failed it would sometimes not run at all, and sometimes the event would run immediately when setTimer() was run. For the test version I have added a Thread.sleep() call to cause the thread to run before the Tick handler exits, demonstrating the problem:

            void timer_Tick6(object sender, EventArgs e)
            {
                log.Debug("timer ticked");
                ThreadPool.QueueUserWorkItem(new WaitCallback(delegate(object arg)
                {
                    timer.Enabled = false;
                    doWork();
                    setTimer();
                }));
                Thread.Sleep(2000);
            }

    If I take the opposite approach, making the thread sleep to ensure the Tick handler finishes first, things seem to work as they should, though it is a bit of a hack and not guaranteed to work all the time:

             void timer_Tick7(object sender, EventArgs e)
            {
                log.Debug("timer ticked");
                ThreadPool.QueueUserWorkItem(new WaitCallback(delegate(object arg)
                {
                    Thread.Sleep(2000);
                    timer.Enabled = false;
                    doWork();
                    setTimer();
                }));
            }

    So, my question is: is this expected behavior, or a bug?  Are there restrictions on when LargeIntervalTimer objects can be updated, and are they documented anywhere?  Is it better to create a new LargeIntervalTimer every time, or will that consume a lot of resources?  And is there a better way of doing this that I haven't thought of?

    Thanks!

    ----Scott.


    Filed under:
  • 05-13-2008 23:11 In reply to

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    I tried re-implementing this to a new LargeIntervalTimer every time.  It seems to work much more reliably, but I'm concerned it will leak resources.  Looking at LargeIntervalTimer in Reflector, it appears to create two EventWaitHandle objects in its constructor (m_waitHandle and m_quitHandle).  EventWaitHandler implements IDisposable, so both of these objects should be Disposed.  But LargeIntervalTimer does not implement IDisposable, so they can't be disposed directly, and its destructor only closes m_waitHandle.  Does that mean m_quitHandle will be leaked?  And shouldn't LargeIntervalTimer implement IDisposable?  Or am I missing something?

    Thanks again!

    ----Scott.

  • 05-14-2008 7:20 In reply to

    • luthv
    • Top 50 Contributor
    • Joined on 03-04-2008
    • Posts 8

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    Is there a reason to use a timer and to run the work process in another thread? Since from your description a spin and wait with AutoResetEvent or ManualResetEvent will do the trick, something like

    ManualResetEvent waiter = new ManualResetEvent(false);

    while (waiter.WaitOne(30000, false) == false)

    {

        DoWork(); //do your work here for as long as you like

    And one more thing, using Thread.Sleep is not recommended since the thread is not guaranteed to wakes up at the exact sleep interval specified.

    Regards,

    Luthfi 

  • 05-14-2008 8:25 In reply to

    • luthv
    • Top 50 Contributor
    • Joined on 03-04-2008
    • Posts 8

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

     oops..I've made a mistake, bettter change the code to this:

     ManualResetEvent waiter = new ManualResetEvent(false);

     AutoResetEvent workWaiter = new AutoResetEvent(false);

    while(waiter.WaitOne(30000, false) == false)

    {

    if ( workInProgress == false)

    DoWork();

    else

    //the work is already called possibly by another thread, so just wait for it to complete and resume our timer

    workWaiter.WaitOne();

    }

     

    while in your doWork method set the workWaiter when it's complete, the DoWork method can be safely called by another thread or in this case by the UI thread if the user wants to initiate the work manually

    void DoWork()

    {

    if (workInProgress == false)

    {

    workInProgress = true;

    ...do something here

    //set the completion flag

    workInProgress  = false;

    workWaiter.Set();

    }

     }

     

    And you might want to put some extra lock before reading/writing the workInProgress variable to make sure it is thread-safe

  • 05-14-2008 8:40 In reply to

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    Thanks luthv,

    I'm using LargeIntervalTimer because my interval can be long enough that the device will go to sleep while it's waiting for it.  I believe a regular call to WaitOne() will not cause the device to wake up if it is asleep, while LargeEventTimer uses CeRunAppAtTime, which will wake it up.  I would be happy to find out I'm wrong, of course!

    Thanks again,

    -----Scott.

     

     

  • 05-14-2008 10:14 In reply to

    • ctacke
    • OpenNETCF Staff
    • Top 10 Contributor
    • Joined on 07-27-2007
    • Indiana
    • Posts 1,890

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    Part of the problem is likely that there are low-end constraints on the LIT based on OS settings.  You really cannot set a LIT to fire less than about 11 seconds into the future.  Trying to do so will lead to the LIT timer either firing immediately or not firing at all (depending on your platform).  THe next SDF release will have bounds checking that will throw ArgumentExceptions when you try to set it to under 15 seconds for this exact reason.

    If you're doing stuff on really short intervals like this it probably beeter to use a standard timer or a loop.  If you're concerned about the device going to sleep then call SystemIdleTimerReset periodically to prevent the device from sleeping.
     

  • 05-14-2008 11:03 In reply to

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    Thanks ctacke,

    I'm aware of timing constraints in LIT, and am careful not to set the timer to less than 30 seconds.  This seems to be the smallest value I can reliably set it to on my platform, and if I use the workarounds described above the timer will fire reliably, so I don't think the length of the timer is an issue.

    Looking at LIT in Reflector, I think I'm running into a race condition of sorts between the thread running InternalThreadProc() and a thread making changes to the LIT.  If OneShot is set and the Tick handler tries to re-enable the timer (or the timer is re-enabled while the Tick handler is running), at the end of the loop m_enabled will be set to false, effectively disabling it.  Here is the sequence of events:

    1. Event is started with OneShot set
    2. Event fires, and tick handler runs
    3. Tick handler re-enables the timer
    4. Tick handler completes.  The InternalThreadProc that was running the tick handler finishes the loop (because m_oneShot is false), then sets m_enabled to false.

    If the tick handler first sets Enabled to false, the state may become inconsistent.  Here's the sequence of events:

    1. Event is started with OneShot set
    2. Event fires, and tick handler runs
    3. Tick handler disables timer when it starts.  This causes m_quitHandle to be set, and sets m_enabled is false.
    4. Tick handler re-enables the timer.  This creates a new thread and starts another InternalThreadProc(), and sets m_enabled to true.
    5. Tick handler completes.  The InternalThreadProc that was running the tick handler finishes the loop (because m_oneShot is false), then sets m_enabled to false.
    6. Now the timer is actually running, but m_enabled is false.  Trying to enable it again will start another thread, and eventually both threads may fire the Tick event.

    Both of these can be worked around by delaying re-enabling the timer until after the Tick handler completes, which is consistent with what I'm seeing.

    They can also be worked around by creating a new LIT every time it needs to be re-enabled, but it looks to me like that leaks resources (see my earlier post), and when I try it my device begins acting strangely after running for a few hours. I don't know how to get a count of the number of named events in the system to see if they are actually accumulating, but when I modify LIT to Close m_quitHandle, implement IDisposable, and Dispose the event before creating a new one, it seems to work reliably, at least for the 12 hours I let it run.

    Unless somebody sees a flaw in this analysis, I'll go ahead and file a bug.  It seems to me that LIT should be threadsafe with its own InternalThreadProc(), or if not the possible issues should be well-documented.  I'll hack on it a little bit and see what I come up with.


  • 05-14-2008 12:40 In reply to

    • ctacke
    • OpenNETCF Staff
    • Top 10 Contributor
    • Joined on 07-27-2007
    • Indiana
    • Posts 1,890

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    It's definitely a bug and the following test proves it out:

    [TestMethod()]
    [
    Description("Ensures that the Enabled property coupled with the Tick hanlder is thread safe")]
    public void EnabledThreadSafetyCheck()
    {
       
    LargeIntervalTimer lit = new LargeIntervalTimer();
        lit.Interval =
    new TimeSpan(0, 0, 20);
        lit.OneShot =
    true;
        lit.Tick +=
    new EventHandler(EnabledThreadSafetyTick);
        m_ticks = 0;
        lit.Enabled =
    true;

     

        // wait > 20 seconds for 1 tick period to pass
        Thread.Sleep(25000);
        Assert.AreEqual(1, m_ticks, "LIT didn't tick the first time");

        // wait > 20 seconds for 1 tick period to pass
        Thread.Sleep(25000);
        Assert.AreEqual(2, m_ticks, "LIT didn't tick the second time");
    }

    private volatile int m_ticks = 0;

    void EnabledThreadSafetyTick(object sender, EventArgs e)
    {
        LargeIntervalTimer lit = (LargeIntervalTimer)sender;
        m_ticks++;
        if (m_ticks == 1)
        {
            // re-enable the LIT once
            lit.Enabled = true;
        }
    }

    I've added it, as well as the resolution status to Bugzilla as bug 251

  • 05-14-2008 13:03 In reply to

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    Thanks as always, ctacke!

    In my second comment above, I noted that m_quitHandle is not closed in the destructor.  EventWaitHandle does not implement a destructor, and it looks to me like m_quitHandle leaks an event.

    Also LargeIntervalTimer contains two IDisposable resources, but does not itself implement IDisposable, so it's impossible for client code to clean up the handle (of course it will be eventually cleaned up by the garbage collector).

    Am I missing something here?  If not I have a fix for both of these in a local version of LargeIntervalTimer I'd be happy to share.

     

  • 05-14-2008 13:24 In reply to

    • ctacke
    • OpenNETCF Staff
    • Top 10 Contributor
    • Joined on 07-27-2007
    • Indiana
    • Posts 1,890

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    The m_quitHandle should be getting closed (and the code now does), though it's not necessairly a leak.  Since EventWaitHandle implements Dispose, the GC will eventually call it and clean it up - it's just better practice to clean it up when we know we no longer need it.

    As for the IDisposable resources, like it's desktop counterpat, the EventWaitHandle object doesn't expose Dispose it's Dispose method, which indicates that consumers needn't Dispose it (and they can't if they want to).

  • 05-14-2008 13:27 In reply to

    • ctacke
    • OpenNETCF Staff
    • Top 10 Contributor
    • Joined on 07-27-2007
    • Indiana
    • Posts 1,890

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    The m_quitHandle issue is filed as bug 252

  • 05-14-2008 14:44 In reply to

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    Thanks again!  I did see issues with network connections not working properly on my phone after creating and destroying a few hundred LIT objects over the course of 12 hours or so (because I worked around the race condition by creating a new LIT every time I needed a timer).  My code was doing timer operations and little else, so it's possible that it did not have enough wasted memory to trigger GC.  If that were the case it could accumulate a large number of open event handles.  If event handles are a finite resource, other applications would not be able to create more at that point, and if the network connector needs to create an event, it would fail.  Of course that is all speculation, it could be coincidence.  I will try some quick experiments and see what I find.

    At any rate, some kind of Dispose() or Close() method would be useful for making sure the events are cleaned up right away, especially in a situation where a large number of LITs are created for single-use events.

     

  • 05-14-2008 22:23 In reply to

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

     I looked into the resource handling a little more closely.  The original version really does seem to leak an event.  Since EventWaitHandle doesn't have a destructor, it is never destroyed unless it is explicitly Disposed or Closed; as far as I can tell the Dispose method isn't called automatically.

     Here was my test.  I made a copy of EventWaitHandle and called it EventWaitHandle2, added a static counter to the class, then incremented the counter when CreateEvent is called, and decremented it when CloseEvent was called.  Like this:

        public partial class EventWaitHandle2 : WaitHandle
        {
           // ...
            public static int countOpenEvents = 0;
           // ...
             public EventWaitHandle2(bool initialState, EventResetMode mode, string name)
                : this(CreateEvent(IntPtr.Zero, mode == EventResetMode.ManualReset, initialState, name))
            {
                ++countOpenEvents;
            }

            public EventWaitHandle2(bool initialState, EventResetMode mode, string name, out bool createdNew)
            {
                IntPtr h = CreateEvent(IntPtr.Zero, mode == EventResetMode.ManualReset, initialState, name);
                if (h.Equals(IntPtr.Zero)){
                    throw new ApplicationException("Cannot create " + name);
                }
                createdNew = (Marshal.GetLastWin32Error() != ERROR_ALREADY_EXISTS);
                ++countOpenEvents;
                this.Handle = h;
            }

            protected override void Dispose(bool explicitDisposing)
            {
                if (this.Handle != InvalidHandle)
                {
                    CloseHandle(this.Handle);
                    this.Handle = InvalidHandle;
                    --countOpenEvents;
                }
                base.Dispose(explicitDisposing);
            }

    I then created 1000 of these objects in a loop, and printed the static counter with log4net:

                for (int i = 0; i < 1000; i++)
                {
                    EventWaitHandle2 testHandle = new EventWaitHandle2(false, EventResetMode.AutoReset);
                    log.Debug(EventWaitHandle2.countOpenEvents + " open events");
                }

    At the end of the loop,  the counter was 1000, indicating that CloseHandle was never called.

    If I add a simple destructor:

            ~EventWaitHandle2()
            {
                Dispose(false);
            }

    then countOpenEvents never gets above 10 or so before GC happens and the handles are closed.

    It looks to me like EventWaitHandle should probably have such a destructor.

    Also, although EventWaitHandle does indeed hide its Dispose method, it exposes a Close method which simply calls Dispose, so it is possible for a user to dispose this.

     

  • 05-14-2008 22:45 In reply to

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

     Sorry to keep pestering, but there's one other issue I came across while debugging my app and writing some test cases for LIT.  If the app creates a LIT for some time in the future and then exits, the timer thread will continue to run, preventing the application from exiting.  For me at least this was quite unexpected behavior.  It is different from the Windows Form timer at least, which does not prevent an application from exiting.

    I solved it in my local copy of LargeIntervalTimer by making the timer thread a background thread:

        new Thread(new ThreadStart(this.InternalThreadProc)) { IsBackground = true }.Start(); 

    It's possible (though unlikely IMHO) that a user would actually want the timer to continue running after their app exits, so maybe it would make sense for this to be optional.  At any rate, it should most likely be clearly documented.

    Thanks again for your continued help!

     

  • 05-16-2008 17:40 In reply to

    Re: Strange behavior adjusting LargeIntervalTimer properties while Tick event is running

    Thanks for the posts!  I have seen this issue in my app for the past week and could not figure out why my event was sometimes seemingly not being fired any more.  I have implemented the IDisposable in my local copy and will test tonight.  Can you talk more out your background thread and where you implemented the code?

     

    Thanks again, great stuff!

Page 1 of 2 (16 items) 1 2 Next >