twitchy graphics

[another_commander]

Nightly 0b97d57 should be out with a timer change slightly different to what was discussed above. Could someone please re-run the universe profiling checks and let us know whether this build does anything about the stutter issues?

[Cody]

A very quick test, with a full OXP load-out:

Code: Select all

11:37:49.874 [universe.profile.update]: Begin update
11:37:49.874 [universe.profile.update]: update:entity
11:37:49.876 [universe.profile.update]: updating linked lists
11:37:49.876 [universe.profile.update]: collision and shadow detection
11:37:49.876 [universe.profile.update]: clean up
11:37:49.876 [universe.profile.update]: JS Garbage Collection
11:37:49.876 [universe.profile.update]: Update complete
11:37:49.876 [universe.profile.draw]: Begin draw
11:37:49.876 [universe.profile.draw]: Begin opaque pass
11:37:49.878 [universe.profile.draw]: Begin translucent pass
11:37:49.878 [universe.profile.draw]: Begin HUD
11:37:49.879 [universe.profile.draw]: End drawing

No stutter seen as yet - I'll run a longer test when I've had coffee.

[Zieman]

New build, just downloaded & compiled.
I think I got the twitchy part in the log now (when animation is smooth, you get 14-18 ms between "End drawing" and "Begin update", but here you see only 3 ms followed by 27 ms - clearly visible twitch in game:

Code: Select all

14:48:07.083 [universe.profile.update]: Begin update
14:48:07.083 [universe.profile.update]: update:entity
14:48:07.083 [universe.profile.update]: updating linked lists
14:48:07.083 [universe.profile.update]: collision and shadow detection
14:48:07.083 [universe.profile.update]: clean up
14:48:07.083 [universe.profile.update]: JS Garbage Collection
14:48:07.083 [universe.profile.update]: Update complete
14:48:07.083 [universe.profile.draw]: Begin draw
14:48:07.083 [universe.profile.draw]: Begin opaque pass
14:48:07.083 [universe.profile.draw]: Begin translucent pass
14:48:07.083 [universe.profile.draw]: Begin HUD
14:48:07.084 [universe.profile.draw]: End drawing
14:48:07.099 [universe.profile.update]: Begin update
14:48:07.099 [universe.profile.update]: update:entity
14:48:07.099 [universe.profile.update]: updating linked lists
14:48:07.100 [universe.profile.update]: collision and shadow detection
14:48:07.100 [universe.profile.update]: clean up
14:48:07.100 [universe.profile.update]: JS Garbage Collection
14:48:07.100 [universe.profile.update]: Update complete
14:48:07.100 [universe.profile.draw]: Begin draw
14:48:07.100 [universe.profile.draw]: Begin opaque pass
14:48:07.100 [universe.profile.draw]: Begin translucent pass
14:48:07.100 [universe.profile.draw]: Begin HUD
14:48:07.100 [universe.profile.draw]: End drawing
14:48:07.103 [universe.profile.update]: Begin update
14:48:07.103 [universe.profile.update]: update:entity
14:48:07.103 [universe.profile.update]: updating linked lists
14:48:07.103 [universe.profile.update]: collision and shadow detection
14:48:07.103 [universe.profile.update]: clean up
14:48:07.103 [universe.profile.update]: JS Garbage Collection
14:48:07.103 [universe.profile.update]: Update complete
14:48:07.103 [universe.profile.draw]: Begin draw
14:48:07.103 [universe.profile.draw]: Begin opaque pass
14:48:07.103 [universe.profile.draw]: Begin translucent pass
14:48:07.103 [universe.profile.draw]: Begin HUD
14:48:07.104 [universe.profile.draw]: End drawing
14:48:07.131 [universe.profile.update]: Begin update
14:48:07.131 [universe.profile.update]: update:entity
14:48:07.131 [universe.profile.update]: updating linked lists
14:48:07.131 [universe.profile.update]: collision and shadow detection
14:48:07.131 [universe.profile.update]: clean up
14:48:07.131 [universe.profile.update]: JS Garbage Collection
14:48:07.131 [universe.profile.update]: Update complete
14:48:07.131 [universe.profile.draw]: Begin draw
14:48:07.131 [universe.profile.draw]: Begin opaque pass
14:48:07.132 [universe.profile.draw]: Begin translucent pass
14:48:07.132 [universe.profile.draw]: Begin HUD
14:48:07.132 [universe.profile.draw]: End drawing
14:48:07.148 [universe.profile.update]: Begin update
14:48:07.148 [universe.profile.update]: update:entity
14:48:07.148 [universe.profile.update]: updating linked lists
14:48:07.148 [universe.profile.update]: collision and shadow detection
14:48:07.148 [universe.profile.update]: clean up
14:48:07.148 [universe.profile.update]: JS Garbage Collection
14:48:07.148 [universe.profile.update]: Update complete
14:48:07.148 [universe.profile.draw]: Begin draw
14:48:07.148 [universe.profile.draw]: Begin opaque pass
14:48:07.148 [universe.profile.draw]: Begin translucent pass
14:48:07.148 [universe.profile.draw]: Begin HUD
14:48:07.149 [universe.profile.draw]: End drawing

[Cody]

Yep, the stutter is still there - on a rotating Coriolis, and when I frag a Viper.

[another_commander]

Seems that there was a slight mistake with commit 0b97d57 and the intended fix did not go in. Those who can build from source, please go ahead and update to commit 925a403, otherwise hold for tomorrow's nightly.

[Zieman]

Updated, but alas, the jittering seems to have only increased. Visible in the log too (same 3 ms followed by a whopping 29 ms now ):

Code: Select all

15:27:07.589 [universe.profile.update]: Begin update
15:27:07.589 [universe.profile.update]: update:entity
15:27:07.589 [universe.profile.update]: updating linked lists
15:27:07.589 [universe.profile.update]: collision and shadow detection
15:27:07.589 [universe.profile.update]: clean up
15:27:07.589 [universe.profile.update]: JS Garbage Collection
15:27:07.589 [universe.profile.update]: Update complete
15:27:07.589 [universe.profile.draw]: Begin draw
15:27:07.589 [universe.profile.draw]: Begin opaque pass
15:27:07.589 [universe.profile.draw]: Begin translucent pass
15:27:07.589 [universe.profile.draw]: Begin HUD
15:27:07.590 [universe.profile.draw]: End drawing
15:27:07.605 [universe.profile.update]: Begin update
15:27:07.605 [universe.profile.update]: update:entity
15:27:07.605 [universe.profile.update]: updating linked lists
15:27:07.605 [universe.profile.update]: collision and shadow detection
15:27:07.605 [universe.profile.update]: clean up
15:27:07.605 [universe.profile.update]: JS Garbage Collection
15:27:07.605 [universe.profile.update]: Update complete
15:27:07.605 [universe.profile.draw]: Begin draw
15:27:07.605 [universe.profile.draw]: Begin opaque pass
15:27:07.605 [universe.profile.draw]: Begin translucent pass
15:27:07.605 [universe.profile.draw]: Begin HUD
15:27:07.606 [universe.profile.draw]: End drawing
15:27:07.609 [universe.profile.update]: Begin update
15:27:07.609 [universe.profile.update]: update:entity
15:27:07.609 [universe.profile.update]: updating linked lists
15:27:07.609 [universe.profile.update]: collision and shadow detection
15:27:07.609 [universe.profile.update]: clean up
15:27:07.609 [universe.profile.update]: JS Garbage Collection
15:27:07.609 [universe.profile.update]: Update complete
15:27:07.609 [universe.profile.draw]: Begin draw
15:27:07.609 [universe.profile.draw]: Begin opaque pass
15:27:07.609 [universe.profile.draw]: Begin translucent pass
15:27:07.609 [universe.profile.draw]: Begin HUD
15:27:07.610 [universe.profile.draw]: End drawing
15:27:07.639 [universe.profile.update]: Begin update
15:27:07.639 [universe.profile.update]: update:entity
15:27:07.639 [universe.profile.update]: updating linked lists
15:27:07.639 [universe.profile.update]: collision and shadow detection
15:27:07.639 [universe.profile.update]: clean up
15:27:07.639 [universe.profile.update]: JS Garbage Collection
15:27:07.639 [universe.profile.update]: Update complete
15:27:07.639 [universe.profile.draw]: Begin draw
15:27:07.639 [universe.profile.draw]: Begin opaque pass
15:27:07.639 [universe.profile.draw]: Begin translucent pass
15:27:07.639 [universe.profile.draw]: Begin HUD
15:27:07.640 [universe.profile.draw]: End drawing

[Zieman]

Weird: recording a short video with FRAPS cures the twitchiness, during recording and after recording(!) : smooth.
Quit the game, quit FRAPS, launch the game - jittering again.

[another_commander]

Zieman, if you just launch Fraps before Oolite and run Oolite without recording anything, is it smooth or jittery? Also, can you please confirm that resetting the animation timer back to 0.01 in GameController.m generates universe profile logs like the first ones you posted, where the frame sync delay appeared in the middle of a frame process, even with Fraps running in the background?

The stutter logged in your last post looks like a driver caused sync problem. 29ms is very close to the sum of the sync delay time for two frames, right? So it looks like for some reason one frame was sent for display too early. Then the frame was displayed and the driver started waiting for sync delay. But instead of acknowledging an "oh, shoot! I sent that one too early" moment and waiting for one frame's sync delay (approx. 14ms), then continue, it did all the waiting for both the frame before the one that was sent too early, plus the waiting for the early frame, possibly because those two waits were already scheduled internally. Of course I could be completely off with this theory, but 27 and 29 ms fit pretty close and I don't think they are just accidental values.

I believe Fraps uses a driver of its own to tap an already running OpenGL/DX application and do its thing. If this is correct, then maybe Oolite is not at fault here, in the sense that there could be nothing in its code that would specifically cause the stutter we witness. What may probably be missing is code that specifically avoids it. Maybe we should look into a v-sync implementation internal to Oolite, that only starts processing frames when the game itself confirms through its running timers that it is OK to do so?

One more thing: Is there anyone who plays Oolite without witnessing any stuttering at all at this moment? When I was at the Elite Meet in the UK in November, I remember the (high-end) machine where Oolite was running and I remember it because it was all so smooth and nice and it seemed to me there was no stutter at all. So I'd be interested to hear from people who don't witness any jitter, stutter or twitch, if there are any. If there are, system specs would be most welcome.

[Diziet Sma]

When I was at the Elite Meet in the UK in November, I remember the (high-end) machine where Oolite was running and I remember it because it was all so smooth and nice and it seemed to me there was no stutter at all.

Do you recall who owned that machine? It might pay to get in touch with them..

[Zieman]

Zieman, if you just launch Fraps before Oolite and run Oolite without recording anything, is it smooth or jittery?

Jittery.

Also, can you please confirm that resetting the animation timer back to 0.01 in GameController.m generates universe profile logs like the first ones you posted, where the frame sync delay appeared in the middle of a frame process, even with Fraps running in the background?

Not anymore, no difference in the logs.

The stutter logged in your last post looks like a driver caused sync problem. 29ms is very close to the sum of the sync delay time for two frames, right? So it looks like for some reason one frame was sent for display too early. Then the frame was displayed and the driver started waiting for sync delay. But instead of acknowledging an "oh, shoot! I sent that one too early" moment and waiting for one frame's sync delay (approx. 14ms), then continue, it did all the waiting for both the frame before the one that was sent too early, plus the waiting for the early frame, possibly because those two waits were already scheduled internally. Of course I could be completely off with this theory, but 27 and 29 ms fit pretty close and I don't think they are just accidental values.

I believe Fraps uses a driver of its own to tap an already running OpenGL/DX application and do its thing. If this is correct, then maybe Oolite is not at fault here, in the sense that there could be nothing in its code that would specifically cause the stutter we witness. What may probably be missing is code that specifically avoids it. Maybe we should look into a v-sync implementation internal to Oolite, that only starts processing frames when the game itself confirms through its running timers that it is OK to do so?

This is worth investigating, IMHO.

One more thing: Is there anyone who plays Oolite without witnessing any stuttering at all at this moment? When I was at the Elite Meet in the UK in November, I remember the (high-end) machine where Oolite was running and I remember it because it was all so smooth and nice and it seemed to me there was no stutter at all. So I'd be interested to hear from people who don't witness any jitter, stutter or twitch, if there are any. If there are, system specs would be most welcome.

I'm beginning to wonder if this is OS specific problem? How is it wit Linux / Mac ?

[Cody]

I'm beginning to wonder if this is OS specific problem? How is it wit Linux / Mac ?

Smivs is on Linux, and he sees the stutter too.

[Zieman]

Ok, I did some testing, and got results too. I've uploaded a bunch of Latest.logs to box: https://app.box.com/s/4n0jmuo1at5t0il2g6em
File names should explain what way I've done the tests.

One interesting thing I noticed:
commenting out

Code: Select all

SDL_GL_SetAttribute(SDL_GL_SWAP_CONTROL, 1);

in MyOpenGLView.m did not get rid of V-sync, but changing the line to

Code: Select all

SDL_GL_SetAttribute(SDL_GL_SWAP_CONTROL, 0);

did the trick. Combined with

Code: Select all

NSTimeInterval ti = 0.001;

in GameController.m I finally got results I expected, FPS-wise with V-sync OFF:

Another interesting thing I noticed that once I got Oolite to have no V-sync, NVidia Control Panel settings (General or Oolite.exe separate or together) have no effect on it. At least Oolite & FRAPS both report stable 99 FPS with

Code: Select all

NSTimeInterval ti = 0.01;

in GameController.m. Well, I have no problem with that, since the graphics are smooth as silk and I notice no tearing on screen. Normal entity-related hiccups still occur though, very occasionally.

[another_commander]

I'm beginning to wonder if this is OS specific problem? How is it wit Linux / Mac ?

Smivs is on Linux, and he sees the stutter too.

cim is on Linux and the stutters occur there too. I'd really be interested to hear our Mac users. If Mac users say they don't see this problem, maybe it could be SDL related, since Win and Linux ports both run under SDL.

[Disembodied]

I'm on a Mac, and I get a stutter too. This is under strict mode, watching the Lave Coriolis:

Normal:

Code: Select all

21:02:28.785 [universe.profile.update]: Begin update
21:02:28.785 [universe.profile.update]: update:entity
21:02:28.785 [universe.profile.update]: updating linked lists
21:02:28.785 [universe.profile.update]: collision and shadow detection
21:02:28.785 [universe.profile.update]: clean up
21:02:28.785 [universe.profile.update]: Update complete
21:02:28.786 [universe.profile.draw]: Begin draw
21:02:28.786 [universe.profile.draw]: Begin opaque pass
21:02:28.786 [universe.profile.draw]: Begin translucent pass
21:02:28.787 [universe.profile.draw]: Begin HUD
21:02:28.793 [universe.profile.draw]: End drawing

Stutter:

Code: Select all

21:02:28.805 [universe.profile.update]: Begin update
21:02:28.805 [universe.profile.update]: update:entity
21:02:28.812 [universe.profile.update]: updating linked lists
21:02:28.812 [universe.profile.update]: collision and shadow detection
21:02:28.812 [universe.profile.update]: clean up
21:02:28.812 [universe.profile.update]: Update complete
21:02:28.812 [universe.profile.draw]: Begin draw
21:02:28.812 [universe.profile.draw]: Begin opaque pass
21:02:28.898 [universe.profile.draw]: Begin translucent pass
21:02:28.899 [universe.profile.draw]: Begin HUD
21:02:28.900 [universe.profile.draw]: End drawing

Normal again:

Code: Select all

21:02:28.905 [universe.profile.update]: Begin update
21:02:28.905 [universe.profile.update]: update:entity
21:02:28.906 [universe.profile.update]: updating linked lists
21:02:28.906 [universe.profile.update]: collision and shadow detection
21:02:28.906 [universe.profile.update]: clean up
21:02:28.906 [universe.profile.update]: Update complete
21:02:28.906 [universe.profile.draw]: Begin draw
21:02:28.906 [universe.profile.draw]: Begin opaque pass
21:02:28.907 [universe.profile.draw]: Begin translucent pass
21:02:28.907 [universe.profile.draw]: Begin HUD
21:02:28.909 [universe.profile.draw]: End drawing

[cim]

My guess, since the "stutter" is generally in between "Begin opaque pass" and "Begin transparent pass" that some object is taking an unusually long time to draw. The likely reason for that is that it's a new object and it needs to load the textures in, but the texture loader hasn't finished and so the game has to wait for it. If you were playing on a computer with a lot of RAM it might be able to keep all of them pre-loaded and not have that happen.

There may be things which can be done to optimise it further, perhaps.