Measuring Render Time
Blitz3D Forums/Blitz3D Programming/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 EndIf 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: 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. 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... |
| ||
But in my sample code: Ah, well. I can't really comment on that curiosity because it works fine on my machine! FlipTime: 0~1 ms NothingTime: 10~20 ms Why? |
| ||
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? |