Forums Bug Reports /timer

The timer function has sometimes problems,

if I set an timer on /timertest 1 60 /command
it does not do the command about in the 60sec but early..

Sometimes it does the command in 10 sec sometime in 20 sec.

And no I don't have timer override.

Can't reproduce it. If the timer command was so unstable it would have been reported years ago.

Sometimes creating another /timertest will cause the timer to be reset. Originally when you said "early" I thought you meant half a second or so, I was going to suggest using the -h switch for a high res timer. But since you said it's about 40-50 seconds off, I'd have to say this is probably due to programmer error, not mirc.

Do you have /timerTEST over ridden with an alias ?

As thats the command your calling!

Don't you have several timer with the same name (test) but different time to function ? check this before.

[20:05:23] <Team-triviant> *** Volgende vraag over 3 seconden... ***
[20:05:24] <Team-triviant> Vraag: Wintersporten
[20:05:25] <Team-triviant> *** Jullie hebben 70 seconden tijd ***
[20:05:39] <Team-triviant> *** Nog 50 seconden.. ***
[20:05:59] <Team-triviant> *** Nog 30 seconden.. ***
[20:06:14] <Team-triviant> *** Nog 15 seconden.. ***
[20:06:24] <Team-triviant> *** Nog 5 seconden.. ***

.timertrivia_0 1 1 .msg %channel 4***10 Jullie hebben4 70 10seconden tijd 4***
.timertrivia_1_1 1 20 .msg %channel 4***10 Nog4 50 10seconden..4 ***
.timertrivia_1 1 40 .msg %channel 4***10 Nog4 30 10seconden..4 ***
.timertrivia_2 1 55 .msg %channel 4***10 Nog4 15 10seconden..4 ***
.timertrivia_3 1 65 .msg %channel 4***10 Nog4 5 10seconden..4 ***

Here you can see it...

everything looks fine but the 2nd timer

i ran the alias and got the same result as you, _the first time_

//.timertrivia_0 1 1 echo -at ONE | .timertrivia_1_1 1 2 echo -at TWO | .timertrivia_1 1 3 echo -at THREE | .timertrivia_2 1 4 echo -at FOUR | .timertrivia_3 1 5 echo -at FIVE

(19:39:53) ONE
(19:39:53) TWO
(19:39:54) THREE
(19:39:55) FOUR
(19:39:56) FIVE

and then i ran it a second time and got normal results (everything was spaced by 1 second)


notice the only timer name that has a different makeup than the rest is the 2nd one, with an extra '_1' at the end.. i don't know if that's the cause, since it corrected itself anyway.. it could be a caching issue of some sort. it was really only a one second difference anyway. if you need accurate timers use -h i guess. that might fix it

*EDIT*
(20:01:28) ONE
(20:01:29) TWO
(20:01:30) THREE
(20:01:31) FOUR
(20:01:31) FIVE

I got the same skip on FOUR and FIVE

using -h i ended up with:
(20:04:05) ONE
(20:04:06) TWO
(20:04:07) THREE
(20:04:08) FOUR
(20:04:13) FIVE


Okay, i admit, something is buggy

There is NOTHING wrong with these results at all. Conssider for a second what were looking at....
The timers are all set off one behind each other so they take effect on the same moment (or close as to)
The reason for the incorrectly proportioned time is IRC SERVER LAG, the ".msg" is what gives it away, the results shown must be from another client which is experenceing intermitent lag.

I was testing it on echo commands with an $time function:

and this were the results:

23:29:34 *** Jullie hebben 70 seconden tijd ***
23:29:53 *** Nog 50 seconden.. ***
23:30:13 *** Nog 30 seconden.. ***
23:30:28 *** Nog 15 seconden.. ***
23:30:38 *** Nog 5 seconden.. ***



And why should I use the -h function for it? It's only take more cpu usage for just 5 timers noway.

Hmm the server is not lagging @ all, with just some 10 users on an 100MBit server. (or I'm sleepwalking?)

Letys have a look at your two time tests....



Again i see a server lag, since i know if the timers you used were the same ones us used for the results, you must have taken the results from another irc connection.


You tested the first line using $time, the other lines by chance worked becuase /echo -atime produces a timestamp on the front of the echo



Exactly what they should have been....... also different from the first results due to you not getting them from a remote location which has other delays

For a clearer demonstration run this.

I used /teststarter to trigger a test directly on the minute mark, only to make the seconds counting up easier to see, so each test shown started at 12:40
results of /TESTSTARTER
* Timer 1 12:40 1 time(s) 1ms delay test (Criten)
results of /TEST
12:40:01 #tmd *** Jullie hebben 70 seconden tijd *** 12:40:01 ( 12:40:00 + 1 ) :: Actual delay 1.282
12:40:20 #tmd *** Nog 50 seconden.. *** 12:40:20 ( 12:40:00 + 20 ) :: Actual delay 20.266 ( + 19 from above )
12:40:40 #tmd *** Nog 30 seconden.. *** 12:40:40 ( 12:40:00 + 40 ) :: Actual delay 40.266 ( + 20 from above )
12:40:55 #tmd *** Nog 15 seconden.. *** 12:40:55 ( 12:40:00 + 55 ) :: Actual delay 55.282 ( + 15 from above )
12:41:05 #tmd *** Nog 5 seconden.. *** 12:41:05 ( 12:40:00 + 65 ) :: Actual delay 65.266 ( + 10 from above )

This shows the timers went off just when they were ment to. The same as yours when you used /echo

* I now put a small cavet on what i say by showing this result, this was achivied by removing the ; of the ;timer command inisde /TEST, it causes a greater delay in completing the alias, the results may or maynot form a pattern as below, based on speed of the processor of the pc (among other things) Im running this on a low end pc.


12:40:01 #tmd *** Jullie hebben 70 seconden tijd *** 12:40:01 ( 12:40:00 + 1 ) :: Actual delay 1.734
12:40:19 #tmd *** Nog 50 seconden.. *** 12:40:20 ( 12:40:00 + 20 ) :: Actual delay 19.75 ( + 19 from above )
12:40:39 #tmd *** Nog 30 seconden.. *** 12:40:40 ( 12:40:00 + 40 ) :: Actual delay 39.734 ( + 20 from above )
12:40:54 #tmd *** Nog 15 seconden.. *** 12:40:55 ( 12:40:00 + 55 ) :: Actual delay 54.734 ( + 15 from above )
12:41:04 #tmd *** Nog 5 seconden.. *** 12:41:05 ( 12:40:00 + 65 ) :: Actual delay 64.734 ( + 10 from above )

As you can see the timers have desynced from the time they should be going off, by one second, Im resonably sure of the cause of this, and what i "beleive" follows.
When you set a X number of seconds timer, say 4 seconds, this is added to the timer list, each time the clock ticks over a second, mirc adjusts these by 1, it well also play catchup if it has been so drasticly delayed that it missed a second of tick over timer (this it can sometimes get confused on however). So if you set a 4 second delay timer at a start of a script, then one at the end and the script has taken only .7 seconds to run but the clock has yet to tick over a second, both timers well be run, directly following each other, there well not be a .7 second delay between them.
I have also found that the -h option doesnt work as well as the -m option, as using the above explained .7 second delay both -h scripts trigger off at the same time, while the -m ones well go off .7 seconds apart.


Over all, i think mirc timers are pretty good for what you need them for in mirc.

Dave
please pay attention to my results if not his.

Notice that my timer also skips on a local echo.. no possible lag.

the skips are _random_, which doesnt make it feature like, but bug like. A timer should be relied on-- a copout like "Oh, you don't really need ACCURATE timers in mIRC" is really unfair. If Khaled's going to put in timers, they should be functioning properly. I had a short discussion with sat, and what I got out of it was that he's having a timer _related_ problem as well, which leads me to believe something in the back of timer isnt working quite right, especially according to my test results

I get odd results too at random times. The command

//.timertrivia_0 1 1 echo -at ONE | .timertrivia_1_1 1 2 echo -at TWO | .timertrivia_1 1 3 echo -at THREE | .timertrivia_2 1 4 echo -at FOUR | .timertrivia_3 1 5 echo -at FIVE

sometimes echoes two words simultaneously, usually TWO with THREE, so it's usually like

ONE
<interval>
TWO
<no interval>
THREE
<interval>
FOUR
<interval>
FIVE

Then I added in $!ticks and things got even weirder:

//.timertrivia_0 1 1 echo -a $!ticks ONE | .timertrivia_1_1 1 2 echo -a $!ticks TWO | .timertrivia_1 1 3 echo -a $!ticks THREE | .timertrivia_2 1 4 echo -a $!ticks FOUR | .timertrivia_3 1 5 echo -a $!ticks FIVE

the results I got:

74713656 ONE
74714656 TWO
74715656 THREE
74716656 FOUR
74717656 FIVE

75724656 ONE
75725656 TWO
75725656 THREE
75726656 FOUR
75727656 FIVE

75868656 ONE
75869656 TWO
75870656 THREE
75871656 FOUR
75872656 FIVE

75910656 ONE
75911656 TWO
75912656 THREE
75912656 FOUR
75913656 FIVE

75953656 ONE
75954656 TWO
75955656 THREE
75956656 FOUR
75957656 FIVE

75975656 ONE
75976656 TWO
75977656 THREE
75978656 FOUR
75979656 FIVE

76113656 ONE
76114656 TWO
76115656 THREE
76116656 FOUR
76116656 FIVE

Notice that the ticks numbers always end in 656 (awfully close to 666, that might explain things!). This happens every time I test it.

CPU load and/or process priority don't seem to affect the bug. I changed mirc.exe's priority to Highest and I got the same results.

Well I felt i had to tell the truth, i saw the first one the
(19:39:53) ONE
(19:39:53) TWO
And i felt I knew what this was, its when the alias/commands executed to create the timers cross over a clock tick boundry, so the /timer 1 1 and timer 1 2 both go off on the next clock tick, same occurs if you delay mirc being able to process commands for multiple seconds, a set of timers set 1 second apart well all trip together.
(by clock tick im refering to a 12:00:00 to 12:00:01 change)

This below I now realise I miss understood (now that you pointed it out) and thought this was what had been reported to you(20:01:28) ONE
(20:01:31) FOUR
(20:01:31) FIVE
and the one below that was you replying about using the -h on a timer (which looks like something else running took a few seconds to complete, with a gap that size)
(20:04:08) FOUR
(20:04:13) FIVE

--
The reason i came to that conclusion is becuase, I ran your command, and not once could i produce results that showed a jumped second, besides the odd inital one never a
(20:01:31) FOUR
(20:01:31) FIVE
type event. I even added fields such as Querty's $!ticks to see about the displacement of time between timers, each one was 1000ms (excepting those odd inital ones)
I also got an identical last 3 digits but mine were different from Querty's, being 082, these always being the same and well different from the last 3 digits of $ticks at the timer creation, enforces how i understand timers to be dealt with , however I think there maybe some code in there to control how those first seconds are dealt with
example
//.timer 3 1 echo -at $ticks : $!ticks : $!calc( $!ticks - $ticks ) : $!ctimems
[09:40:42] 719850505 : 719851442 : 937 : 1122327642.235
[09:40:43] 719850505 : 719852442 : 1937 : 1122327643.235
[09:40:44] 719850505 : 719853442 : 2937 : 1122327644.235
//.timer 3 1 echo -at $ticks : $!ticks : $!calc( $!ticks - $ticks ) : $!ctimems
[09:40:51] 719859114 : 719860442 : 1328 : 1122327651.235
[09:40:52] 719859114 : 719861442 : 2328 : 1122327652.235
[09:40:53] 719859114 : 719862442 : 3328 : 1122327653.235

The first time the timer goes off slightly under 1 second, the next time its over 1 second, I have seen it as low as 908 and as high as 1804, I assume there must be some code in there that says something like if 900 or less ticks since creation then dont give it the first second count.
Something else I also used was a custom identifier $ctimems which gives $ctime plus a milliseconds as a decimal, i confirmed this was goiving accurate results before use. You well notice the time the times went off was not anywheer near the actual $time tick over of a second, but did seem to be at a constant second tick over point.

--- please read ---
hmmmmm ok i written what i wrote above, not really trying to disprove you, just saying what i found, and now i found how to produce your results so i take back the (now italic above)
and not once could i produce results that showed a jumped second. If i take the mirc online and have several other events/timers running i can produce the same effect. While offline everything runs smooth (then again all my other timers stop also)

That test isn't valid though, because you're only using one timer to create your results. This is far different from mine and qwerty's, which relies on 5 timers to create a 1 second delay in each echo. This was the control in the test and has to remain so-- it's possible that the actual bug has to do with executing multiple timers at once. Therefore, it is probable that you cannot reproduce the bug with one timer, and might need more than one.

I do somewhat believe your theory about a time gap, but if you look at qwerty's results using my exact alias, you'll notice there is a random jump

As I write this -- I'm preparing to test with 10+ timers

Followup:

very, very interesting:

Thirteen command timer, based on qwerty's ticks addition:



Check out these results:

5146648 ONE
5147648 TWO
5148648 THREE
5149648 FOUR
5149648 FIVE
514[color:red]9648 NINE[/color]
514[color:red]9648 TEN[/color]
5150648 SIX
5150648 ELEVEN
5151648 SEVEN
515[color:red]1648 TWELVE[/color]
5152648 EIGHT
5152648 THIRTEEN

The purple lines are completely misplaced commands to begin with. How 9,10 got in front of 6, i do not know. Also note how many skips are observed. The amount of error seems to increase as more timers are put into the list. In fact, 13 timers have atleast one skip or misplaced command about every time I've tested this alias

Another test:

5584680 ONE
5585680 TWO
5586680 THREE
5587680 FOUR
5587680 NINE
5588680 FIVE
5588680 TEN
5589680 SIX
5589680 ELEVEN
5590680 SEVEN
5590680 TWELVE
5591680 EIGHT
5591680 THIRTEEN

And another:

5690680 ONE
5691680 TWO
5692680 THREE
5693680 FOUR
5693680 FIVE
5693680 NINE
5693680 TEN
5694680 SIX
5694680 ELEVEN
5695680 SEVEN
5695680 TWELVE
5696680 EIGHT
5696680 THIRTEEN

Notice that 9 always seems to come at around the 4th or 5th timer. In fact, the entire result seems to have some sort of pattern-- the last result was exactly equal to my first. Weird

I have no idea what to make of this, besides the fact that I'm now positive there is a bug, and I'm pretty sure it's related to multiple timers executed in one script process.

qwerty: can you come up with a way to test 2 seperate script processes executing multiple timers? They have to be executed at the *same time*.. I just want to see if it's related to being run from one process

Oh the timer i showed was only ment to be in refrence to showing how mirc seems to tick a second off if your over 900ms (aprox) from the time you created the timer to the time the seconds tick over occurs, as in if assume that the second ticks over, at $ticks = 100950, 101950, 102950, 103950, then if the timer was created at 101025, then since 925ms have passed since it was created, a second well be ticked off, however if it was created at 101500, then only 450 well have passed and it wont be counted as a second, and must wait another full 1000ms before a second is ticked off. I was using a 3 repeat timer, to show that the following events matched a one second delay from the previous, but the first could be from 900ms to 1899ms (aprox). I also ment to show how the decimal offset (ms) of the seconds of $ctimems produces the same offset, which I believe points to a regular once per second internal action of mirc that processes timers. For my tests I had been using 9 times going off from 1 to 9 seconds, and as i said untell i went online they would always come up in perfect sync. As you have clearly shown, there does appear to be some unusal behavour as I could easily see a timer being delayed by other events, however the jump is in the area of a acceleration of the timer, so two go off in one second. I guess unlesss Khaled actually told us how he worked them we wont ever know the exact reasoning for some behavours.

I think your delays for NINE to THIRTEEN are wrong.

Still, with those delays, NINE should have been before FIVE