Page 1 of 1
[Bug?] ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 12:56 pm
by PureLust
In one on my projects, I needed a little 3 seconds progress-bar and I used ElapsedMilliseconds() to realize it.
I developed the code on my Laptop with Win10 and anything was working fine.
When I tested it on the destination machine with WinXP, I was wondering, why the progress-bar was not working right.
After some tests, I find out, that ElapsedMilliseconds() jumps to the past (to lower values) randomly after a few seconds.
To proof this, I wrote a little test-code, which reports, if a new ElapsedMilliseconds()-value is lower than the one before.
Code: Select all
Repeat
ActTimer = ElapsedMilliseconds()
If ActTimer < OldTimer
Debug "ERROR at "+FormatDate("%hh:%ii:%ss", Date())+" - old Timer -> "+Str(OldTimer)+" / "+Str(ActTimer)+" <- new Timer ("+Str(ActTimer-OldTimer)+"ms)"
EndIf
OldTimer = ActTimer
Delay(100)
Until 0
And here are some results:
Code: Select all
ERROR at 12:38:49 - old Timer -> 1153164 / 1148576 <- new Timer (-4588ms)
ERROR at 12:38:58 - old Timer -> 1162498 / 1157910 <- new Timer (-4588ms)
ERROR at 12:39:07 - old Timer -> 1190624 / 1186036 <- new Timer (-4588ms)
ERROR at 12:39:17 - old Timer -> 1199980 / 1195392 <- new Timer (-4588ms)
ERROR at 12:39:22 - old Timer -> 1200026 / 1186064 <- new Timer (-13962ms)
ERROR at 12:39:26 - old Timer -> 1190658 / 1186071 <- new Timer (-4587ms)
ERROR at 12:39:36 - old Timer -> 1199966 / 1195399 <- new Timer (-4567ms)
ERROR at 12:39:40 - old Timer -> 1199998 / 178184 <- new Timer (-1021814ms)
ERROR at 12:39:50 - old Timer -> 187446 / 178191 <- new Timer (-9255ms)
ERROR at 12:39:59 - old Timer -> 187449 / 178173 <- new Timer (-9276ms)
ERROR at 12:40:08 - old Timer -> 187446 / 178170 <- new Timer (-9276ms)
ERROR at 12:40:27 - old Timer -> 224927 / 215652 <- new Timer (-9275ms)
ERROR at 12:40:37 - old Timer -> 224987 / 215712 <- new Timer (-9275ms)
ERROR at 12:40:46 - old Timer -> 224965 / 215690 <- new Timer (-9275ms)
ERROR at 12:41:05 - old Timer -> 262405 / 253160 <- new Timer (-9245ms)
As you can see, ElapsedMilliseconds() jumps to lower values at irregular intervals.
Sometimes it falls back only a few seconds, sometimes more than 17 Minuten (1199998 > 178184).
The only consistency I can see is, that the 'fallback-time' is ~4.6 Seconds or a multiplication of it.
Anyone an idea why or how this could happen?
Maybe some of you could run the test-code and give me some feedback if this phenomenon appears on your machine as well.
Attention: Because it's an endless routine, you need to break it manually.
I've testet it with PB 5.5 on several WinXP-PCs, and run into this problems on all of them.
All PCs do have the same configuration: WinXP-Pro SP3, an older AMD Geode single-core Processor and 512MB Ram.
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 1:01 pm
by Keya
so your Win10 was ok but XP not? are they both 32 or 64bit or different or? which PB are you using, and have you tried an older build of PB? I just had it running on XP32 with 5.42 x86 for over 40 minutes, no problem
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 6:28 pm
by bosker
ElapsedMilliseconds returns a Quad.
Using an Int could result in all kinds of mayhem depending on what the absolute values happen to be.
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 6:37 pm
by Keya
bosker wrote:ElapsedMilliseconds returns a Quad.
The docs don't specify the return type, which suggests it's an Integer, so 32bits on x86. I just checked my XP32 and the current Debug Hex(ElapsedMs(), #PB_Quad) = FFFFFFFFF9684E8E which is within 32bit, and in 30.7 hours i'll be able to check how it rolls over
ps. PureLust do you get the same problem from calling GetTickCount_() ?
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 8:18 pm
by Mistrel
ElapsedMilliseconds() used to call Win32 GetTickCount() unless this has changed. This function returns an unsigned int (PureBasic long) which rolls over after 49.7 days. Because PureBasic only has signed longs then this number will flip to the past in half that time unless you explicitly use a bitwise AND with your comparison to treat it as unsigned.
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 8:18 pm
by bosker
Well, my 5.50 help file certainly does specify return type.
ElapsedMilliseconds()
Syntax
Result.q = ElapsedMilliseconds()
Description
Returns the number of milliseconds that have elapsed since a specific time in the past.
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 8:43 pm
by bosker
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 9:04 pm
by netmaestro
ElapsedMilliseconds() and Delay() both use QueryPerformanceCounter now, hence the quad return value. Rollover is no longer a consideration. (not that rollover was happening here, this is most likely overflow in a too-small variable type.)
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 10:14 pm
by Mistrel
netmaestro wrote:.. this is most likely overflow in a too-small variable type.
This does sound accurate. I'm still in the habit of storing ElapsedMilliseconds() in an integer. I didn't realize that it had been changed to quad on x86; although I do recall of a feature request for it.
I don't think 64-bit granularity for this function is necessary as it's typically used for very short timers. The issue with its use is that it's reliant upon system uptime and not application uptime.
I think it would have been more useful as such:
Code: Select all
Result.l = ElapsedMilliseconds(*WrapCount=0)
.. where elapsed time begins at 0 since program start and WrapCount increments if this value ever loops. You won't have to ever account for it unless you plan on writing something that stays resident for a while. Moving to 64-bits is just replacing one problem with another (as this thread demonstrates).
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 10:17 pm
by PureLust
Using quads does not help.
But GetTickCount_() does the trick and works fine ... thanks Keya.
I thought, ElapsedMilliseconds() was just a mapped GetTickCount_(), but as netmaestro mentioned, PB uses QueryPerformanceCounter now.
So it looks like that the new routine, PB uses for ElapsedMilliseconds() works fine on an actual CPU, but may produce some problems on older platforms?
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 10:22 pm
by Mistrel
Sounds like you would have to do some further testing with the API in question directly to be sure. It doesn't appear that we will be able to duplicate this in our environment if it is indeed a hardware issue.
Re: Strange: ElapsedMilliseconds() jumps to the past ...
Posted: Tue Dec 27, 2016 10:41 pm
by PureLust
Mistrel wrote:Sounds like you would have to do some further testing with the API in question directly to be sure. It doesn't appear that we will be able to duplicate this in our environment if it is indeed a hardware issue.
Yes, I agree. It's difficult to locate a problem if it does not occur on you hardware.
But it looks like that you have to consider some anomalies when implementing QueryPerformanceCounter.
I did find these information on that:
=>
https://blogs.msdn.microsoft.com/oldnew ... 0/?p=20963
=>
https://blogs.msdn.microsoft.com/oldnew ... 33/#461129
The author of this article describes the problem quite good, although it's about Gecko and not PB.
=>
http://www.janbambas.cz/usage-of-queryp ... -in-gecko/
Also the following article describes, that QueryPerformanceCounter could cause great Problems on older hardware:
=>
http://computerperformancebydesign.com/ ... ilization/
(Scroll down around 60% of the page or search for 'it is a problem that only occurs on older hardware'.)
Even though it will not be fixed, this behavior should be mentioned in the Doc with a hint to use GetTickCount_() instead.