Thread ignoring Sleep but works initially 2024 R4.2

I have several Threads, each with a sender.Sleep(8000) at the bottom of the loop, and everything works as it should, normally.

For some reason it’s as if all the Threads in my app suddenly start ignoring the Sleep statement, but execute the code both before and after Sleep line, rapidly over and over.

I’ve set up counters outside of the loop, to make sure it isn’t a new Thread being instantiated, and as I expected the counter increments - showing me that the same Thread/Loop is running.

Once the Threads stop honoring the sender.Sleep() they continue to ignore it, until I restart the app.

The call to ‘Sleep’ is done in the Method defined as the AddHandler for the Thread’s .Run event.

Here’s an example of how I’m instantiating the Thread…

' start scanner_MONITOR_LOCKS (thread)
scanner_MONITOR_LOCKS = New xThread_class
scanner_MONITOR_LOCKS.Priority = Thread.NormalPriority

AddHandler scanner_MONITOR_LOCKS.Run, AddressOf scanner_MONITOR_LOCKS_action
scanner_MONITOR_LOCKS.Start()

Additional observations…
It seems that it does recover, but only after ‘bursting’. Once the sleep(10000) ten seconds is ignored, it does a burst where the loop runs 14x in a row, then ten seconds later it bursts, and then again another ten seconds later. Then for some reason it starts obeying the sleep request, executing a single time, then sleeping, etc.

20:40:06 : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 26
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 27
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 28
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 29
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 30
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 31
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 32
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 33
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 34
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 35
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 36
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 37
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 38
         : Feb 21 20:40:06  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 39
20:40:16 : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 40
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 41
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 42
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 43
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 44
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 45
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 46
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 47
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 48
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 49
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 50
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 51
         : Feb 21 20:40:16  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 52
20:40:26 : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 53
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 54
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 55
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 56
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 57
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 58
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 59
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 60
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 61
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 62
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 63
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 64
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 65
         : Feb 21 20:40:26  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 66
20:40:36 : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 67
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 68
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 69
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 70
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 71
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 72
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 73
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 74
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 75
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 76
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 77
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 78
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 79
         : Feb 21 20:40:36  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 80
20:40:46 : Feb 21 20:40:46  notify.debug[75455] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 5385556480 counter: 81

Final observation…

It appears as though it does ‘sleep’, but when it awakes it executes the code for X-times repetitively, as though it’s trying to catch up for all the loops it would have executed during the time it was asleep.

so where is your loop code?

in your sender.Sleep(… ) is the WakeEarly paramter False or true?

1 Like

Hi Derk,

Here’s the reduced version of the code. I didn’t explicitly state False for WakeEarly, since according to the docs that’s the default value.

Private Sub scanner_MONITOR_LOCKS_action(sender As xThread_class)
  
  Var keep_running As Boolean = True
  Var counter As Integer = 0
  
  While keep_running
    // do some tasks here
    sender.Sleep(10000)    
    counter = counter +1
    System.DebugLog(CurrentMethodName + " sender.ThreadID: " + sender.ThreadID.ToString + " counter: " + counter.ToString)
    
  WEnd
    
End Sub
1 Like

And you don’t have any calls to Resume on those threads?

1 Like

I am curious though… why isn’t this a Timer if you need a 10 second delay?

In many cases I’ll use conditional statements with a Thread’s loop to adjust the Sleep(time) dynamically.

I never distrusted the thread.Sleep() function in the past, and would really like to continue using it - if I can just find out why it’s behaving so unexpectedly.

Hi Greg, no - no calls to Resume anywhere. Any function that would Stop or Start these threads also contains Debug output, so I can see whenever they run - the only output I’m seeing is the “run away” thread loop.

More observations (Thread knows it’s sleeping but still runs!)

I put a select-case in the bottom of the loop, and it reports “Running” each time, as it should, since once it finishes Sleeping it should in fact be running. However, when a run-away state happens you can see the code loops agressively, and reporting that it’s ‘Sleeping’ the whole time.

09:10:17 : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 4999656448 counter: 160
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action Running
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 4999656448 counter: 161
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action Sleeping
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 4999656448 counter: 162
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action Sleeping
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 4999656448 counter: 163
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action Sleeping
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 4999656448 counter: 164
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action Sleeping
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 4999656448 counter: 165
         : Feb 22 09:10:17  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action Sleeping
09:10:27 : Feb 22 09:10:27  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 4999656448 counter: 166
         : Feb 22 09:10:27  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action Sleeping
         : Feb 22 09:10:27  notify.debug[85337] <Warning>: AUTOMATIONS.scanner_MONITOR_LOCKS_action sender.ThreadID: 4999656448 counter: 167

Do you call Thread.YieldToNext (shared method) anywhere?

Maybe that forces a thread to resume could be a bug if that happens. I’ve not seen threads move past the sleep boundary unless manually Resume or wakeEarly = true.

Well not to spoil anything while that ‘may’ be a solution let’s keep it to the thread so that we all know what may cause this.

Ok great. Now we is there aything that may get a thread to slow down.

  • is this a cooperative thread?
  • Is there alot of threads?

Do you make alot of instances if this Addressed Thread?
Make sure to use WeakAddressOf and make sure to RemoveHandler after the thread is done (close event or Destructor).
Do you happen to do this?

Well there’s nothing fancy about this thread, and there are several more threads in the app, and they all seem to misbehave the same way. It’s not set as preemptive, and the debug output shows it’s the same Thread_ID (not a new instance of the thread) the entire time.

I’m now leaning towards a temporary solution, wrapping the content of the thread’s code with

If sender.ThreadState <> Thread.ThreadStates.Sleeping Then

…to bypass executing internal code while the Sleeping thread is ‘Sleep Walking’.

So that may be because you use AddHandler with AddressOf ? Since Addressof holds a reference to the thread. If you don’t use RemoveHandler in the correct way it will leak (e.g. stay alive).

Di you intent to use new threads (instances) or is it purposely that you re-use the same?

I’ve intentionally been keeping these specific threads alive, sleeping and waking and starting and stopping them based on the needs of the app.

For instance, one thread polls a dbase for ‘new’ records, then calls methods to process the data, then sleeps and waits to poll again, and again. I only want a single instance of this thread, as multiple instances wouldn’t be useful for this process.

1 Like

Trying to replicate this. I see this behavior if I instantiate the Thread instance on a WebPage, but not if I create and manage the thread in the App class, due to multiple sessions:

5:09:52 PM : My Application Launched
5:10:03 PM : Feb 22 17:10:03  My Application.debug[47387] <Warning>: App.onThreadRun sender.ThreadID: 4538866688 counter: 1
           : Feb 22 17:10:03  My Application.debug[47387] <Warning>: WebPage1.onThreadRun sender.ThreadID: 4974494720 counter: 1
5:10:08 PM : Feb 22 17:10:08  My Application.debug[47387] <Warning>: WebPage1.onThreadRun sender.ThreadID: 4395682304 counter: 1
           : Feb 22 17:10:08  My Application.debug[47387] <Warning>: WebPage1.onThreadRun sender.ThreadID: 4546747904 counter: 1
5:10:13 PM : Feb 22 17:10:13  My Application.debug[47387] <Warning>: App.onThreadRun sender.ThreadID: 4538866688 counter: 2
           : Feb 22 17:10:13  My Application.debug[47387] <Warning>: WebPage1.onThreadRun sender.ThreadID: 4974494720 counter: 2
5:10:18 PM : Feb 22 17:10:18  My Application.debug[47387] <Warning>: WebPage1.onThreadRun sender.ThreadID: 4395682304 counter: 2
           : Feb 22 17:10:18  My Application.debug[47387] <Warning>: WebPage1.onThreadRun sender.ThreadID: 4546747904 counter: 2
5:10:19 PM : Process Completed.
           : My Application Ended

I can’t seem to reproduce it otherwise. Can you provide an example project?

I will try to create a sample project. :+1:t2:

1 Like

Oh fer… sorry. I should have been paying closer attention.

The Web Framework, because of its high dependency on Threads does call YieldToNextThread in places to make sure things run smoothly. You’re not going to be able to get around that without a major overhaul from Xojo.