Measuring Render Time

Hi friends. This one goes for Blitz3d Guru's:

I am trying to measure every time my program needs. So i measure the rendertime, the physicstime, the blitz-code time, etc...

But i get some things very curious...

Look at my while loop:

While (Not KeyHit(1))

If (KeyDown(200)) MoveEntity camera,0,0,1
If (KeyDown(208)) MoveEntity camera,0,0,-1
If (KeyDown(203)) MoveEntity camera,-1,0,0
If (KeyDown(205)) MoveEntity camera,2,0,0

time1 = MilliSecs()
RenderWorld
time2 = MilliSecs() - time1

nothingtime = MilliSecs()

DebugLog "NothingTime = " + nothingtime2

fliptime = MilliSecs()
Flip
fliptime = MilliSecs() - fliptime

nothingtime2= MilliSecs()-nothingtime
Wend

In a Scene with 34.000 triangles and 5 textures i get:

rendertime = 2ms
fliptime = 0<1 ms
nothingtime = 20 ms !!!! (when looking at the hole scene). and Even commenting the Flip line...

So the fps drops drastically...

What am i missing?

Thanks!

Probably debuglog takes so much time? How about to store its average value and print it when the program ends?

Thanks for the answer, but no, it is not debuglog. I have done the same writing to a file without debug enabled and the result is the same :(

And if i don't make anything i can see the slow down in the program!!!

It is some "after-rendering" process or so...

Well this really doesn't make sense.

So you say

...
nothingtime = MilliSecs()
text 0,0,nothingtime2
;Flip
nothingtime2= MilliSecs()-nothingtime
...

still gives you about 20 ms?

KuRiX (Posted 41 minutes ago)

While (Not KeyHit(1))

If (KeyDown(200)) MoveEntity camera,0,0,1
If (KeyDown(208)) MoveEntity camera,0,0,-1
If (KeyDown(203)) MoveEntity camera,-1,0,0
If (KeyDown(205)) MoveEntity camera,2,0,0

time1 = MilliSecs()
RenderWorld
time2 = MilliSecs() - time1

nothingtime = MilliSecs()

DebugLog "NothingTime = " + nothingtime2

fliptime = MilliSecs()
Flip
fliptime = MilliSecs() - fliptime

nothingtime2= MilliSecs()-nothingtime
Wend 

Shouldn't you be finding out the value of nothingtime2?

Yes! Amazing!

It is some kind of collapse time after renderworld...

If i change the code a little bit the problem appears on different zones of the code :_(

I will upload a demo for you to test...

@Ross C: The first time the value is zero, but then you will get the latest value.

Please some test this code and tell me the value of Nothingtime2 and why???

;************************;
; Nothing Time DEMO By KuRi
; Why nothing time is so high?
;************************;

Graphics3D 800,600,16,1

SetBuffer BackBuffer()
ClearTextureFilters

Camera = CreateCamera()
PositionEntity camera,0,100,0
RotateEntity camera,45,0,0
CameraRange camera,1,500
EntityType camera,1,True
EntityRadius camera,2.5

;LOAD MAP (NOTHING???)

;CREATE LIGHT
light = CreateLight()
PositionEntity light,0,100,0

;MAIN LOOP
While (Not KeyHit(1))

If (KeyDown(200)) MoveEntity camera,0,0,1
If (KeyDown(208)) MoveEntity camera,0,0,-1
If (KeyDown(203)) MoveEntity camera,-1,0,0
If (KeyDown(205)) MoveEntity camera,2,0,0

RotateEntity camera,EntityPitch(camera),EntityYaw(camera),0
TurnEntity Camera,0,-MouseXSpeed(),0
TurnEntity Camera,MouseYSpeed(),0,0
MoveMouse 400,300

time1 = MilliSecs()
RenderWorld
time2 = MilliSecs() - time1

nothingtime = MilliSecs()

Text 0,0,"TESTING NOTHINGTIME v.01 -:- TR = " + TrisRendered()
Text 0,20,"Rend MS = " + time2
Text 0,40,"Flip MS = " + Fliptime
Text 0,60,"NothingTime = " + nothingtime2

Fliptime= MilliSecs()
Flip
Fliptime= MilliSecs() - Fliptime

nothingtime2 = MilliSecs()-nothingtime


Wend

End

I tried to reproduce this problem with a few thousand createcubes, it gives me zero in windowed mode (used with no Flip). If I test it in fullscreen mode with Flip false, it gives my 7 ms, surprisingly. If I SetBuffer Frontbuffer() and remark the Flip Command, I get zero to one ms again.

EDIT. now this is really strange:

If I use 2000 Cubes with Flip False in Fullscreen, it takes 7 ms, but if I use 4000 cubes, it takes 0 to 1 ms!
And it's getting even crazier:
500 Cubes: 14ms!
50 Cubes: 16 ms!

The code is:

text 0,0,tn2-tn1
tn1=milisecs()
flip 0
tn2=millisecs()

this is reeeeeeally weird... Especially since one frame at 60HZ should not take more than 16.67 millisecs.

What's going on here? Does a renderworld automaticly force flip to make a break no matter if its waitsync-flag is true or false?

nevermind - Deleted

@jfk EO-11110 : I am happy i am not the only having this problem!. The weird thing is that i can see the rendertime at 2ms but the fps drop dramatically!

any solution?

Well I have isolated the bugger, in my case it's clearly flip false that doesn't flip immediately, but acts like flip true.
I'd like to know if this happens on all machines. I've tested it on my oltimer, win98 with Radeon 9200se.

Right now it also seems, contrairy to what I said before, the number of cubes doesn't matter, it always takes at least 17 millisecs.

Not sure why I had other results before, got to make some more tests.

Ok, latest insights: The whole loop always takes 16.7 ms, even with Flip 0. But the flip command acts always like flip true, so when I have 50 cubes only, flip 0 takes 16ms, when I got 500 cubes then flip false takes 14ms, the remeining time to the next sync I think.

Probably I got to chek older compiler versions. I remember some time Flip 1 didn't work and acted like Flip 0, now it's the opposite. really confusing.

But try commenting the flip command and then using debuglog or writestring to see the ms... they are 20 anyway!

Not here as it seems. I only got problems with flip false.

Works fine for me with the code from Kurix... with Flip false te code gives me 0-1 on nothingtime...

You guys may have forced vwait in directx display setting...

Flip doesn't use Vsync AFAIK, isn't it? But, no, my DxDiag Refresh Rate is set to "Standard" as well as the Ati Panel Monitor settings (no TV out sync forced).

I see. Then the problem should be that too fast renderworld's occur then flip must wait the vsync...?

Flip uses vsync to stop the graphics card until new sync
and vwait stops the CPU until new sync... or that is what i think.

Kurix : Between 'nothingtime' and 'nothingtime2' you've got a flip true that's waiting for the next scanline, so the delay between these is going to be flip_time plus a little bit.

I've modified your example to take a mean average after a time, and nothingtime2 is always nearly equal to fliptime, because the same amount of work is happening between both start clocks.

;************************;
; Nothing Time DEMO By KuRi
; Why nothing time is so high?
;************************;

Graphics3D 1024,768,16,1

SetBuffer BackBuffer()
ClearTextureFilters

Camera = CreateCamera()
PositionEntity camera,0,0,-100
CameraRange camera,1,500
;EntityType camera,1,True
;EntityRadius camera,2.5

;LOAD MAP (NOTHING???)
For n=1 To 10
	box=CreateCube()
	ScaleEntity box,Rnd(1,5),Rnd(1,5),Rnd(1,5)
	PositionEntity box,Rnd(-50,50),Rnd(-50,50),Rnd(-50,50)
	EntityColor box,Rand(255),Rand(255),Rand(255)
Next

;CREATE LIGHT
light = CreateLight()
PositionEntity light,0,100,0

;MAIN LOOP
frames=0
While (Not KeyHit(1))
frames=frames+1
If (KeyDown(200)) MoveEntity camera,0,0,1
If (KeyDown(208)) MoveEntity camera,0,0,-1
If (KeyDown(203)) MoveEntity camera,-1,0,0
If (KeyDown(205)) MoveEntity camera,1,0,0

;RotateEntity camera,EntityPitch(camera),EntityYaw(camera),0
;TurnEntity Camera,0,-MouseXSpeed(),0
;TurnEntity Camera,MouseYSpeed(),0,0
;MoveMouse 400,300

time1 = MilliSecs()
RenderWorld
time2 = MilliSecs() - time1

nothingtime = MilliSecs()

render_time#=render_time+time2
flip_time#=flip_time+Fliptime
Idle_time#=Idle_time+nothingtime2

Fliptime= MilliSecs()
;VWait
Flip False
Fliptime= MilliSecs() - Fliptime

nothingtime2 = MilliSecs()-nothingtime


Wend
FlushKeys
Text 0,0,"TESTING NOTHINGTIME v.01 -:- TR = " + TrisRendered()
Text 0,20,"Rend MS = " + render_time/frames
Text 0,40,"Flip MS = " + flip_time/frames
Text 0,60,"NothingTime = " + Idle_time/frames
Flip
WaitKey
End
 

If you want to measure the time spent not doing anything, that'll be the time from the end of the loop to the beginning of the loop, which strangely enough will be around about 0 microseconds because no work is being done! If you want the time remaining from a frame after rendering so you know how much game code you can fit in a frame, you'll want '(number of milliseconds per frame) - (milliseconds consumed in renderworld and flip false)'. The flip true time will consume as many milliseconds to the next VBL, so you'd need to measure the flip false time (time to swithc front and back buffers) to factor that in.

I'll add some modified code. This measures the time per frame on your computer from an average of 30 VWaits, the time taken to render some cubes, the time taken to flip buffers, and presents a final calculation of how many ms time you have after rendering for game code at full frame speed. 700 boxes leaves me with less than 1ms per frame for game code!

;************************;
; Nothing Time DEMO By KuRi
; Why nothing time is so high?
;************************;

Graphics3D 1024,768,16,0

SetBuffer BackBuffer()
ClearTextureFilters

Camera = CreateCamera()
PositionEntity camera,0,0,-100
CameraRange camera,1,500
;EntityType camera,1,True
;EntityRadius camera,2.5

SeedRnd MilliSecs()
;LOAD MAP (NOTHING???)
For n=1 To 700
	box=CreateCube()
	ScaleEntity box,Rnd(1,5),Rnd(1,5),Rnd(1,5)
	PositionEntity box,Rnd(-50,50),Rnd(-50,50),Rnd(-50,50)
	EntityColor box,Rand(255),Rand(255),Rand(255)
Next

;CREATE LIGHT
light = CreateLight()
PositionEntity light,0,100,0

;MAIN LOOP
frames=0
nothingtime=MilliSecs()

; Calculate mean vwait over n frames
Screen_frame_time#=MilliSecs()
For n=1 To 30
	VWait
Next
Screen_frame_time=MilliSecs()-Screen_frame_time
Screen_frame_time=Screen_frame_time/30

While (Not KeyHit(1))
	nothingtime2 = MilliSecs()-nothingtime
	frames=frames+1
	If (KeyDown(200)) MoveEntity camera,0,0,1
	If (KeyDown(208)) MoveEntity camera,0,0,-1
	If (KeyDown(203)) MoveEntity camera,-1,0,0
	If (KeyDown(205)) MoveEntity camera,1,0,0
	
	time1 = MilliSecs()
	RenderWorld
	time2 = MilliSecs() - time1
	
	render_time#=render_time+time2
	flip_time#=flip_time+Fliptime
	
	Fliptime= MilliSecs()
;	VWait
	Flip False
	Fliptime= MilliSecs() - Fliptime
	
	Idle_time#=Idle_time+nothingtime2
	nothingtime = MilliSecs()
	
Wend

FlushKeys
Text 0,0,"TESTING NOTHINGTIME v.01 -:- TR = " + TrisRendered()
Text 0,20,"Render MS = " + render_time/frames
Text 0,40,"Flip MS = " + flip_time/frames
Text 0,60,"NothingTime = " + Idle_time/frames
Text 0,80,"MS per frame = " + Screen_frame_time
Text 0,100,"Time for logic = "+ (Screen_frame_time-flip_time/frames-render_time/frames)
Flip
WaitKey
End
 

But in my sample code:

FlipTime: 0~1 ms
NothingTime: 10~20 ms

Why?

KuRiX:

I thought it's the exact opposite! At least Vwait seems to use the current monitor refresh rate, while flip ignores the rate and uses 60 HZ all the time.

That's why I use vwait:Flip 0, but if flip 0 takes 17ms anyway, I really got to think about that again. What if vwait:flip 0 takes two vsyncs now? the horror...

Ah, well. I can't really comment on that curiosity because it works fine on my machine!

Kurix: Maybe windows is stealing time for background tasks sometime before/after the flip? Although, 10-20ms does sound alot. Anyway, try killing all your non-essential tasks and re-run.

I have tried several computers... Is anyone getting the error too?

did you tried to use a Repeat...Forever loop instead of the While(Not Keyhit(1))...Wend one? since it could be, that keyhit() takes some time to determine if the key was actually pressed. just a guestimate however...

keyhit and esp. keydown shouldn't be a problem.

KuRiX - I'd suggest you try to isolate the problem. I'd try something like this:

...
n=1000
dim a(n)
for i=0 to n
 a(i)=millisecs()
 while millisecs()=a(i)
 wend
next

for i=1 to n
 t=a(i)-a(i-1)
 if t>1 then
  print "puter had problems at: "+i+" for "+t+" millisecs"
 endif
next

Maybe you can see if it's a frequent problem, regardless of the monitor rate or renderworld etc. Maybe it will give you a hint about what it could be when you see it's frequency.

OK, I used to "click some buttons" in the ati 3d performence settings. I know for sure the vsync settings where "always off", and I set them to "standard" and all of a sudden my flip false works again as is should. I really have no idea what happened, seems like my card was kind of confused. I am really sorry for making this issue even more a mistery. So on my side the problem is solved. Although I still have no idea what's wrong with your machine, KuRiX, probably something with the settings as well? Or background tasks of other apps?