Nasty bug with pauseStarted in a timer

[georgiee]

This affects the built in game timer and every other created timer. When you pause the game and you resumes it, it will happen that events - even when you added them after the game already resumed - are delayed by the amount the game LAST was paused. And that can be a lot of seconds. It first seemed to be that the events are lost but they only have a very large delay after a few toggled pause states.

Here a log with the current timer & after the fix. The value of diff timer/game in the log
should always be smaller than 500 (the intended delay of the event).

This fix is a one liner. I don't think that it affects other places.

//current state. The first hello works, the second is delayed, the third even more as pauseStarted is not updated properly. 
game: paused
game: resumed
>>> wait for  hello
diff timer/game 467
>>> hello!

game: paused
game: resumed
>>> wait for  hello
diff timer/game 2549 //<-- wrong should be < 500
>>> hello!<-- 2.5 seconds until triggered

game: paused
game: resumed
>>> wait for  hello
diff timer/game 6717 //<-- wrong should be < 500
>>> hello! <-- 6.7 seconds until triggered


//after fix
game: paused
game: resumed
>>> wait for hello
diff timer/game 300 //<-- nice!
>>> hello!

game: paused
game: resumed
>>> wait for hello
diff timer/game 350 //<-- nice!
>>> hello! 

game: paused
game: resumed
>>> wait for hello
diff timer/game 350 //<-- nice!
>>> hello! 

This is the test code. I just rewrote it from coffee script so maybe it's not 100% valid.

game.input.onDown.add(handleClick)

handleClick: function(){
  //toggle pause
  game.paused = !game.paused
  if(game.paused){
    console.log('game: paused')  
  }else{  
    console.log('game: resumed')
  }

  //say delayed hello
  if(!game.paused){
    console.log '>>> wait for hello'
    game.time.events.add(500, function(){ console.log '>>> hello!' })
    setTimeout(debugEvents, 50) //show me whats happening
  }
}

//debug some information about the timer
debugEvents: function(){
  if (game.time.events.events.length > 0)
      event = game.time.events.events[0]
      console.log('diff timer/game', (game.time.events.nextTick - game.time.now))
    else
      console.log('no pending events')
  }
}

[georgiee]

wait. This also needs to be fixed for code pausing and it seems that manual created timers
still suffer from the bug. I need to dig deeper. And of course travis failed ;)

[georgiee]

I still have problems with this in my game. The current fix is to use a setTimeout
with a delay of 50ms.

game.paused = false
setTimeout(resumeGameAndStartSomeTimers, 50)
//resumeGameAndStartSomeTimers stands for everything that happens after I resume a game. This includes the creation of various timeout events- which would show the mentioned bug otherwise.

I am not able to fix this bug at the moment. Maybe you have a better big picture than I.
The problem is still the calculated value pauseDuration in Timer#resume. This value should be 0 for a game that was paused manual as the timer do not need to catch up, shouldn't it ?
My workaround seems to work around the problem as I have 50ms to properly set everything to the current time and than initial my timer events (as if no pause ever happened)

resume: function () {

        if (this.running && !this.expired)
        {
            var pauseDuration = this.game.time.now - this._pauseStarted;
            //When I set pauseDuration to 0 before I manual resume the game
            //the bug is gone.
           //I think this calculation should only be done for a manual pause as the
           //timer still runs as opposite to the case that the window was unfocussed
           //where we have to catch up to the missed time. 
            this._pauseTotal += pauseDuration;

            for (var i = 0; i < this.events.length; i++)
            {
                this.events[i].tick += pauseDuration;
            }

            this.nextTick += pauseDuration;

            this.paused = false;
            this._codePaused = false;
        }

    },

[photonstorm]

I've been working through this and have got the various issues resolved across both events and manual Timers, but there is still a clash if you manually pause and then have focus loss. Figuring it out now.

[georgiee]

I'm excited to see how you fix it 👍

[photonstorm]

Alright, I'm quite happy with the version currently in the dev branch. It's got a much more robust pause/resume handler. It took hours to do, but ultimately the solution was really quite simple. Would appreciate if you could give it a quick test.

[georgiee]

And all the problems are gone :)
I just tried every combination of disableVisiblityChange, manual & code pause & useElapsedTime.
Everything worked- so this issue is done! Thank you rich! Good job 👌

There is only one (somehow related) special scenario still makes problems:
set disableVisibilityChange to true, change the tab, wait some seconds and then go back. The timer seems to go nuts, but they are actually catching up. You can see clearly in the log when I switched back (7423), then the catch up phase and then the normal behaviour again. This should also be fixable as we could detect the very large time diff and reset the timer accordingly, shouldn't it ?

>>> time diff (should be 500): 499
>>> time diff (should be 500): 499
>>> time diff (should be 500): 500
>>> time diff (should be 500): 500
>>> time diff (should be 500): 7423
>>> time diff (should be 500): 35
>>> time diff (should be 500): 10
>>> time diff (should be 500): 16
>>> time diff (should be 500): 15
>>> time diff (should be 500): 16
>>> time diff (should be 500): 16
>>> time diff (should be 500): 16
>>> time diff (should be 500): 34
>>> time diff (should be 500): 33
>>> time diff (should be 500): 34
>>> time diff (should be 500): 34
>>> time diff (should be 500): 33
>>> time diff (should be 500): 32
>>> time diff (should be 500): 49
>>> time diff (should be 500): 199
>>> time diff (should be 500): 500 

This is the code to to test. Execute it, switch the tab and go back. I know that tab switching is somewhat uncontrollable- so is it worth to dig deeper ? I think the occuring large time delta (when measured) is promising.

    game.stage.disableVisibilityChange = true
    before = +new Date()

    game.time.events.loop(500, function(){
      console.log('>>> time diff (should be 500): ', (+new Date() - before) );
      before = +new Date();
    })

Now I will have a look at your changes. Thank you!

[georgiee]

Here another problem:

Manual mute > manual pause > manual resume = Sound on
Manual mute > code pause > code resume = Sound still off (Therefore it works as expected)

Or more explicitly:

game.sound.mute = true
game.sound.paused = true
game.paused = true
//now sound is unmuted again

[photonstorm]

Ok the latest push fixes the first case with a new timeCap property. I'm only checking it if disableVis is true, but I'm thinking it might be useful to just check all the time anyway - then a system slow down, like Windows grinding would be covered even though the game didn't actually pause or loose vis.

[hilts-vaughan]

This is currently an issue when windows lags down too, can confirm. I had
to stop using timers and rely on intervals because halting in the debugger
would cause massive timer event delays (and sometimes oddly, multiple ones
in a row, separate bug?)
On Apr 28, 2014 8:24 AM, "Richard Davey" notifications@github.com wrote:

Ok the latest push fixes the first case with a new timeCap property. I'm
only checking it if disableVis is true, but I'm thinking it might be useful
to just check all the time anyway - then a system slow down, like Windows
grinding would be covered even though the game didn't actually pause or
loose vis.

—
Reply to this email directly or view it on GitHubhttps://github.com//pull/759#issuecomment-41551885
.

[photonstorm]

Maybe I will enable it all the time then :)

[georgiee]

Now with disableVisibilityChange = true I have back the problem where I need to defer the start of the game by 50ms with setTimeout so that my timers are running. It's only a problem during startup- later in the game everything works fine. It seems that every timer event which is created before the game starts is never fired.

I can even work around it by delaying the flag setter:

setTimeout( function(game.stage.disableVisibilityChange = true ){}, 500)

So it's clearly something that happen only during startup.

Maybe this should be skipped in the first step ?

if (this.game.stage.disableVisibilityChange && this.elapsed > this.timeCap)
        {
            //  For some reason the time between now and the last time the game was updated was larger than our timeCap
            //  This can happen if the Stage.disableVisibilityChange is true and you swap tabs, which makes the raf pause.
            //  In this case we'll drop to some default values to stop the game timers going nuts.
            this.elapsed = 1 / 30;
        }

[photonstorm]

When are you calling disableVis? For me calling it in the create method appears to be time enough for it to work fine. But if you're doing it earlier than this that may be enough to throw it out.

[georgiee]

I'm doing it in the create method of my state. Also in the create method there is my class creating all those timers. It doesn't matter how I order them, disableVisibilityChange stops them from being executed in the first place. I try to build a demo for this behaviour.

[georgiee]

It's something with manual created timers. The following example won't work unless you set game.stage.disableVisibilityChange = false. You will only see the message hello default event as this is dispatched by the default game timer- which works apparently.

create: function(){
  game.stage.disableVisibilityChange = true;
  timer = game.time.create(false);

  timer.repeat(500, 10, function() {
    console.log('>>> hello repeat');
  });

  timer.add(500, function() {
    console.log('>>> hello event');
  });

  timer.start();

  game.time.events.add(500, function(){
    console.log('>>> hello default event');
  });
}

It's not related to the timer.start() because even when I delayed that call via setTimeout it's not running.

Regards George

[photonstorm]

Heh, yeah I wonder why:

:)

[photonstorm]

Ok there - try the new push! Basically Timer._now was never seeded on creation, so the first elapsed went insane. Now handled. Your tests above work fine for me now anyway.

[georgiee]

Ahh lovely error, so the timer is only a little bit delayed :) I can confirm your fix, works for me now 👍
So the last problem is the one with the sound + manual pause. Have you already reproduced that error or do I need to provide a quick demo? (Error is still there with the latest commit). After this everything is fixed with the timers!

[photonstorm]

Nope I've got a test case for this error already and am part way through fixing it.

[photonstorm]

Sound issue fixed :) Here's the test code:

var game = new Phaser.Game(800, 600, Phaser.CANVAS, 'phaser-example', { preload: preload, create: create, render: render });

function preload() {

    game.load.audio('boden', ['assets/audio/bodenstaendig_2000_in_rock_4bit.mp3', 'assets/audio/bodenstaendig_2000_in_rock_4bit.ogg']);

}

var music;

function create() {

    var bmd = game.make.bitmapData(800, 600);
    bmd.context.fillStyle = '#754c24';
    bmd.context.fillRect(0, 0, 800, 300);
    bmd.context.fillStyle = '#24756b';
    bmd.context.fillRect(0, 300, 800, 300);
    game.add.image(0, 0, bmd);

    music = game.add.audio('boden');

    music.play();

    game.input.onDown.add(handleClick);

}

function handleClick(pointer) {

    if (pointer.y <= 300)
    {
        game.paused = !game.paused
    }
    else
    {
        //  It is entirely possible to un-mute audio WHILE a game is paused.
        //  I consider this a feature, so I'm not going to prevent it.
        //  What this test should demonstrate is that paused audio isn't restarted when a game un-pauses.
        game.sound.mute = !game.sound.mute;
    }

}

function render() {

    game.debug.text('Click to toggle game paused state', 32, 32);
    game.debug.text('Game Paused: ' + game.paused, 32, 96);

    game.debug.text('Click to toggle audio mute', 32, 332);
    game.debug.soundInfo(music, 32, 396);

}

[georgiee]

YES. Confirmed!

//  It is entirely possible to un-mute audio WHILE a game is paused.

Absolutely.

In fact this is the second thing I tested and I would have been disappointed if you had fixed it!
Timer Fixing Mission completed. Thanks a lot! Another step to a Phaser Library without any complaints :)

[photonstorm]

Sweet - looking at your P2 / IE9 TypeArray posts now. Figuring I can just use that little shim to sort out my BitmapData changes :)

[georgiee]

That would be great! It would be a shame to let Phaser not fully support IE9 because of some small parts in the code. Maybe you can already merge that p2 change (Utils.ARRAY_TYPE = window.Float32Array || Array; cited from englercj, schteppe/p2.js#83) in the bundled p2 version until Stefan merges it? Then you could mark 2.0.4 as fully IE9 compatible! (minus the things we might have missed)

Regards George

[photonstorm]

I've added the dataview polyfill into the resources folder in the repo (it's too large to bundle in natively). I've also added the TypedArray shim into Utils and patched it up for jshint. Updated to latest p2.js and included the fixed Float32Array line too. All in all, that should be everything IE9 needs.