graphics.SynchronizeWithVerticalRetrace = false;

Topics: Developer Forum, User Forum
Aug 21, 2009 at 3:49 AM

I am having some issues with performance.

setting graphics.SynchronizeWithVerticalRetrace = false; runs the game smoothly but chews up the CPU,

setting graphics.SynchronizeWithVerticalRetrace = true; runs the game choppy but does not chew up the CPU.

 

This issue is present in a FlatRedBall project with farseer physics.  There are only several objects on screen at any time.

 

Has anyone come across this issue before.  Ideally I would like to have smooth draws with low CPU.

Aug 21, 2009 at 5:38 PM

Just a hunch: I think you might need to decouple the render time step from the physics time step. For stability the physics system wants constant timesteps which it should get anyway with VSync on. Your simulation probably needs a smaller timestep than the framerate (which could be either 1/60 or 1/30 fps).

Aug 24, 2009 at 1:31 PM

It is running at a fixed time step.  It looks like Draw() is taking its sweet time sometimes.  IsRunningSlowly flag is set periodically.  It seems like the issue is with the GPU / monitor combination? 

Aug 24, 2009 at 6:50 PM

I believe IsRunningSlowly means your update and draw together are taking longer than the alloted fixed time step. You could try a profiler like NProf or Ants Performance Profiler (free trial available). You probably don't notice the slowdown with VSync OFF as it's a relatively smooth slowdown, where as with VSync ON, any time your FPS drops below 60 (or your target), you'll see a little stutter because it misses a frame to wait for the next retrace. Does your fps ever go below 60 with VSync OFF?

Aug 25, 2009 at 2:07 AM

Right about the IsRunningSlowly... http://blogs.msdn.com/shawnhar/archive/2007/07/25/understanding-gametime.aspx

Any tips on the Ants profiler?

Fps does go below 60 with vsync OFF, 48-55.  Why do you ask?

Aug 25, 2009 at 2:32 AM

I take that back, FPS does not drop wth vsync OFF.

Aug 25, 2009 at 2:39 AM

I'm not sure how to use this ANTS profiler to catch a frame's worth of processing... Also I'm only seeing the Update and Draw calls for the main Game Class.  Should I be seeing individual override calls?

Aug 25, 2009 at 3:42 AM

I too couldn't work out how to show individual frames in ANTS - I don't think it's meant to. It doesn't matter to much because it adds up the time of all frames so you get an average picture. If you click and drag across the timeline at the top, you are setting the time period to analyse. I also like to set it from treeview to list so you don't have to drill down to find the slow methods - you can just sort them by time (not time with children - that means how much time it spent including the calls it made to other methods). Then the trick is trying to work out which calls to ignore and concentrate on the ones where you can make a difference.

This may not help a great deal if you're tracking down a regular spike. Can you see the spikes in the timeline graph at the time?

I asked about the FPS dropping below 60 because this would indicate that when you switch VSync on, you will get choppiness due to lost frames. VSync on means that if your game runs at 55 FPS, you will only ever get 30 FPS. If your game hovers around 50 - 70 FPS, you will see jumps between 60 and 30 FPS, which looks very choppy.

 

Aug 25, 2009 at 4:53 AM

The hit count gives an idea of the average frame time.  I don't see any spikes at all, but one thing I did notice is that FlatRedBallServices.Draw takes longer to excecute (if i'm reading this right) with vsync  ON (25% versus 6% with vsync OFF).

Roonda, take a look at the source if you have some time: http://frbfarseer.codeplex.com/Release/ProjectReleases.aspx?ReleaseId=31949#DownloadId=80458

The only thing I'm playing with is Vsync false/true.

Aug 25, 2009 at 4:55 AM

For some reason I think it's my hardware ... This laptop is 5 years old.  Is there a way to use remote performance counters on the Xbox?

Aug 25, 2009 at 12:42 PM
Edited Aug 25, 2009 at 3:21 PM

 

I changed my view to Milliseconds and selected one second at a time.  I also selected "top down (any method)" with CPU Time (excluding thread blocking times and such).  Then I dug into XNA.Game.Tick() method.  This method breaks it down per frame since Tick calls Upate and Draw.  Update is called every 17ms.  Ideally Update should complete in less than 17ms so that Draw has time to present the graphics.

Within my selected 1 second Update was called 79 times and DrawFrame was called 77 times.  Looking at Time With Children (ms) @ CPU Time: Draw took 211ms and Update took 67ms.  I am assuming that this is the total time this method took to execute (recursively) within the time-frame selected (eg. 1 second)? 

 

 

 

 

Aug 25, 2009 at 2:10 PM
Edited Aug 25, 2009 at 3:21 PM
roonda wrote:

 

I asked about the FPS dropping below 60 because this would indicate that when you switch VSync on, you will get choppiness due to lost frames. VSync on means that if your game runs at 55 FPS, you will only ever get 30 FPS. If your game hovers around 50 - 70 FPS, you will see jumps between 60 and 30 FPS, which looks very choppy.

 

Am I understanding the game loop correctly?  Out of the 17ms game loop intervals if Update takes 2ms then Draw has 15ms.  If Update takes 15ms then Draw has only 2ms to complete.  When this happens and Draw takes 10ms, that totals 25ms; 8ms over allowed time.  So when Draw completes, now the next iteration has only 90ms to complete Update and Draw.  IsRunningSlowly is set to True and again, Update will run over it's allowed time and the game loop will continue running Update until Update loops back around (catches up to its 17ms interval).  Then Draw will be tried again....etc....etc...

Aug 25, 2009 at 4:18 PM
Edited Aug 25, 2009 at 5:29 PM

Something odd is happening.  Where did Frame3 go?

 

 

Frame1:
UPDATE GAME CLOCK: 5424 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update : 3 ms (ticks 11465)
DRAW GAME CLOCK: 5427 ms
DRAW CALL gametime elapsed since last Draw : 16.6667
DRAW execution time for this Draw : 2 ms (ticks 8958)

Frame2:
Game Clock is about 16ms from previous Update, good...
UPDATE GAME CLOCK: 5440 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update : 3 ms (ticks 10902)
DRAW GAME CLOCK: 5444 ms
DRAW CALL gametime elapsed since last Draw : 16.6667
DRAW execution time for this Draw : 6 ms (ticks 24165)

Should block until GAME CLOCK is between 5456 to 5460...

Frame3:????

Frame4:
Game Clock jumped 36ms ahead, uhhhh, what happened to Frame3???
UPDATE GAME CLOCK: 5476 ms
UPDATE CALL gametime elapsed since last Update: 16.6667 <<< this should be 34ms ???!!!
UPDATE execution time for this Update : 3 ms (ticks 12981)
ok... catching up...
UPDATE GAME CLOCK: 5480 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update : 1 ms (ticks 3637)

DRAW GAME CLOCK: 5481 ms
DRAW CALL gametime elapsed since last Draw : 33.3334
DRAW execution time for this Draw : 1 ms (ticks 6465)

Frame5:
ok, back at 16ms interval again....
UPDATE GAME CLOCK: 5490 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update : 6 ms (ticks 23128)
DRAW GAME CLOCK: 5503 ms
DRAW CALL gametime elapsed since last Draw : 16.6667
DRAW execution time for this Draw : 8 ms (ticks 29635)

 

 

Aug 25, 2009 at 4:30 PM

Here is a normal frame skip:

Frame1:
  GameClock is at 4862 so next Update should happen about 4878
     but it will not since this frame will take longer than 17ms
UPDATE                              GAME CLOCK: 4862 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update         : 2 ms (ticks 10310)
DRAW                                GAME CLOCK: 4866 ms
DRAW   CALL gametime elapsed since last Draw  : 16.6667
DRAW   execution time for this Draw           : 21 ms (ticks 78084)

 Oops, last gameloop iteration took about 24ms...
  So, blocked until next Update iteration which is 4862 + 34, rougly 4893, give or take

Frame2:
  Ok, frame 2 is coming right on time...
UPDATE                              GAME CLOCK: 4893 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update         : 2 ms (ticks 9082)
 
  An extra update to catch up for the missed gameloop iteration... good...
UPDATE                              GAME CLOCK: 4896 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update         : 3 ms (ticks 13245)

   and finally a draw... screen will present correctly since the lost update has been run so sprite positions and such will be in correct place...
DRAW                                GAME CLOCK: 4900 ms
DRAW   CALL gametime elapsed since last Draw  : 33.3334
DRAW   execution time for this Draw           : 2 ms (ticks 9999)

Aug 25, 2009 at 4:47 PM

The above were run with VSYNC ON.  I get the same odd behavior with VSYNC OFF.

 

UPDATE                              GAME CLOCK: 7093 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update         : 2 ms (ticks 10102)
DRAW                                GAME CLOCK: 7097 ms
DRAW   CALL gametime elapsed since last Draw  : 16.6667
DRAW   execution time for this Draw           : 1 ms (ticks 6697)
UPDATE                              GAME CLOCK: 7127 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update         : 4 ms (ticks 14797)
UPDATE                              GAME CLOCK: 7132 ms
UPDATE CALL gametime elapsed since last Update: 16.6667
UPDATE execution time for this Update         : 3 ms (ticks 13782)
DRAW                                GAME CLOCK: 7136 ms
DRAW   CALL gametime elapsed since last Draw  : 33.3334
DRAW   execution time for this Draw           : 3 ms (ticks 11021)


Here is the Game.cs code implementing the stop watches...

public class Game1 : Microsoft.Xna.Framework.Game
    {
        GraphicsDeviceManager graphics;

        //Stopwatch _drawWatch = new Stopwatch();
        //Stopwatch _updateWatch = new Stopwatch();
        
        Stopwatch _drawElapsedWatch = new Stopwatch();
        Stopwatch _updateElapsedWatch = new Stopwatch();
       
        Stopwatch _secondElapsedWatch = new Stopwatch();
        int _updateHitCounter = 0;
        int _drawHitCounter = 0;
        bool _drawHitCounterReset = false;
        long _lastElapsedSecond = 0;

        public Game1()
        {
            Program._totalTimeWatch.Start();
            _secondElapsedWatch.Start();
            graphics = new GraphicsDeviceManager(this);
            IsFixedTimeStep = true;
            graphics.SynchronizeWithVerticalRetrace = false;
        }

        /// <summary>
        /// Allows the game to perform any initialization it needs to before starting to run.
        /// This is where it can query for any required services and load any non-graphic
        /// related content.  Calling base.Initialize will enumerate through any components
        /// and initialize them as well.
        /// </summary>
        protected override void Initialize()
        {

            FlatRedBallServices.InitializeFlatRedBall(this, this.graphics);
            
            //FlatRedBallServices.GraphicsOptions.SetResolution(320, 240);
            // Uncomment the following line and add your Screen's fully qualified name
            // if using Screens in your project.  If not, or if you don't know what it means,
            // just ignore the following line for now.
            // For more information on Screens see the Screens wiki article on FlatRedBall.com.
            //Screens.ScreenManager.Start(typeof(warheadsxna.Screens.TestScreen).FullName);
            Screens.ScreenManager.Start(typeof(warheadsxna.Screens.GameScreen1).FullName);
            IsMouseVisible = true;
        }

        /// <summary>
        /// Allows the game to run logic such as updating the world,
        /// checking for collisions, gathering input, and playing audio.
        /// </summary>
        /// <param name="gameTime">Provides a snapshot of timing values.</param>
        protected override void Update(GameTime gameTime)
        {
            _updateElapsedWatch.Start();

            Debug.WriteLine("UPDATE                              GAME CLOCK: " + Program._totalTimeWatch.ElapsedMilliseconds.ToString() + " ms");
            Debug.WriteLine("UPDATE CALL gametime elapsed since last Update: " + gameTime.ElapsedGameTime.TotalMilliseconds);

            _updateHitCounter++;
            if ( _secondElapsedWatch.ElapsedMilliseconds >= 1000 )
            {
                _secondElapsedWatch.Stop();
                _lastElapsedSecond = _secondElapsedWatch.ElapsedMilliseconds;
                if ( gameTime.IsRunningSlowly ) Debug.WriteLine(gameTime.IsRunningSlowly);
               // Debug.WriteLine("GAME CLOCK      : " + Program._totalTimeWatch.ElapsedMilliseconds.ToString() + " ms");
               // Debug.WriteLine("UPDATE hit count: " + _updateHitCounter.ToString() + " hits     (elapsed [ms] " + _lastElapsedSecond.ToString() + ")");
               // Debug.WriteLine("UPDATE avg / hit: " + (_lastElapsedSecond / _updateHitCounter).ToString() + " ms");
                _updateHitCounter = 0;
                _drawHitCounterReset = true;
                _secondElapsedWatch.Reset();
                _secondElapsedWatch.Start();
            }
            
            
            //_updateWatch.Reset();
            //_updateWatch.Start();

            FlatRedBallServices.Update(gameTime);
            Screens.ScreenManager.Activity();
            base.Update(gameTime);

            //_updateWatch.Stop();
            //Debug.WriteLine("UDT (tick): " + _updateWatch.ElapsedTicks.ToString() + "  GameTime.Elapsed(ms) : " + gameTime.ElapsedGameTime.TotalMilliseconds.ToString() + "  IsRunningSlowly : " + gameTime.IsRunningSlowly.ToString());

            _updateElapsedWatch.Stop();
            Debug.WriteLine("UPDATE execution time for this Update         : " + _updateElapsedWatch.ElapsedMilliseconds + " ms (ticks " + _updateElapsedWatch.ElapsedTicks + ")");
            _updateElapsedWatch.Reset();
        }

        /// <summary>
        /// This is called when the game should draw itself.
        /// </summary>
        /// <param name="gameTime">Provides a snapshot of timing values.</param>
        protected override void Draw(GameTime gameTime)
        {
            _drawElapsedWatch.Start();

            Debug.WriteLine("DRAW                                GAME CLOCK: " + Program._totalTimeWatch.ElapsedMilliseconds.ToString() + " ms");
            Debug.WriteLine("DRAW   CALL gametime elapsed since last Draw  : " + gameTime.ElapsedGameTime.TotalMilliseconds);

            _drawHitCounter++;
            if (_drawHitCounterReset)
            {
                //Debug.WriteLine("GAME CLOCK      : " + Program._totalTimeWatch.ElapsedMilliseconds.ToString() + " ms");
                //Debug.WriteLine("DRAW   hit count: " + _drawHitCounter.ToString() + " hits" );
                //Debug.WriteLine("DRAW   avg / hit: " + (_lastElapsedSecond / _drawHitCounter).ToString() + " ms");
                _drawHitCounter = 0;
                _drawHitCounterReset = false;
            }
            //_drawWatch.Reset();
           // _drawWatch.Start();
 
            FlatRedBallServices.Draw();
            base.Draw(gameTime);

            //_drawWatch.Stop();
            //Debug.WriteLine("DRW (tick): " + _drawWatch.ElapsedTicks.ToString() + "  GameTime.Elapsed(ms) : " + gameTime.ElapsedGameTime.TotalMilliseconds.ToString() + "  IsRunningSlowly : " + gameTime.IsRunningSlowly.ToString());

            _drawElapsedWatch.Stop();
            Debug.WriteLine("DRAW   execution time for this Draw           : " + _drawElapsedWatch.ElapsedMilliseconds + " ms (ticks " + _drawElapsedWatch.ElapsedTicks + ")");
            _drawElapsedWatch.Reset();
        }


    }

Aug 25, 2009 at 6:11 PM

I can't see anything obvious jumping out at me. I downloaded the project you linked and it ran fine with VSync both off and on. As it should on my quad core + 8800GT  :)

I'd look into why the Draw is taking 21ms sometimes. Perhaps something else on the laptop is interfering. It'd be worth opening task manager, sort by CPU and see if another process jumps up around the same time as the frame spikes.

Perhaps the issue is hardware related after all!? What sort of GPU are you using - an Intel integrated chipset perchance? You could try to get some other people with different/older hardware to give it a go.

Aug 25, 2009 at 6:28 PM

I tried on two PCs both with integrated GPU (intel).  I'm not going to worry about it.  Thanks for checking it out.

Aug 25, 2009 at 6:38 PM

Yeah I wouldn't worry either - those intel integrated GPUs are truly crappy. Good luck.