IronHorseDeveloper, QA Manager, Technical Support & contributorJoin Date: 2010-05-08Member: 71669Members, Super Administrators, Forum Admins, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Blue, Subnautica Playtester, Subnautica PT Lead, Pistachionauts
edited June 2014
You were able to reproduce waitingforbufferedframes with 60 fps capped, without ever dropping below 60???
I need to see this screenshot, because that breaks everything I know about this issue. Be sure that maxfps 60 is used as well since vsync is broke. (you'll notice waiting on gpu remains until that command is manually entered)
DC_DarklingJoin Date: 2003-07-10Member: 18068Members, Constellation, Squad Five Blue, Squad Five Silver
edited June 2014
Yes, my latest test inclused 60fps min/max. See, pics!
I forced a max fps with nvidia inspector, outside ns2.
it was a short run because the problem showed quite fast! (like I said, I was done in around 12 to 13 seconds of play)
BUT I had earlier tests which lasted longer with exactly the same results in terms of stutter and fps!
The start fps is of course due to starting the benchmark.
the other 45sec one was NOT in the frame which was lagging! I checked!
ALso like I said, in earlier tests I did not even break below 55!
FPS
49
55
58
56
58
59
58
58
59
60
59
56
45
58
60
Here have the frametest file. Last column is the frame duration.
grumble, wont allow me to attach.
If you mean a profiler shot... havent got.. (yet) as that was not the goal of my last test.
But I can do! But its the same identical stutter as always, so what else could it be?
If you got questions spam me on steam, perhaps faster.
But its VERY easy for me to reproduce so I can grab all info we want in terms of screenshots.
IronHorseDeveloper, QA Manager, Technical Support & contributorJoin Date: 2010-05-08Member: 71669Members, Super Administrators, Forum Admins, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Blue, Subnautica Playtester, Subnautica PT Lead, Pistachionauts
edited June 2014
You have to have to have to use maxfps command, using 3rd party app /driver setting or even the game's option only will not properly engage it.
The evidence that you've done this correctly is r_stats reporting 0 ms waiting on gpu - when prior to entering the command and remaining in the same position, it reported anything higher than 0... See screenshots below.
DC_DarklingJoin Date: 2003-07-10Member: 18068Members, Constellation, Squad Five Blue, Squad Five Silver
Why would it not properly limit 60fps when I see it.. limiting to 60fps?
You are making no sense or I fail to understand you. Nonetheless I can do this test countless times with any variable you want so let me get back to you on this tomorrow.
IronHorseDeveloper, QA Manager, Technical Support & contributorJoin Date: 2010-05-08Member: 71669Members, Super Administrators, Forum Admins, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Blue, Subnautica Playtester, Subnautica PT Lead, Pistachionauts
edited June 2014
This is what I am referring to
BOTH SCREENSHOTS HAVE VSYNC ENABLED IN THE GRAPHICS OPTIONS
Sometimes you have to move around a bit first to see this difference/ impact. It doesn't always display itself / change until you move around a bit / new textures streamed in etc
Basically... Vsync isn't working correctly.. it hasn't been for quite some time, hence why it disables itself inbetween map loads. Using the debug cmd "maxfps" helps with this.
These two methods combined will make r_stats show "Waiting for GPU" return 0 ms.... which makes it impossible for "waitingforbufferedframes" to exist.
But like i said.. it comes with mouse input delay, so it's not the best workaround
Thats guesswork at best im afraid.
Different people seem to have different results in terms of % of vram in use vs stuttering and/or quality of textures.
We would need many more people to test both low, mid to high textures to see how that would matter. More then the folk in this topic.
Explain how to test this and i gonna test this and post results.
you can actualy make a theard for it @technial forums with how to test and people can post results below even.
(im sure if people smell any kind of performance increase stutter/reduce they are willing to help).
DC_DarklingJoin Date: 2003-07-10Member: 18068Members, Constellation, Squad Five Blue, Squad Five Silver
Ok first of a big report I guess. Note I shall not post (fraps) logs of all this. The freezes on fraps are identical as before. frame freezes, gets repeated, frame moves finally.
ONE funny and perhaps important detail however!
It consistently goes as follow
* run fraps/profiler
* run
* freeze on frame
* freeze lasts some x frames
* 1 new frame
* profiler shows pic around the 2nd new frame after the freeze, consistently.
After the 5th video I gave up checking, it just does this every time.
Ok... pictures!
I have tested loads of variables, including the ones @Ironhorse requested.
All vsyncs are on tripple buffer, set in ns2 only.
* first 2 are with maxfps 60 command. Note the gpuwait time is 0!
* The next 9 are with nvidia inspector, limiting fps to 60. Some also have fraps recording. (4 and 5) Note the gpuwait is higher when limiting it outside ns2. Also both the buffer AND the 'present' spikes are there.
* What is we limit it both with nvidia and maxfps? The next 7 show! gpuwait is again above 0.
* But ironhorse asked vsycn/maxfps! Look at the next 4. Note out of all those, the one with 'present' is consistent with other results. Yes those were all hitches. Also much smaller hitches were much more noticable in my tests. (or still noticable)
* The 23th picture (the one before the last) is with maxfps/vsync AND nvidia inspector. Welcome back buffered. Note nvidia was only used for fps limit, not vsync or buffer options.
* last one: vsync
Conclusions, questions, etc:
* if you want to remove buffered errors, vsync/maxfps60 is the place you want to be. Input lag, for me, was pretty ok. Smaller causes to hitch are however more noticable. Also hitches not spitting out buffered do still occur.
* any other setting: a mix between random spikes, buffered and 'present'.
* The present error has been shown earlier in this thread as either a big spike itself or being prior to a very big spike. I do not believe it is unrelated.
* Having profiles show the spike 2 frames past the frozen frame makes me wonder how accurate it truly is. Is this intended? Note if you go back 2 frames, who is always there? 'present'. And yes, I am assuming! Always separate fact from assumptions!
* People see a spike and generally go to the biggest column in the profiler and check it out.. However in my tests smaller spikes can be seen. So what if the smaller spikes are the CAUSE and the bigger spikes are added RESULT/EFFECT which wouldn't exist without the earlier smaller spike?
HOW to test various stuff?
* always test with r_stats 1 AND/OR profiler!
- type 'profile' in console to enable or disable.
- Use spacebar to pause/unpause. (rebind your jump if spacebar)
- use arrowkeys to move frames to check spikes in a paused profiler.
- use mouse to click open purple bars.
- find the biggest spike/column with arrowkeys, click open biggest. Since there is some evidence to suspect earlier frames, screenshot 1 or 2 frames PRIOR to the spike also!
- screenshot to show if its buffered, present, or another reason!
* bind fraps benchmark and video to the same key.
- run fraps with record on fps60 in fraps.
- perhaps also profiler, but in any case r_stats 1
- fraps (free one) captures around 25 seconds so records in bulks.
- after freeze, close all.
- open frametimes csv in excel. (some excel knowhow needed from this point on!)
- take newer frame - older frame = frame duration. So if you have frames in B2 and B3, and B3 is the newer (thus later frame), your code would be =B3-B2. Do this for every frame to make a nice duration column.
- resave and reopen csv.
- use greater command for the entire duration column. The 1 on the end is first biggest number, like. =greater(B2:B400;1)
- take the framenumber / 60. (like 350th frame/60)
- open video recorded with fraps at the same time.
- the answer from your previous calculation is the second it happened. To verify play the video to see the stutter.
- JUST before this starts, play vlc frame by frame.
- verify the frozen frames happen (you click the button but you see nothing chance on screen)
- verify your profiler big spike is 2 frames AFTER the frozen frame. (thats 2 clicks)
IronHorseDeveloper, QA Manager, Technical Support & contributorJoin Date: 2010-05-08Member: 71669Members, Super Administrators, Forum Admins, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Blue, Subnautica Playtester, Subnautica PT Lead, Pistachionauts
edited June 2014
Device:Present is a lesser evil of spikes, imo, as the most i could personally recreate (with all settings high including AO) was ~45 ms... compared to the buffered spikes which can be anywhere from 80 ms to 4,000 ms.
You have some interesting network related spikes there i have not seen before.
In any case there seems to be something systemic and nearly unavoidable... makes me really want texture streaming to be disabled if we cannot fix it.
FYI @matso and @McGlaspie have been looking into this. Excited to see what they find.
DC_DarklingJoin Date: 2003-07-10Member: 18068Members, Constellation, Squad Five Blue, Squad Five Silver
edited June 2014
Aaah.. ISP modems.. Dont worry about it, the network spike is rare. Actually, ive seen it never before.
Still, I included those for my being accurate and complete in my report.
The buffered & present errors are far more often.
I have to strongly disagree on the present/buffered view. Allow me to explain!
* We do not know if people who experience stutters have mostly buffered! Few post screenshots of every stutter, and as ive shown.. it changes!
* 1 big spike or 2 smaller ones will produce the same effect.
* You can see buffered pics I posted are aroun 150ms at most also. Those were noticable. That would conclude that a 90-150ish spike on present is also noticable. (and yes it was) And I remember seeing more present stutters around 70/90.
* One of those screenshots is a present of 160ms
Note that lower fps is never a real problem. The true thing most people experience as a hindrance is a change in fps or frametimes. So a stutter from 60 to 30 could be noticable. You can also have a 60-55 fps nonstop, but if some frames their frametimes go up by 10, you still notice.
Another factor of course is both the eyes of the person as well as they monitor.
A 4000ms one is no longer a stutter. Thats a all out freeze!
This is the frametime log of all my tests yesterday:
These are 9 runs, and show the biggest ms per frame!
553.403 97.952 105.277 132.382 104.890 119.748 71.843 108.205 92.163
Even the smallest, the 71.843, is a very long time for a single frame. Lets check the vid! http://imgur.com/CRGaq9m
This IS the correct vid, times match! Also the frametimes report this at a frame of 1115, so 1115/60 = 18,583 or in the 18th second. Also correct, spike occurred in that time.
You can see the vid reports a profile jump of 13.786.
So while ns2 profiler reports a mere 13ms spike, the REAL spikle lasts for 71ms on a single frame. That is why we notice!
But whats the difference in frametime?
Thats a 4.4 to 7 times a bigger frametime then the frames directly around it!
So what about the big spikes?
Frame; Frametime; Duration of frame.
172; 3333,891; 19,594
173; 3887,294; 553,403
174; 3920,95; 33,656
Thats a 16 to 29 times bigger frametime then the frames around it!
http://imgur.com/s68ageE
WUT? 12.033?
Is it really the same one? yes, yes it is.. It occured in the first 3 seconds. 173/60=2.8833 near the late end of the 2nd second.
So ns2 is saying its a mere 12ms spike. But we wouldnt even notice a mere 12ms spike surely. But I saw a stutter on the video which seemed much bigger. INDEED nearly half a second.
aka, the profiler is not entirely accurate. Good luck!
>edit
forgot to poke @Ironhorse <
DC_DarklingJoin Date: 2003-07-10Member: 18068Members, Constellation, Squad Five Blue, Squad Five Silver
well yes, I assumed that was clear from my tests as stutters occured even on lower vram use.
Then again, Im unaware of the finer details but its worked on.. so all we need to know aye?
IronHorseDeveloper, QA Manager, Technical Support & contributorJoin Date: 2010-05-08Member: 71669Members, Super Administrators, Forum Admins, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Blue, Subnautica Playtester, Subnautica PT Lead, Pistachionauts
edited June 2014
@matso and others have been super awesome and have been having me test different things and record plogs until he found the issues.
Some more info from matso than what is in the trello card:
After digging deep into the causes of hitching (as experienced and reported by others), I have found a couple of reasons for the hitching.
1. Device contention; the texture manager was using the device for uploading textures at the same time the render was using the device for rendering. This causes the cost for creating textures to be inserted into the render thread, causing it to mysteriously take a long, long time to do things.
FIX: Added reservation/locking to device use. This significantly lowers the amount of textures loaded per second, but that can be improved later (by splitting file loading and device use into two thread for the texture manager; later patch).
2. AGP streaming. Graphics cards report the mixed ram as available, so even if you only have a 1Gb card, the card reports 4Gb (max unsigned int) as available. Thus, the texture manager never manages texture memory (the unloading never goes in), instead the graphics card will stream textures to/from primary memory. This can cause significant hitching, as the card GPU will stall while waiting for the texture to be streamed in. If your video ram is significantly smaller than the NS2 working set (lategame, this can be > 1500Gb), you will notice it if you are GPU limited.
Fix: Added r_texmax command that allows you to specify the size that the texture manager will think the card has. This means that textures will be unloaded "manually"
@matso and others have been super awesome and have been having me test different things and record plogs until he found the issues.
Some more info from matso than what is in the trello card:
After digging deep into the causes of hitching (as experienced and reported by others), I have found a couple of reasons for the hitching.
1. Device contention; the texture manager was using the device for uploading textures at the same time the render was using the device for rendering. This causes the cost for creating textures to be inserted into the render thread, causing it to mysteriously take a long, long time to do things.
FIX: Added reservation/locking to device use. This significantly lowers the amount of textures loaded per second, but that can be improved later (by splitting file loading and device use into two thread for the texture manager; later patch).
2. AGP streaming. Graphics cards report the mixed ram as available, so even if you only have a 1Gb card, the card reports 4Gb (max unsigned int) as available. Thus, the texture manager never manages texture memory (the unloading never goes in), instead the graphics card will stream textures to/from primary memory. This can cause significant hitching, as the card GPU will stall while waiting for the texture to be streamed in. If your video ram is significantly smaller than the NS2 working set (lategame, this can be > 1500Gb), you will notice it if you are GPU limited.
Fix: Added r_texmax command that allows you to specify the size that the texture manager will think the card has. This means that textures will be unloaded "manually"
Comments
I need to see this screenshot, because that breaks everything I know about this issue. Be sure that maxfps 60 is used as well since vsync is broke. (you'll notice waiting on gpu remains until that command is manually entered)
I forced a max fps with nvidia inspector, outside ns2.
it was a short run because the problem showed quite fast! (like I said, I was done in around 12 to 13 seconds of play)
BUT I had earlier tests which lasted longer with exactly the same results in terms of stutter and fps!
The start fps is of course due to starting the benchmark.
the other 45sec one was NOT in the frame which was lagging! I checked!
ALso like I said, in earlier tests I did not even break below 55!
FPS
55
58
56
58
59
58
58
59
60
59
56
45
58
60
Here have the frametest file. Last column is the frame duration.
grumble, wont allow me to attach.
If you mean a profiler shot... havent got.. (yet) as that was not the goal of my last test.
But I can do! But its the same identical stutter as always, so what else could it be?
If you got questions spam me on steam, perhaps faster.
But its VERY easy for me to reproduce so I can grab all info we want in terms of screenshots.
The evidence that you've done this correctly is r_stats reporting 0 ms waiting on gpu - when prior to entering the command and remaining in the same position, it reported anything higher than 0... See screenshots below.
You are making no sense or I fail to understand you. Nonetheless I can do this test countless times with any variable you want so let me get back to you on this tomorrow.
BOTH SCREENSHOTS HAVE VSYNC ENABLED IN THE GRAPHICS OPTIONS
Sometimes you have to move around a bit first to see this difference/ impact. It doesn't always display itself / change until you move around a bit / new textures streamed in etc
Basically... Vsync isn't working correctly.. it hasn't been for quite some time, hence why it disables itself inbetween map loads. Using the debug cmd "maxfps" helps with this.
These two methods combined will make r_stats show "Waiting for GPU" return 0 ms.... which makes it impossible for "waitingforbufferedframes" to exist.
But like i said.. it comes with mouse input delay, so it's not the best workaround
Explain how to test this and i gonna test this and post results.
you can actualy make a theard for it @technial forums with how to test and people can post results below even.
(im sure if people smell any kind of performance increase stutter/reduce they are willing to help).
ONE funny and perhaps important detail however!
It consistently goes as follow
* run fraps/profiler
* run
* freeze on frame
* freeze lasts some x frames
* 1 new frame
* profiler shows pic around the 2nd new frame after the freeze, consistently.
After the 5th video I gave up checking, it just does this every time.
Ok... pictures!
I have tested loads of variables, including the ones @Ironhorse requested.
All vsyncs are on tripple buffer, set in ns2 only.
http://imgur.com/a/Ggm5s
* first 2 are with maxfps 60 command. Note the gpuwait time is 0!
* The next 9 are with nvidia inspector, limiting fps to 60. Some also have fraps recording. (4 and 5) Note the gpuwait is higher when limiting it outside ns2. Also both the buffer AND the 'present' spikes are there.
* What is we limit it both with nvidia and maxfps? The next 7 show! gpuwait is again above 0.
* But ironhorse asked vsycn/maxfps! Look at the next 4. Note out of all those, the one with 'present' is consistent with other results. Yes those were all hitches. Also much smaller hitches were much more noticable in my tests. (or still noticable)
* The 23th picture (the one before the last) is with maxfps/vsync AND nvidia inspector. Welcome back buffered. Note nvidia was only used for fps limit, not vsync or buffer options.
* last one: vsync
Conclusions, questions, etc:
* if you want to remove buffered errors, vsync/maxfps60 is the place you want to be. Input lag, for me, was pretty ok. Smaller causes to hitch are however more noticable. Also hitches not spitting out buffered do still occur.
* any other setting: a mix between random spikes, buffered and 'present'.
* The present error has been shown earlier in this thread as either a big spike itself or being prior to a very big spike. I do not believe it is unrelated.
* Having profiles show the spike 2 frames past the frozen frame makes me wonder how accurate it truly is. Is this intended? Note if you go back 2 frames, who is always there? 'present'. And yes, I am assuming! Always separate fact from assumptions!
* People see a spike and generally go to the biggest column in the profiler and check it out.. However in my tests smaller spikes can be seen. So what if the smaller spikes are the CAUSE and the bigger spikes are added RESULT/EFFECT which wouldn't exist without the earlier smaller spike?
HOW to test various stuff?
* always test with r_stats 1 AND/OR profiler!
- type 'profile' in console to enable or disable.
- Use spacebar to pause/unpause. (rebind your jump if spacebar)
- use arrowkeys to move frames to check spikes in a paused profiler.
- use mouse to click open purple bars.
- find the biggest spike/column with arrowkeys, click open biggest. Since there is some evidence to suspect earlier frames, screenshot 1 or 2 frames PRIOR to the spike also!
- screenshot to show if its buffered, present, or another reason!
* bind fraps benchmark and video to the same key.
- run fraps with record on fps60 in fraps.
- perhaps also profiler, but in any case r_stats 1
- fraps (free one) captures around 25 seconds so records in bulks.
- after freeze, close all.
- open frametimes csv in excel. (some excel knowhow needed from this point on!)
- take newer frame - older frame = frame duration. So if you have frames in B2 and B3, and B3 is the newer (thus later frame), your code would be =B3-B2. Do this for every frame to make a nice duration column.
- resave and reopen csv.
- use greater command for the entire duration column. The 1 on the end is first biggest number, like. =greater(B2:B400;1)
- take the framenumber / 60. (like 350th frame/60)
- open video recorded with fraps at the same time.
- the answer from your previous calculation is the second it happened. To verify play the video to see the stutter.
- JUST before this starts, play vlc frame by frame.
- verify the frozen frames happen (you click the button but you see nothing chance on screen)
- verify your profiler big spike is 2 frames AFTER the frozen frame. (thats 2 clicks)
You have some interesting network related spikes there i have not seen before.
In any case there seems to be something systemic and nearly unavoidable... makes me really want texture streaming to be disabled if we cannot fix it.
FYI @matso and @McGlaspie have been looking into this. Excited to see what they find.
Still, I included those for my being accurate and complete in my report.
The buffered & present errors are far more often.
I have to strongly disagree on the present/buffered view. Allow me to explain!
* We do not know if people who experience stutters have mostly buffered! Few post screenshots of every stutter, and as ive shown.. it changes!
* 1 big spike or 2 smaller ones will produce the same effect.
* You can see buffered pics I posted are aroun 150ms at most also. Those were noticable. That would conclude that a 90-150ish spike on present is also noticable. (and yes it was) And I remember seeing more present stutters around 70/90.
* One of those screenshots is a present of 160ms
Note that lower fps is never a real problem. The true thing most people experience as a hindrance is a change in fps or frametimes. So a stutter from 60 to 30 could be noticable. You can also have a 60-55 fps nonstop, but if some frames their frametimes go up by 10, you still notice.
Another factor of course is both the eyes of the person as well as they monitor.
A 4000ms one is no longer a stutter. Thats a all out freeze!
This is the frametime log of all my tests yesterday:
These are 9 runs, and show the biggest ms per frame!
553.403 97.952 105.277 132.382 104.890 119.748 71.843 108.205 92.163
Even the smallest, the 71.843, is a very long time for a single frame. Lets check the vid!
http://imgur.com/CRGaq9m
This IS the correct vid, times match! Also the frametimes report this at a frame of 1115, so 1115/60 = 18,583 or in the 18th second. Also correct, spike occurred in that time.
You can see the vid reports a profile jump of 13.786.
So while ns2 profiler reports a mere 13ms spike, the REAL spikle lasts for 71ms on a single frame. That is why we notice!
But whats the difference in frametime?
Frame; Frametime; Duration of frame.
1114; 20406,06; 16,174
1115; 20477,903; 71,843
1116; 20489,163; 11,26
Thats a 4.4 to 7 times a bigger frametime then the frames directly around it!
So what about the big spikes?
Frame; Frametime; Duration of frame.
172; 3333,891; 19,594
173; 3887,294; 553,403
174; 3920,95; 33,656
Thats a 16 to 29 times bigger frametime then the frames around it!
http://imgur.com/s68ageE
WUT? 12.033?
Is it really the same one? yes, yes it is.. It occured in the first 3 seconds. 173/60=2.8833 near the late end of the 2nd second.
So ns2 is saying its a mere 12ms spike. But we wouldnt even notice a mere 12ms spike surely. But I saw a stutter on the video which seemed much bigger. INDEED nearly half a second.
aka, the profiler is not entirely accurate. Good luck!
>edit
forgot to poke @Ironhorse <
So it was not entirely VRAM related... quite interesting!
Then again, Im unaware of the finer details but its worked on.. so all we need to know aye?
Some more info from matso than what is in the trello card:
1. Device contention; the texture manager was using the device for uploading textures at the same time the render was using the device for rendering. This causes the cost for creating textures to be inserted into the render thread, causing it to mysteriously take a long, long time to do things.
FIX: Added reservation/locking to device use. This significantly lowers the amount of textures loaded per second, but that can be improved later (by splitting file loading and device use into two thread for the texture manager; later patch).
2. AGP streaming. Graphics cards report the mixed ram as available, so even if you only have a 1Gb card, the card reports 4Gb (max unsigned int) as available. Thus, the texture manager never manages texture memory (the unloading never goes in), instead the graphics card will stream textures to/from primary memory. This can cause significant hitching, as the card GPU will stall while waiting for the texture to be streamed in. If your video ram is significantly smaller than the NS2 working set (lategame, this can be > 1500Gb), you will notice it if you are GPU limited.
Fix: Added r_texmax command that allows you to specify the size that the texture manager will think the card has. This means that textures will be unloaded "manually"
This is about VRAM and not about system Ram. How much VRAM does your Graphics card have?
Im sure all are happy with the progress so far.
/inserts a well done to all :P