_Timer_SetTimer not reliable

[Hawk]

Hello all! Sorry this is a rather long post, I need to learn to keep it short :S I hope somebody will read it at all.

I have big problems debugging this buggy behaviour of _Timer_SetTimer. In my script I use several timers to run several different functions at different times using _Timer_SetTimer (for example check and log the amount of free RAM every 60 seconds, make a screenshot of a particular window every 10 seconds, and so on).

The problem with one of these timed functions is that at some point it just stops being called. For debugging I have put a ConsoleWrite under each _Timer_SetTimer(), _Timer_KillTimer() and _Timer_KillAllTimers() to track if everything is set correctly or if a _Timer_KillAllTimers() kills my desired timer too without re-setting it.

I don't know if it happens to all timer functions, but in general they look like this:

Func function1($hwnd, $Msg, $iIDTimer, $dwTime)
    If $timer_function1 <> 0 Then
        _Timer_KillTimer($hGui, $timer_function1)
        Logg("Killed Timer.")
    EndIf

        ...do stuff...

    $timer_function1 = _Timer_SetTimer($hGui, 250, "function1")
    Logg("Set Timer. Nr " & $timer_function1)
    If $timer_function1 = 0 Then LogTimerError(@ScriptLineNumber)
EndFunc

Notice: "Logg()" just does a ConsoleWrite with a timestamp, "LogTimerError()" is similar.

The output I get is:

2012/03/11 18:01:49 Killed Timer.
2012/03/11 18:01:49 Set Timer. Nr 1005
2012/03/11 18:01:59 Killed Timer.
2012/03/11 18:02:00 Set Timer. Nr 1004
2012/03/11 18:02:10 Killed Timer.
2012/03/11 18:02:10 Set Timer. Nr 1004
2012/03/11 18:02:20 Killed Timer.
2012/03/11 18:02:20 Set Timer. Nr 1004

Everything fine, BUT at some point (after 2 minutes, after 30 minutes or after 8 hours, it's totally unpredictable and non-reproducable ) it just stops to be called. No more ConsoleWrite's from this timer. Other things still work normally, but sometimes also my HotKeys don't respond and make the script only to be killed via SciTE or Task Manager, but this also appears randomly and seems to have nothing to do with the timer problem (and is also not reproducable). The AutoIT processes have 0% CPU though and I checked several times for infinite loops in my script, not finding any. (Also there is no single while/do loop in my script).

Ok back to the problem. How would I track such bug? The program works normally, just the timer stops functioning. AutoIT Debugger doesn't work for me because of the "OnAutoItExitRegister" (or so) error, even though I don't use that function/label whatever it is. All necessary timer events are logged...

Another notice: I use _Timer_SetTimer() instead of TimerInit() because I have many timed functions, and I use _Timer_SetTimer() instead of AdlibRegister, because Adlib stops the timer when a function like MsgBox is blocking the script and I want to avoid that. Simple demo script:

#include

;AdlibRegister("Function1", 500)
_Timer_SetTimer(0, 500, "Function2")

While 1
    MsgBox(0, "", "")
WEnd

Func Function1()
    ConsoleWrite("AdlibRegister" & @CRLF)
EndFunc

Func Function2($a, $b, $c, $d)
    ConsoleWrite("_Timer_SetTimer" & @CRLF)
EndFunc

Run and watch the debug console, then uncomment line 3 and comment line 4 and run again, watching the debug console. That's why I want to stick with _Timer_SetTimer().

Also I kill and reset each timer in its called function because I don't want it to be called multiple times within itself. For example if I call the function every 250 ms and the timer function has a Sleep(300), then it would be like this:

Time 0000: Set timer
Time 0250: Breakpoint in main program -> timed function is called first time (and sleep 300ms)
Time 0500: Still breakpoint in main program -> timed function is still called first time -> breakpoint in timed function ->
           timed function is called second time (and sleep again 300ms)
Time 0750: and so on, infinite loop

Killing the timer on function call and re-setting it only when the code is done solves this problem if a function takes longer than the delay between calls.

-

While writing this I found a possible cause. Probably it can be like this:

Time 0000: function1 timer is set to 250 ms (timer id 1)
Time 0000: function2 timer is set to 500 ms (timer id 2)
Time 0250: function1 performed (timer id 1 killed, then re-set to timer id 3)
Time 0500: function1 is called. timer id 3 is killed, the function1 does its stuff and calls _Timer_SetTimer().
           In _Timer_SetTimer() a new timer id is allocated (let's say timer id 4), but the timer is not set yet because of breakpoint:
Time 0500: function2 breaks function1 and is performed: timer id 2 killed, and timer is re-set ALSO with timer id 4,
           because it doesn't know that function1 allocated timer id 4 already. function2 ends and the code jumps
           back to where it breaked in function1 (right before it was about to set its timer). function1 sets its new timer
           ALSO to timer id 4 because it has already allocated this number and doesn't know that it's already used by function2's new timer id.
Time 0750: function1 performs.
Time 1000: function1 performs. function2 is never called again because it got stolen its timer id before.

Can this be a possible cause?

Edit: Especially when another timer breaks right after these lines in_Timer_SetTimer() in Timers.au3 (line 262):

For $x = 1 To $iIndex
            If $_Timers_aTimerIDs[$x][0] = $iTimerID Then
                $iTimerID = $iTimerID + 1
                $x = 0
            EndIf
        Next

In C I have written a program, where I used a "conch" system (from lord of the flies, only who has the conch could speak) for multithreading. If a function was called, I gave it the "conch" (1), and all other functions where waiting until the conch was untaken (0) again. I then improved it to use TryEnterCriticalSection(). Or it is similar to network tokens IIRC. If this is really the cause for these bugs, then maybe I should implement some kind of conch system too.

Thanks in advance if you have really taken the hassle to read all this

Edited March 11, 2012 by Hawk

[Melba23]

Hawk,

I did read it all and I am working on it.

I may have a solution for you but dinner intervenes - I will be back suitably fortified late this evening.

M23

[Melba23]

Hawk,

More complicated, but in some ways simpler, than I thought. Timers are not something I have used a lot - they are interesting beasts.

I will sleep on it and get back to you tomorrow.

M23

[Hawk]

Thanks for looking into it

I also appended something to my post. If the problem is really what I think it is then using a global timer id counter in Timers.au3 and rewriting _Timer_SetTimer() to give each newly set timer an unique ID.

[jchd]

I didn't spend as much time as Melba23 did and this is just a 30-second opinion.

I believe you're right in your possible cause explanation, but even making the ID assignment global doesn't make it an atomic operation: for that you'd need a mutex around it. Granted that $id+=1 makes a much narrower window for reentrancy in between the operation (which isn't limited to that), but it's still there. So my guess is that you're going to make the problem less common but still unpredictable and unreliable.

Again I may oversee something else, not having studied the code. I can take the risk, having eaten a number of hats before.

[kylomas]

Hawk,

You might be interested in this code by Gary Frost.

kylomas

[trancexx]

If the problem is reentrancy then there is nothing you can do. Every function that should be reentered must not use global variables. There is no mutex, semaphore or critical section that would be able to sensibly synchronize access to the code in case of interrupting.

This is because execution just jumps from one point to another. Every global variable that's set before the jump is found in set state after the jump - therefore synchronization is impossible.

The only correct thing to do is to use and manipulate only (on) local scope. In that case all works beautifully.

Here's the catch - AutoIt uses global scope variables and objects internally even if the script is executed within function. Every local variable is stored inside global object. Draw conclusions yourself from there.

[Melba23]

Hawk,

That was hard work and I do not have a solution for you. I do have a couple of general points that I discovered about _Timer functions that may be of interest to you though.

When you run a _Timer and try to call it again before it has terminated the new call appears to be discarded, so you do not get the calls queued as I originally expected. So there is no need for you to continually destroy and recreate the _Timer within the functions - which I think may well be the root cause of your problem.

Secondly, any other _Timers are not actioned either! I must admit this came as somewhat of a surprise, as I had always believed that _Timers were separated from the running script. It seems that another _Timer will add its call to the queue, but as before will then not add further calls until that call is honoured by the system once the running _Timer has ended. And even this queued call is sometimes discarded meaning that the _Timer does not fire at all!

This script shows these events happening. The first _Timer is called every 2 secs, but Sleeps for 3 secs internally (more on this later) - the second _Timer should fire every 500 ms and return immediately. Just look at the counter values:

expandcollapse popup

#include <Timers.au3>

HotKeySet("{ESC}", "On_Exit")

$fTimer_Kill = False

$hGUI = GUICreate("Test", 500, 500)

$cLabel_1 = GUICtrlCreateLabel("", 10, 10, 200, 20)
$cLabel_2 = GUICtrlCreateLabel("", 10, 50, 200, 20)

GUISetState()

$cTimer_1 = _Timer_SetTimer($hGUI, 2000, "_Timer_Func_1")
$cTimer_2 = _Timer_SetTimer($hGUI, 500, "_Timer_Func_2")

While 1
    Sleep(10)
WEnd

Func _Timer_Func_1($hwnd, $Msg, $iIDTimer, $dwTime)
    Static $iCount_1 = 0
    $iCount_1 += 1
    If $fTimer_Kill = True Then Exit
    GUICtrlSetData($cLabel_1, "Firing Timer_1 for " & $iCount_1 & " at " & @SEC & ":" & @MSEC)
    Sleep(3000)
EndFunc

Func _Timer_Func_2($hwnd, $Msg, $iIDTimer, $dwTime)
    Static $iCount_2 = 0
    $iCount_2 += 1
    If $fTimer_Kill = True Then Exit
    GUICtrlSetData($cLabel_2, "Firing Timer_2 for " & $iCount_2 & " at " & @SEC & ":" & @MSEC)
    ;Sleep(1500)
EndFunc

Func On_Exit()
    _Timer_KillAllTimers($hGUI)
    ConsoleWrite("Exiting at " & @SEC & ":" & @MSEC & @CRLF)
    $fTimer_Kill = True
    Exit
EndFunc

Initially _Timer_2 rushes ahead as you would expect, but after 7/8 firings of _Timer_1 it is only on level peggings and then it falls far behind. You can also see the code I introduced to get the script to exit cleanly - by setting the flag you exit when the next queued _Timer exits as it fires - the Help file explains that _Timer_KillAllTimers does not itself remove these queued events.

Which brings me to my general points:

- 1. _Timers are not as independent as I thought.

- 2. Planning to set _Timer (or indeed Adlib) calling intervals which are knowingly shorter than the time the called function will take to complete is a bad idea and can only lead to problems.

Thanks for asking the question as it taught me a lot about _Timers that I did not know - and also taught me that they are even more complicated that I at first thought, at least when using several of them. Sorry I did not come up with a solution - basically from your description I think you are trying to do too many things too quickly in your script and running into timing conflicts. This would explain the random nature of the failures and also the complete breakdon of the script as you enter some internal loop.

So my advice would be to separate these timing critical events into separate scripts - you can compile them into .a3x files and FileInstall and Run them from the main script so you still have only the one executable - and try to get the timings closely matched to the function duration. That way the system itself can deal with the conflicts - which is what it is designed to do.

Like jchd above, I am quite ready to eat my headgear (note I only ever wear paper hats at Christmas ) if any of the above is complete garbage - but I have had enough of these pesky _Timer things for the moment and I am not digging any further.

M23

[Hawk]

Wow these _Timers are some strange things...

Thanks for all the input, especially for your intense tests, M23.

Yes I see and I am surprised that timer functions do not queue up, except one time as it seems, shown in this example (edited from yours):

Edit: I was just about to understand how the _Timers are queued up but then trying another example shows me totally non-understandable behaviour. Running this:

#include 

HotKeySet("{ESC}", "On_Exit")

$fTimer_Kill = False
$flag = 5

$hGUI = GUICreate("Test", 500, 500)

$start = TimerInit()
$cTimer_1 = _Timer_SetTimer($hGUI, 300, "_Timer_Func_1")

While 1
    Sleep(10)
WEnd

Func _Timer_Func_1($hwnd, $Msg, $iIDTimer, $dwTime)
    If $fTimer_Kill = True Then Exit
    Sleep(700*($flag>0))
    ConsoleWrite(TimerDiff($start) & "(slept for " & 700*($flag>0) & ")" & @CRLF)
    $flag -= 1
    $start = TimerInit()
EndFunc

gives me this output:

1020.12574223819(slept for 700)
709.856979029458(slept for 700)
708.912724941298(slept for 700)
708.916356687791(slept for 700)
708.933118594682(slept for 700)
0.675784212797995(slept for 0)
203.358248045492(slept for 0)
311.463049074673(slept for 0)
311.571163374116(slept for 0)
311.525626860397(slept for 0)
311.326718898631(slept for 0)
311.569207818312(slept for 0)
311.373652237924(slept for 0)

Line 1 is clear: 300ms for the timer to fire + 700ms sleep

Line 2-5: Queueing the functions to fire immediately after the previous is done with sleeping 700ms

Line 6: The queued function is ran immediately after the previous is done.

Line 7: ??????????

Line 8+: Normal behaviour

Anyways with your insights, M23, I will remove my _TimerKills and just try without them. If a function with a 10second+ timer needs more than 10 seconds to perform (because of msgboxes or whatever), then I can live with it being executed exactly one more time immediately afterwards. Just line 7 bugs me, it has nothing to do with the set numbers at all. And if a function with a ~20ms timer needs more than these 20ms to perform, it is also okay for me if it runs one more time immediately afterwards - the difference between 0ms and 20ms is not crucial.

I didn't know that killing the timers do not kill already queued functions too, so thanks for pointing that out, I will likely use your method to check for queued timer functions.

If I really cannot get it to work how I want, I will need to use several scripts as you wrote, but I would really like to avoid that for now.

I will report back interesting outcome.

@trancexx: I didn't quite get the message, I am not that versed in how AutoIT works. But I believed that it would be okay using a global variable for unique timer IDs because in Timers.au3 is also a globally declared array ("Global $_Timers_aTimerIDs[1][3]"), that all the _timer functions use.

Edit: @M23: I totally forgot to mention that I don't know what you wanted to say with timers being unreliable sometimes not firing at all. No matter for how long I run your demo program, timer1 is always 2 numbers behind.

Edited March 13, 2012 by Hawk

[Aktonius]

I had issue like this long time ago and its hard to remember exactly how solved this and i am not 100% sure you have same issue but this reminds me to much of my problem.

I know i had to manually set every timer to 0 because timer_killtimer would sometimes fail. Everytime you kill timer put it to 0 as well like this

_Timer_KillTimer($hWnd, $ex1_timer)
            $ex1_timer = 0

I used them alot and never really had happy time, like now fileread() will sometimes fail if i use timers in my script but if i use adlibregister() instead fileread() works perfect.

Edited April 8, 2012 by Aktonius