System.Threading.Timer runs wild

[K1BBQ]

There are 2 places in my application where I use a System.Threading.Timer. The app is a Windows Service, and is deployed at several customer sites, where it runs continuously.

One timer is used to send a "Keep Alive" email message once every hour. When called, the delegate kicks off the routines that create and send the email so we know the customer installation is alive and running.

The other is used to purge unwanted log files. The app does continuous logging, and the logfile rolls over to a new logfile name at midnight, so the logs don't get too big. The trail of logs is limited to 10 days. Once a day, the log file purging routine is called by that timer's delegate. It examines all the logs in the logging directory and deletes any file found that is older than 10 days.

The code seems extremely straightforward:

Declared variables at the top of the class:
Private KeepAliveDelegate As TimerCallback
Private KeepAliveTimer As System.Threading.Timer

Start the timer in New():
KeepAliveDelegate = AddressOf KeepAliveTimerHandler
KeepAliveTimer = New System.Threading.Timer(KeepAliveDelegate, _
Nothing, _
New TimeSpan(DueTime), _
New TimeSpan(1, 0, 0))
[DueTime is a value calculated to determine the number of ticks from the present until the next clock hour, so KeepAlives come on the hour]

Timer delegate:
Private Sub KeepAliveTimerHandler(ByVal state As Object)
' Do the sending of the email
End Sub

That's all there is to it. The purging timer is equivalent, except for the parameters of the timer:
LogFilePurgeTimer = New System.Threading.Timer(LogFilePurgeDelegate, _
Nothing, _
New TimeSpan(1), _
New TimeSpan(24, 0, 0))
[This one does a purge when the Service starts, and at 24 hour intervals after]

The app has been used for over a year now and generally the timed events work just fine.

On four occasions before today (not always at the same customer site) we observed the hourly Keep Alive emails "running wild" - instead of a one hour interval, they were getting sent out at an interesting pattern of intervals. Each one has a timestamp in the log so I can say for sure that those are the intervals. The pattern would be to fire like this:
09:18:08 [10 sec]
09:18:18 [10 sec]
09:18:28 [10 sec]
09:18:38 [10 sec]
09:18:48 [10 sec]
09:18:58 [10 sec]
09:18:59 [ 1 sec]
09:19:08 [10 sec]
09:19:18 [10 sec]
09:19:28 [10 sec]
etc

Like that, without end.

Before today the solution was to just restart the Service.

Today it happened again, except that this time BOTH timers were running wild, both showing the same pattern. And the interesting thing is that restarting the Service did NOT fix it. At restart, both timers went right into the same run-wild pattern. I restarted 3 times and the behavior persisted. I then rebooted the computer and that fixed it.

How can a Timer run wild? And how could the behavior persist across a restart? Am I setting them up wrong? When I wrote them I got the syntax from a book on VB.Net

I wonder if there is something underlying, at a System level, is involved, but that is very troubling.

 

[ThatRickGuy]

I have a similar service and I set it up slightly differently.

Every midnight it closes and reopens a connection and restarts a listener. Instead of using a timer to force this, I user a private module level variable to track the date of the last reset. When the timer hits, it checks to see if LastReset.toshortdate <> Now.toShortDate. If they are different, then I fire off the restart.

You could do something like this and see if the Last timer tick was at a different interval then what it should have been. Then log that information.

The will keep the service running even though the timer is screwed up.

-Rick

VB.Net Forum forum796 forum855 ASP.NET Forum
I believe in killer coding ninja monkeys.

 

[K1BBQ]

I'm not clear what your idea is. You still have a timer, yes? What type of timer is it? The two I know of are System.Timers.Timer and the type in my app, System.Threading.Timer.

Are you saying that at the timer event, I could avoid the runaway effect by comparing to some variable and only let the Keep ALive message get sent if it meets some criterion? If so, then any time it runs wild, I would never know it. It would get into that state and only send me a normal-looking Keep Alive email right on time. This app runs on a system with no users present, no one to look at it unless a technician is sent over to check a problem.

The way it is now the only bad effect is that at our end we see a flood of emails. It doesn't really hurt anything but at least we know it's gone bad.

Again, this has only happened 5 times now in over a year, at 4 different user sites, where the Service runs all the time.

 

[ThatRickGuy]

class MyService
  private m_LastKeepAliveEmail as date
  private m_LastTick as date

  private sub TimerTick(...) handles MyThreadingTimer.Tick
    if m_lastKeepAliveEmail.addhours(1) <= now then
      'Send Keep Alive Email
      m_lastKeepAliveEmail = now
    Else
      'Log thread gone wild
    end if

    if m_lastTick.toshortdate <> now.toshortdate then
      'The date has changed, swap logs
    end if

    m_LastTick = now
  end sub

end class

This way, even if your timer gets screwed up and fires every 10 seconds, your processes (Keep alive and log swap) will still run at the correct time. Your log file will bloat. But you can add a flag to handle that. If you log a timer gone wild error, flip a blnBadTimer flag and check it before logging any more wild timer errors.

-Rick

VB.Net Forum forum796 forum855 ASP.NET Forum
I believe in killer coding ninja monkeys.

 

[K1BBQ]

I'm thinking

 

[K1BBQ]

Is the Tick event from a System.Windows.Forms.Timer? That's the only Timer with a Tick event that I have found so far. Would that work in a Service?

And still, it seems like solving the problem of the effects of the runaway (good trick to even keep the log from bloating), and leaves the timer in a runaway state indefinitely. I'm not sure that's a bad thing, once a second or once every ten seconds, that's not a big performance problem, I guess it just makes me squirm to do that kind of solution - if it gets started running wild, deal with the mess.

Any idea how a .Net object like a Timer with a specified interval can lose its mind like that?

 

[ThatRickGuy]

I just used the windows timer syntax because its what I had in my head at the moment. Use what ever type of timer you think is best for the situations and put the code in the sub that handles the related event.

As for allowing the service to continue with a runaway timer, I would think its the best available option. You are warned off the problem (via log/email), and the processes the service is responsible for continue to run appropriately.

I'm not sure why it happens. I've noticed as similar problem in a VB6 app I have to maintain. In some situations a hard coded ten minute timer will begin firing events every 1 minute. No idea why, we have a log system that warns us if it happens and we restart the app/server as needed.

-Rick

VB.Net Forum forum796 forum855 ASP.NET Forum
I believe in killer coding ninja monkeys.

 

[chiph]

That's the only Timer with a Tick event that I have found so far. Would that work in a Service?

Since it's a service, there's no user interface, and so you can't use the Timer from the Forms namespace. The one from the Threading namespace would be the correct one to use.

I would look into how objects get disposed, and see if you have a memory leak somewhere. You can use perfmon.exe to watch the .NET CLR garbage collector to see how often it's running, and if you're having a large number of objects surviving generations 1 and 2 gc cycles (generation 3 objects are released from memory, but are never compacted, so you can get memory fragmentation).

Chip H.


____________________________________________________________________
Donate to Katrina relief:

http://s1.amazon.com/paypage/PELYGQVJ8Q7IB/103-6821258-5919825

If you want to get the best response to a question, please read FAQ222-2244 first