Jump in cycle time.

BlitzMax Forums/BlitzMax Beginners Area/Jump in cycle time.

tonyg(Posted 2007) [#1]
I run the following and get a constant 0ms reported which is as expected.... I guess.
Graphics 800 , 600
GCSetMode 2
Local t1:Int
Local t2:Int
While Not KeyHit(KEY_ESCAPE)
	t1=MilliSecs()
'	Cls
 '       Flip 0	
	t2 = MilliSecs() 
	Print (t2-t1)
Wend

I then uncomment the cls/flip 0.
The same 0ms is reported but, every 170-190 frames (possibly every 3secs) there is a 50 ms spike.
There is no internet connection active, no other applications open and the same processes running in both tests. GCSetmode 2 means there should be no GC running.
If you run in fullscreen then the 'spikes' are more frequent although I can't say whether they are the same problem.
What is taking the 50ms or so?
<edit> *might be similar to this but mine is a VERY simple program.


Who was John Galt?(Posted 2007) [#2]
Hi tony-

I am seeing something which may or may not be related. My game forces a 60Hz frame rate (full screen), and about every 4 or 5 seconds there is a 'glitch' in on-screen movements. I thought it may be a result of forcing the frame rate, but looking at my monitor the windows set refresh is also at 60. My game isn't using any collisions.


QuickSilva(Posted 2007) [#3]
Any chance you guys are using a flat screen monitor with DVI connection? If you are I was getting a similar problem because of it.

Just thought I`d mention it.

Jason.


Grey Alien(Posted 2007) [#4]
This is why some people report my framework as being jerky. The framework itself isn't jerky but naturally if you have a nice smooth 60Hz display and then every so often there is a big time loss, the delta time catches up and it looks bad. I was wondering about maybe smoothing out the jerk by having the delta time catch up over several frames instead of in one go.

Have you tried it with OpenGL in case it's a DX thing. For that matter have you tried it in full-screen mode?

Or it could be that the DX render lag fix has been accidentally removed from windowed mode. I posted about it in the bug forum.

When I run your code I get 1s and 0s and the occasional 11 or 12. Could PRint be affecting it?


Grey Alien(Posted 2007) [#5]
Try this:

Graphics 800 , 600
GCSetMode 2
Local t1:Int
Local t2:Int
Local test: Int
Local high: Int
While Not KeyHit(KEY_ESCAPE)
	t1=MilliSecs()
	Cls
	DrawText test,0,0
	DrawText high,0,20
    Flip 0	
	t2 = MilliSecs() 
	test:Int = (t2-t1) 
	If test>high Then high = test
	If KeyHit(KEY_SPACE) Then high = 0
Wend

Run it and press space to reset the high value. You need to do this because the first frame takes a long time. Anyway after that high is mostly 1 on my PC but sometimes goes up to 2. Wonder if Print was causing the problem. Bit of quantum physics there. Observing the time difference and printing the results affected the time difference ;-)

When I change flip to 1 I get a high of 12. That's because my desktop runs at 85Hz and 1000/85 = 11.76.

Note that I DO have the render lag fixed in windowed mode so can't tell you if that's the problem or not.

Good luck.


tonyg(Posted 2007) [#6]
No flat monitor with DVI.
If you run in fullscreen then the 'spikes' are more frequent although I can't say whether they are the same problem.


If you run the same code with cls/flip commented BUT still with the print I get 0ms all the way.
Problem seen on my WinXP SP2 system with 9800pro but not on my W2K S3 Laptop.
Will run OGL mode and see what happens.


ziggy(Posted 2007) [#7]
This can be happening due the overloading of the StandardOut pipe in the IDE. flushing the standardout text stream sincronized with an IDE, can sometimes introduce a LAG. In addition, the StandardOutput Stream has a default size of 4096 Bytes. If this stream gets filled, both the IDE and the running application can hung. I would recomend to make the same test building as console application, and runing it from console. the Flip command gives some time to the host application to flush the text stream, and everything runs faster.


Grey Alien(Posted 2007) [#8]
Yeah I say you can't trust Print as an accurate indicator of frame jerks, I found this out before.


tonyg(Posted 2007) [#9]
Would this negate the Print influence?
Graphics 640,480
GCSetMode 2
Local t1:Int
Local t2:Int
Global mylist:tlist=CreateList()
While Not KeyHit(KEY_ESCAPE)
	t1=MilliSecs()
	Cls
'   changed from  Flip 1 to   	
     flip 0
	t2 = MilliSecs() 
	savetime(t2-t1)
Wend
For Local all:ttime = EachIn mylist
	Print all.value
Next
Type ttime
	Field value:Int
End Type
Function savetime(time:Int)
	Local temp:ttime = New ttime
	temp.value = time
	ListAddLast mylist , temp
End Function

?
<edit> and I'll run in console mode with the print statement.


ziggy(Posted 2007) [#10]
Well, using Flip 1 takes the time needed for vertical sync. Use Flip 0 and again will be 0 time.


Grey Alien(Posted 2007) [#11]
yeah good test. Unless there any kind of memory allocation slowdowns with the list it should be fine.


tonyg(Posted 2007) [#12]
Might be a few of these dotted around the forum.
Another Athlon user but no idea how coincidental that is.
BTW : the code in my first post uses Print and showed constant 0ms so I don't *think* it's 'print' related.
I also ran with no Flip but a cls and with no cls but a flip and the spike still occured.


Grey Alien(Posted 2007) [#13]
yeah it's the problem that never goes away and is annoying. That's why I sometimes harp on about the Amiga being smooth and also DOS for that matter (unless running via windows). Wonder if it's better in Vista with DX10...

Yes curious that your first print test was fine, but it only goes funny with cls and flip. But does it go away if you replace flip with that list filling code from above?

Also of course my graph demo should show a true picture of what's going on as it doesn't use print. Plus a graph is doing a bit more as well, more like a real game, instead of a print command.


H&K(Posted 2007) [#14]
Well..... Can you actualy show me that its a spike in runtime, and not an error in MilliSecs()

(That is, although Its probably a spike, it cannot be said to be one, until its shown that the device you are measuring it with is accurate)


tonyg(Posted 2007) [#15]
Yep, *most* annoying for me is when I looked at Fixed rate Logic I was getting jerks which I assumed were part of my code so did all sorts of jiggery-pokery.
<edit> At H&K, I'll use QueryPerformanceCounter() but surely any error in milliseconds() would be in all tests... wouldn't it?


H&K(Posted 2007) [#16]
I dont know tony, but there was some code that counted in a different way, thosands of a milli.

I use fixed rate, but with system hooks, and Ive never seen this problem
I have a Wait event loop, and Hooks that grab control at hrtZ, so maybe the addition of WaitEvent? Or Delay 1?


tonyg(Posted 2007) [#17]
Yep, that's QueryPerformanceCounter. I'll give it a try but I'm sure it's not a ms issue.
Are they any Athlon users who can try the code in my first post and say whether they get constant 0ms (or near 0ms) and then uncomment flip/cls and check again to see if there are spikes every 3 secs or so?


H&K(Posted 2007) [#18]
I have an atherlon, and I get a "Spike" but as was said in the other thread, straight after the spike, I get a dip so that the adverage is the same. The dip lasts a few cycles.

This is the reason I think that it might be a Milli problem
34
0
0
0
7
9
8
8
8
7
8
9
33
0
0
0
8
8
8
8
7
9
8
8
9
33
0
0
0
8
7
8
8
8
8
7
9

According to this I have three cycles that take no time. Doesnt this imply that is more lickly that its the code Imusing to do the timimg?


tonyg(Posted 2007) [#19]
Does this code show *any* spikes :
Graphics 800 , 600
GCSetMode 2
Local t1:Int
Local t2:Int
While Not KeyHit(KEY_ESCAPE)
	t1=MilliSecs()
'	Cls
 '       Flip 0	
	t2 = MilliSecs() 
	Print (t2-t1)
Wend

?


Grey Alien(Posted 2007) [#20]
H&K. Yeah that sort of result is bound to make my framework look totally rubbish. Sprites would make a giant leap then pause!


Grey Alien(Posted 2007) [#21]
Here's what I get with Flip 0
0
1
0
0
1
0
0
0
1
0
0
1
0
0
0
1
0
0
1
0
0
1
0
0
0
1
0
0
1
0
0
0
1
0
0
1
0
0
0
1


And here's with flip 1

11
11
11
11
11
12
12
11
12
12
12
12
11
11
11
13
11
12
11
11
13
10
13
11
12
11
12
12
12
11
12
12
11
12
12
11
12
12
12
11
12
12
12
11


Basically rock solid.


TaskMaster(Posted 2007) [#22]
I run the code with the cls/flip in and I get 3 as a high, but then, when I move the mouse over something that makes it change, I get a spike to about 150. In other words, if I move the mouse over a textfield somewhere and the mouse changes to an I-Bar, the program spikes to 150.

If I minimize or maximize a windows (like firefox) I get a spike anywhere from 150 to about 400.

It does not do this without the cls and flip.

On another note. If you leave the Cls turned on but remove the flip, the whole thing just slows to a crawl and drags the whole PC down with it.

If you turn off the cls but leave the flip on, then it acts the same as if they were both on.

Strange...


TaskMaster(Posted 2007) [#23]
More playing with this...

Using the GL driver, I do not see any glitches except when a window is min'd/max'd. The mouse glitch does not occur.

It is as I suspected, the GL driver is much better...


Grey Alien(Posted 2007) [#24]
It could be the DX Lag fix. A but wait it's not implemented in windowed mode, only full-screen mode.


tonyg(Posted 2007) [#25]
@H&K
Does this show *any*spikes?
Graphics 800 , 600
GCSetMode 2
Local t1:Int
Local t2:Int
While Not KeyHit(KEY_ESCAPE)
	t1=MilliSecs()
'	Cls
 '       Flip 0	
	t2 = MilliSecs() 
	Print (t2-t1)
Wend



H&K(Posted 2007) [#26]
No, but as they are all zero, it would be impossible for the timer to Jump wouldnt it?

Graphics 800 , 600
GCSetMode 2
Local t1:Int
Local t2:Int
While Not KeyHit(KEY_ESCAPE)
	t1=MilliSecs()

	Cls
    Delay 9
    Flip 0	
	t2 = MilliSecs() 
	Print (t2-t1)

Wend
Notice the addition of Delay 9, with this added I get no increase in the normal time, andno spikes.
SO..
Global T1:Int
Global T2:Int
Global count

Function MyHook:Object( id,data:Object,context:Object )
	
	t2=MilliSecs()
    Print (t2-t1)
	t1 = MilliSecs()

End Function

AddHook FlipHook,MyHook

Graphics 800 , 600
GCSetMode 2

While Not KeyHit(KEY_ESCAPE)
	
    'Cls
    Flip 0
    'Flip -1	
    		
Wend
As you can see Ive changed it a bit, but you will agree that the values represent the same thing?
Anyway, one of two things are happening
1) The flip hooks are stacking up on the stack
2) You cannot trust millisecs

The problem is for me, that if Flip -1 doesnt give the spike, then it does imply that something which runs in these program "Pause" times, is taking time every now and then, and "Jamming the stack", so Its is in my opinion now that it isnot a milli problem.


Grey Alien(Posted 2007) [#27]
I've seen H&K's behaviour somewhere before, might have been on my laptop or something, can't remember. But I was getin double 1000MS/60 = 16.666 which was 33 ish, immediately followed by a 0. But H&K seems to be getting 3-4 frames worth of rendering followed by a 3 frame dip. Weird.


tonyg(Posted 2007) [#28]
Test *NOT* using millisecs()



H&K(Posted 2007) [#29]
My FlipHook example, also shows that its a problem with the queue events stackingup.

Is there a command to clear the queue stack?


tonyg(Posted 2007) [#30]
Don't think so.
Could you do something like this ?
	Local myevent:Int=1
 	While Not myevent:Int=0
		myevent = PollEvent()
		Print "event" + currentevent.tostring$()
	Wend



Grey Alien(Posted 2007) [#31]
Not sure what results you are expecting but I get this sort of thing



they are mainly around 0.5 but it does vary a bit. Then every so often I get > 1 and sometimes > 10! Must be system processes if this is a very fine timer.

Anyway I'm paranoid about QuerySystemPerformanceCounter due to some stuff I read about weirdness on certain CPUs. Mind you we seem to be getting plenty of weirdness withplain old millisecs() too.


tonyg(Posted 2007) [#32]
It's specifically to discount the chance that there was a problem with milliseconds().


H&K(Posted 2007) [#33]
Do you think it might be a problem with variable speed CPUs?


tonyg(Posted 2007) [#34]
.. after all that I re-rean the tests on my desktop *without* print statements and the spike does *NOT* appear.
Great news although I feel a bit of a plank. My only defence is my initial test has the same print statements without a spike and my laptop doesn't get the problem whatever I do. Bizarre.


H&K(Posted 2007) [#35]
So....
Is the conclution, that is a cli spike?
DrawText? Spike or no SPike?


H&K(Posted 2007) [#36]
Global T1:Int
Global T2:Int

Global Array:Int[41]
For f= 0 To 40
    Array[f]=0
Next

Function MyHook:Object( id,data:Object,context:Object )
	
    t2=MilliSecs()
   
    Local l=t2-t1
    If l<39
        Array[l]:+1
    Else
        Array[40]:+1    
    EndIf
    
    For f=0 To 40
        DrawText (array[f],0,F*10)
        t1 = MilliSecs()
    Next

End Function

AddHook FlipHook,MyHook

Graphics 800 , 600
GCSetMode 2

While Not KeyHit(KEY_ESCAPE)
	
    Cls
    Flip 0	
    		
Wend
The final one is for >39Milli


tonyg(Posted 2007) [#37]
No idea why one test causes the spike and another doesn't. I'm still checking as I just run TomToads code from the other thread and got the problem again.