test clock.SCHEDULE_INTERVAL fails in windows xp ( 1.1 maintenance )

[GoogleCodeExporter]

What steps will reproduce the problem?
1. edit tests.txt commenting out all but the clock section
2. run test.py
3.

Paste in the traceback or error message:
(from the test log)
INFO:root:Begin unit tests for clock.SCHEDULE_INTERVAL
ERROR:root:Failure in clock.SCHEDULE_INTERVAL
ERROR:root:Traceback (most recent call last):
  File "..\tests\clock\SCHEDULE_INTERVAL.py", line 49, in 
test_schedule_interval
    self.assertTrue(self.callback_1_count == int(t / 0.1))
AssertionError

pyglet svn branch 1.1 maintenace rev 2501

Any additional info (platform/language/hardware) that may be relevant?
windows xp sp3 32bits, python 2.6

Original issue reported on code.google.com by ccanepacc@gmail.com on 19 Aug 2009 at 11:01

[GoogleCodeExporter]

I can't reproduce this on my vista 64 machine, though I haven't looked into the 
code 
yet.  I've also tried it on osx leopard, just because, and no reproduction 
there, 
either.

Would you mind trying it with the tagged pyglet 1.1.3 release?  This way I 
could 
determine if the error was introduced with my backports or existed before them. 

Also, would you attach your test plan text file, just in case I did something 
differently?

Thanks.

Original comment by benjamin...@gmail.com on 19 Aug 2009 at 3:51

[GoogleCodeExporter]

Same with 1.1.3 release.
attached into the zip the logs for release and maintenance test runs, also 
plan.txt

Can someone in XP give a try ?

Original comment by ccanepacc@gmail.com on 19 Aug 2009 at 4:09

[GoogleCodeExporter]

ouch, the zip:

Original comment by ccanepacc@gmail.com on 19 Aug 2009 at 4:10

Attachments:

• issue445_logs_and_plan.zip

[GoogleCodeExporter]

PD: also note there are *more* errors in the 1.1.3 release run

Original comment by ccanepacc@gmail.com on 19 Aug 2009 at 4:26

[GoogleCodeExporter]

Alright, well, no dice here with your test plan, either.  Looking at the code, 
seems 
like it's testing to see if the callback is called the expected number of 
times.  
Another thing to look into is the value of callback_1_count.  

If this issue is related to the general windows timing problems, I'd guess that 
the 
third assertTrue in that test would also fire, as it's an even higher precision 
clock.  
I am guessing, though.

Original comment by benjamin...@gmail.com on 19 Aug 2009 at 4:36

[GoogleCodeExporter]

Additional info: error quantity depends on machine load, and no load -> more 
errors!

4 runs pyglet 1.1.3 release, all aps closed: more errors
The four runs have the same errors, except one where the fail in 
clock.SCHEDULE_ONCE 
doesn't happen.

log:
INFO:root:Beginning test at Wed Aug 19 13:39:39 2009
INFO:root:Capabilities are: GENERIC, WIN
INFO:root:sys.platform = win32
INFO:root:Reading test plan from plan.txt
INFO:root:Testing top.IMPORT.
INFO:root:Begin unit tests for top.IMPORT
INFO:root:27 tests run
INFO:root:Testing clock.TICK.
INFO:root:Begin unit tests for clock.TICK
INFO:root:1 tests run
INFO:root:Testing clock.FPS.
INFO:root:Begin unit tests for clock.FPS
ERROR:root:Failure in clock.FPS
ERROR:root:Traceback (most recent call last):
  File "..\tests\clock\FPS.py", line 25, in test_fps
    self.assertTrue(abs(result - 5.0) < 0.05)
AssertionError

INFO:root:1 tests run
INFO:root:Testing clock.FPS_LIMIT.
INFO:root:Begin unit tests for clock.FPS_LIMIT
INFO:root:1 tests run
INFO:root:Testing clock.SCHEDULE.
INFO:root:Begin unit tests for clock.SCHEDULE
INFO:root:3 tests run
INFO:root:Testing clock.SCHEDULE_INTERVAL.
INFO:root:Begin unit tests for clock.SCHEDULE_INTERVAL
ERROR:root:Failure in clock.SCHEDULE_INTERVAL
ERROR:root:Traceback (most recent call last):
  File "..\tests\clock\SCHEDULE_INTERVAL.py", line 49, in test_schedule_interval
    self.assertTrue(self.callback_1_count == int(t / 0.1))
AssertionError

INFO:root:1 tests run
INFO:root:Testing clock.SCHEDULE_ONCE.
INFO:root:Begin unit tests for clock.SCHEDULE_ONCE
ERROR:root:Failure in clock.SCHEDULE_ONCE
ERROR:root:Traceback (most recent call last):
  File "..\tests\clock\SCHEDULE_ONCE.py", line 48, in test_schedule_once
    t += clock.tick()
  File "C:\Python26\Lib\site-packages\pyglet\clock.py", line 698, in tick
    return _default.tick(poll)
  File "C:\Python26\Lib\site-packages\pyglet\clock.py", line 303, in tick
    item.func(ts - item.last_ts, *item.args, **item.kwargs)
  File "..\tests\clock\SCHEDULE_ONCE.py", line 23, in callback_1
    self.assertTrue(abs(dt - 0.1) < 0.01)
AssertionError

INFO:root:1 tests run

----------------------------------------------------------------

4 runs pyglet 1.1.3 release, opened 
  opera browser with two tabs
  5 instances notepad
  2 windows IDLE
  1 explorer window 

-> only one error (in each run) 
INFO:root:Begin unit tests for clock.SCHEDULE_INTERVAL
ERROR:root:Failure in clock.SCHEDULE_INTERVAL
ERROR:root:Traceback (most recent call last):
  File "..\tests\clock\SCHEDULE_INTERVAL.py", line 49, in test_schedule_interval
    self.assertTrue(self.callback_1_count == int(t / 0.1))
AssertionError

Original comment by ccanepacc@gmail.com on 19 Aug 2009 at 4:51

[GoogleCodeExporter]

Would you try this with some of the extra debugging on?  at the command line do:

> set PYGLET_DEBUG_TRACE=True 
> set PYGLET_DEBUG_TRACE_ARGS=True 
> python pyglet/pyglet-1.1.3/tests/test.py >output.txt

Original comment by benjamin...@gmail.com on 20 Aug 2009 at 4:03

[GoogleCodeExporter]

tried, attached the output and the log

Original comment by ccanepacc@gmail.com on 20 Aug 2009 at 4:47

Attachments:

• output_1.1.3release.txt
• pyglet.2.log

[GoogleCodeExporter]

[deleted comment]

[GoogleCodeExporter]

I will summarize the observations on pyglet clock tests:

Some clock test fails in my machine
windows xp sp3 32bits, python 26
Slightly old hardware: amd sempron 2400+ 32 bits single core (socket A), 512MB 
mem, 
nvidia gforce 6600 gpu. It runs Call of Duty 4, so even if old is not so much 
weak.

10 runs - pyglet 1.1.3 - light load (opera, idle, notepad)

Stats failures in 10 runs:
clock.TICK = 0
clock.FPS_LIMIT = 0
clock.SCHEDULE = 0
clock.FPS  = 0

clock.SCHEDULE_INTERVAL = 10
clock.SCHEDULE_ONCE = 2

---

10 runs - pyglet 1.1.3 - no other app running

Stats failures in 10 runs:
clock.TICK = 0
clock.FPS_LIMIT = 0
clock.SCHEDULE = 0

clock.FPS  = 10
SCHEDULE_INTERVAL = 10
SCHEDULE_ONCE = 3

---

10 runs - pyglet 1.1.3 using time.clock - no other app running

Stats failures in 10 runs:
clock.TICK = 0
clock.FPS_LIMIT = 0
clock.SCHEDULE = 0
SCHEDULE_INTERVAL = 0
SCHEDULE_ONCE = 0

clock.FPS  = 4

---

10 runs - pyglet 1.1.3 using time.clock - light load (opera, idle, notepad)

All clock test passed

---

Some thoughts:

If time.clock is reliable in multicore processors, then conditionally 
using time.clock in windows would solve the issue.

Tests must be done on Linux with the stock 1.1.3 code to see if similar 
problems 
happens.

The test clock.FPS relies on time.wait, which probably has time.time 
resolution. To 
make it pass, it should be revamped, but that can wait until a fix for 
schedule_interval is chosen.

---

I will try to get time to test in a more modern rig ( AMD athlon 

5200, 2 GB, ATI 4650) for comparison, but maybe you can request in 

pyglet-users volunteers to do some testing.

Original comment by ccanepacc@gmail.com on 20 Aug 2009 at 8:29

[GoogleCodeExporter]

with pyglet 1.1.3 using time.clock I mean:
in pyglet.clock.Clock __init__ parameters change
time_function=time.time
to
time_function=time.clock

In windows with single core processor time.clock is a high resolution time 
which 
comes from the CPU register that counts ticks from last reboot; this is handled 
with 
the win32 QueryPerformanceCounter ( python docs 2.6 dixit )

In windows multicore tests must be done to confirm if time.clock is reliable: 
the 
underlaying win32 function has the Remark:
"On a multiprocessor computer, it should not matter which processor is called. 
However, you can get different results on different processors due to bugs in 
the 
basic input/output system (BIOS) or the hardware abstraction layer (HAL)"
It is possible that the AMD or Intel patch for multicores is needed to reliable 
operation (remember all games initially broken by multicores ?).

In Linux is more like the process time; it runs way slower than the wall clock.
So if we want time.clock in windows, conditional must be used so that non 
windows 
systems continue to use time.time 

Original comment by ccanepacc@gmail.com on 20 Aug 2009 at 9:17

[GoogleCodeExporter]

Thank you for all of the feedback.  The time.clock() function may indeed be the 
way to 
go on windows.  Have you had any issues in general running pyglet apps that use 
the 
clock?

One thing that concerns me is that this test fails on your windows system, but 
not on 
mine.  I'd really like to know why.  I have an XP box I can fire up at home, 
though 
it's multicore as well.  I will post on the users list to see if more people 
can spend 
some time looking at this.

Original comment by benjamin...@gmail.com on 20 Aug 2009 at 6:32

• Changed state: Accepted
• Added labels: OpSys-Windows, Type-Defect

[GoogleCodeExporter]

No problems with any pyglet app that I remember; I runned all pyweek with 
pyglet 
entries with no problems. 

Original comment by ccanepacc@gmail.com on 20 Aug 2009 at 6:37

[GoogleCodeExporter]

I got a chance to try this out on XP.  I didn't have this issue with the tests, 
though 
I was running python 2.6.2.

Are you able to update your python?  The last time I did the update from 2.6.1 
to 2.6.2  
it seemed to work fine with all of my existing installed modules, I didn't have 
to 
reinstall any.

Original comment by benjamin...@gmail.com on 21 Aug 2009 at 4:08

[GoogleCodeExporter]

Also, looks like the trunk's clock.py has been changed to use time.clock() in 
r2323.  
I'm tempted to just apply the change here.

Original comment by benjamin...@gmail.com on 21 Aug 2009 at 5:15

[GoogleCodeExporter]

I've done some local testing to try out only the changes done to clock.py in 
r2323 on 
xp and on vista, and it passes the tests.  I'm still hesitant to apply the 
patch 
because I can't get to the bottom of the problem you're having, and I'm unsure 
if there 
are wider ramifications from this change.

Original comment by benjamin...@gmail.com on 21 Aug 2009 at 5:48

[GoogleCodeExporter]

ok, I put it in maintenance as r2516. Please let me know what happens with 
testing.

Original comment by benjamin...@gmail.com on 21 Aug 2009 at 5:53

[GoogleCodeExporter]

Test in a more modern machine:
win XP sp3 32bits (with AMD patch for dual cores), python 2.6.1, AMD athlon 
5200 
dual core, 2GB ram, ati radeon 4650 gpu.

Results are in line with the one in the older machine:

Failures in 10 runs, using pyglet 1.1 maintenance *without* the time.clock 
patch:
clock.FPS: 10
clock.SCHEDULE_INTERVAL: 10
clock.SCHEDULE_ONCE: 1

Failures in 10 runs, using pyglet 1.1 maintenance *with* the time.clock patch:
clock.FPS: 10
clock.SCHEDULE_INTERVAL: 0
clock.SCHEDULE_ONCE: 0

Also, upgrading python from 2.6.1 to 2.6.2 makes no changes in the old rig 
results.

To keep an eye with this change I suggest to add a test in the line:

""" There is the possibility that time.clock be non monotonic in multicore 
hardware, 
due to the underlaying use of win32 QueryPerformanceCounter.
If your update is seeing a negative dt, then time.clock is probably the culprit.
AMD or Intel Patches for multicore may fix this problem (if it happens)"""

import time

old_time = time.clock()
end_time = time.time() + 3

failures = 0
while time.time()<end_time:
   t = time.clock()
   if t<old_time:
       failures += 1
   old_time = t
   time.sleep(0.001)
assert failures==0

Original comment by ccanepacc@gmail.com on 21 Aug 2009 at 8:17

[GoogleCodeExporter]

I've added your test, thanks. (r2517)

I'm glad that things seem better with the clock test.  I still can't reproduce 
this 
on my xp sp3 machine, which makes for a frustrating troubleshooting process.

I went over the clock.FPS test.  Would you mind modifying tests/clock/FPS.py to 
print 
the results of clock.get_fps() on each run?  I'd like to see if it's very far 
off of 
the 0.05 deviation the test samples, or maybe catch if it's something else 
(nearly) 
obvious that I'm missing.

Original comment by benjamin...@gmail.com on 22 Aug 2009 at 12:14

[GoogleCodeExporter]

Here are results in the slow machine:

using pyglet branch 1.1 maintenance *without* the time.clock fix no other apps 
running

clock.FPS - result , expected , delta: 4.92341402394 5.0 -0.0765859760561
clock.FPS - result , expected , delta: 4.92341402394 5.0 -0.0765859760561
clock.FPS - result , expected , delta: 4.92072171611 5.0 -0.0792782838868
clock.FPS - result , expected , delta: 4.92341402394 5.0 -0.0765859760561
clock.FPS - result , expected , delta: 4.9234133818 5.0 -0.0765866181969
clock.FPS - result , expected , delta: 4.9234133818 5.0 -0.0765866181969
clock.FPS - result , expected , delta: 4.9234133818 5.0 -0.0765866181969
clock.FPS - result , expected , delta: 4.9234133818 5.0 -0.0765866181969

using pyglet branch 1.1 maintenance *with* the time.clock fix , no other apps 
running

clock.FPS - result , expected , delta: 4.92310980205 5.0 -0.0768901979458
clock.FPS - result , expected , delta: 4.9231910551 5.0 -0.0768089449034
clock.FPS - result , expected , delta: 4.9231203347 5.0 -0.0768796652953
clock.FPS - result , expected , delta: 4.92322415896 5.0 -0.0767758410431
clock.FPS - result , expected , delta: 4.92311506837 5.0 -0.0768849316262
clock.FPS - result , expected , delta: 4.92321588295 5.0 -0.0767841170499
clock.FPS - result , expected , delta: 4.9229728817 5.0 -0.0770271183011

Original comment by ccanepacc@gmail.com on 22 Aug 2009 at 12:49

[GoogleCodeExporter]

I can reproduce this issue on XP now.  I think I've gotten to the bottom of 
this.

It think it is as you suggest in comment #10.  I didn't do a lot of looking 
around, 
but inside Python's timemodule.c it uses the WaitForSingleObject function, 
which 
looks like (http://blogs.msdn.com/oldnewthing/archive/2005/09/02/459952.aspx) 
it uses 
the same precision as GetTickCount which is usually 10-16ms.

There may be ways to increase the timer resolution in xp without modifying 
Python by 
using some of the multimedia timers with ctypes - some details here: 
http://msdn.microsoft.com/en-us/library/ms712704(VS.85).aspx and here: 
http://msdn.microsoft.com/en-us/library/ms713422%28VS.85%29.aspx 

Python's time.sleep() isn't going to give the resolution this test expects, 
unless 
the method above works, or Python moves to a different timing mechanism on xp.  
So, 
the options are either change the test or do some experimentation with the 
above 
method.

I haven't been able to find a reference that notes that this is different in 
vista, 
though it is on the two vista machines I tested.

Original comment by benjamin...@gmail.com on 22 Aug 2009 at 3:18

[GoogleCodeExporter]

Resolution must be better than 10-16ms: in the MULTICORE test you can add  a 
counter 
to know how much times the loop runs and print the counter after the loop. In 
my old 
machine in 3 seconds the counter was around 1500, so I think time.sleep 
resolution 
is more near to 2ms ( that was without load, so is a better case).

Original comment by ccanepacc@gmail.com on 22 Aug 2009 at 3:35

[GoogleCodeExporter]

I'm getting different results on xp than you are.  I think it may still be 
related to 
setting the multimedia timer resolution.  

After a fresh boot, I reliably get 192 iterations on a multiproc running xp 
sp3.  
However, if I start up windows media player (on the assumption that it alters 
the 
timer resolution) I get 1531, 1534, 1532, 1536, 1529, 1535, and 1532 
iterations! wow!   
If I exit media player, it drops back to 192.  It is possible that some 
applications 
set this timer resolution and don't un-set it when they exit, or one that 
alters the 
resolution is running.  Still, if that's the case, I don't understand why the 
FPS 
test would fail when MULTIPROC is yielding 1500 iterations.

I think I can come up with a way to test this theory out, given a little time.

Original comment by benjamin...@gmail.com on 22 Aug 2009 at 4:11

[GoogleCodeExporter]

wow, that is a very interesting piece of info! , and probably amerits a mention 
in 
the docs, in the time handling section.
But back to the current problem, clock.FPS fails:
At first you cant repro the issue in xp, but now you can. Can be that Vista 
fails 
also in some situations? That will point to errors in get_fps or clock.tick.
On the other side, if Vista is always correct and XP somehow fails, then the 
problem comes from different behavior in win libs.

Original comment by ccanepacc@gmail.com on 22 Aug 2009 at 4:51

[GoogleCodeExporter]

another (hypothetical) explanation for the difference 190 - 1500 can be: the 
windows task scheduler uses an adaptive time-slice; more load or more high 
priority 
tasks would reduce the time slice, hence calling more times per seconds.
Fair warning: I dont know the windows task scheduler.
But back to the problem, the baffling thing is:
 why at 1500 hits the test fails in XP, and not fails in Vista ?  

Original comment by ccanepacc@gmail.com on 22 Aug 2009 at 5:11

[GoogleCodeExporter]

The failure with reproduction on xp was entirely a mistake I made, I'm 
embarrassed to 
admit.  The test consistently failed, I just... missed it.  I'm sorry.

I'm making some encouraging (but not yet stable) progress with ctypes and the 
windows 
multimedia timers, it looks like it could lead to a solution of sorts.

Original comment by benjamin...@gmail.com on 22 Aug 2009 at 5:14

[GoogleCodeExporter]

Ok, I'm no expert at this windows mm stuff, but here's something that at least 
shows 
some interesting results on xp.

I find it confusing that the timings I get on my machine are pretty much the 
same in 
all tests except for the second one (where the period is wPeriodMin).  It may 
lead to a 
workaround.

Original comment by benjamin...@gmail.com on 22 Aug 2009 at 5:31

Attachments:

• windowstimer.py

[GoogleCodeExporter]

On vista, I'm getting about 3000 iterations out of the multicore test.  Same 
with the 
windowstimer.py test above.

Original comment by benjamin...@gmail.com on 22 Aug 2009 at 5:36

[GoogleCodeExporter]

Hum, if the test really needs 1ms resolution to be passed then I think the test 
must be rewrited.

windowstimer.py results in my machine:

Max: 1000000, Min: 1
Runs windowtimer.py - some light task running ( opera browser, notepad, idle)

1489
1537
1537
1537

D:\>c:\python26\python.exe windowstimer.py
Max: 1000000, Min: 1
1538
1538
1536
1537

D:\>c:\python26\python.exe windowstimer.py
Max: 1000000, Min: 1
1537
1536
1537
1535

D:\>c:\python26\python.exe windowstimer.py
Max: 1000000, Min: 1
1537
1537
1536
1537

----------------------------------------------

after reboot, nothing else opened :

D:\>c:\python26\python.exe windowstimer.py
Max: 1000000, Min: 1
193
1530
193
193

D:\>c:\python26\python.exe windowstimer.py
Max: 1000000, Min: 1
193
1531
193
193

D:\>c:\python26\python.exe windowstimer.py
Max: 1000000, Min: 1
193
1531
193
193

D:\>c:\python26\python.exe windowstimer.py
Max: 1000000, Min: 1
193
1532
193
193

D:\>c:\python26\python.exe windowstimer.py
Max: 1000000, Min: 1
193
1531
193
193

Original comment by ccanepacc@gmail.com on 22 Aug 2009 at 5:58

[GoogleCodeExporter]

your fresh boot looks consistent with mine.  If I run media player, I get the 
~1530 
timings across the board.  I obviously don't quite understand the ins and outs 
of the 
timeBeginPeriod and timeEndPeriod functions yet, as I expect to get something 
along 
the lines of:

193
1531
(some lower number)
(some even lower number)

I'm sure I'll hack on it some more, but it's good to see your results seem 
consistent 
with what I'm seeing and guessing.

Original comment by benjamin...@gmail.com on 22 Aug 2009 at 6:07

[GoogleCodeExporter]

Hey ben!
I think I spotted an error in FPS.py:
Shouldn't clock.tick() be called once before entering the loop ?
I'm looking pyglet.clock lines  279, 288 ( updating cumulative_time ) and below 
in 
get_fps()
the first tick dont count as a frame ( it is not entered in self.times, soo...)
I am correct ?

Original comment by ccanepacc@gmail.com on 22 Aug 2009 at 7:10

[GoogleCodeExporter]

Interesting idea.  I get some pretty varied ranges when I use that.

in FPS.py, my (5.0 - result) ranges from 0.039(low enough to pass) to over 
0.076, 
which is too high.  

Without it, I get pretty consistent 0.0772.  

In all of my samples, *with* the clock tick before the loop starts, I get a 
shorter 
time than *without*, though *without* is more consistent.  

I'd like to work on this in 1.2.  It seems like there's a way to reliably get a 
higher resolution timer in windows in a fashion that will be consistent across 
xp, 
vista, and hopefully windows 7.  

For 1.1 maintenance, I can apply this change to the test, which means that 
sometimes 
it will pass on windows, and sometimes it will not.  An improvement over always 
failing, I suppose.  Also, since it's only changing the test, it does not risk 
stability in the library.  I don't want to gum things up before pyweek :)

Original comment by benjamin...@gmail.com on 22 Aug 2009 at 8:28

• Changed title: test clock.SCHEDULE_INTERVAL fails in windows xp ( 1.1 maintenance )

[GoogleCodeExporter]

I'm closing this bug since it is rather old and we need a clean list to follow 
new issues. It may be gone with the new AVBin work. If you think this is still 
a problem, can you retest the problem with a recent version and add the issue 
again? Better yet, can you write test which illustrates it and/or a patch to 
fix it?

Original comment by winstonw...@gmail.com on 22 Jun 2012 at 10:37