Merge lp:~nick-dedekind/indicator-sound/account-services-update-heuristics into lp:indicator-sound/14.04

[Nick Dedekind]

Added timers to volume changes to settle frequent updates from account services.

Added timers to volume changes to settle frequent updates from account services.
Asynchronous updates from changes to dbus properties were causing old volume values to feedback in control.

[lp:~nick-dedekind/indicator-sound/account-services-update-heuristics]

442. By Nick Dedekind on 2014-04-16

Added heuristic account services update timer

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:442
http://jenkins.qa.ubuntu.com/job/indicator-sound-ci/130/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-amd64-ci/70
    SUCCESS: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-armhf-ci/69
        deb: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-armhf-ci/69/artifact/work/output/*zip*/output.zip

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/indicator-sound-ci/130/rebuild

review: Approve (continuous-integration)

[lp:~nick-dedekind/indicator-sound/account-services-update-heuristics]

443. By Nick Dedekind on 2014-04-16

continue update timer if another change has come in

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:443
http://jenkins.qa.ubuntu.com/job/indicator-sound-ci/131/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-amd64-ci/71
    SUCCESS: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-armhf-ci/70
        deb: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-armhf-ci/70/artifact/work/output/*zip*/output.zip

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/indicator-sound-ci/131/rebuild

review: Approve (continuous-integration)

[Michael Terry (mterry)]

Functionality wise, it seems to work fine. Much snappier, and thank you for cleaning up after my mistake.

Code comments:

- I think I'd prefer if local_volume_changed_timeout() looked more like the following, so we don't duplicate logic about what to do when we change AS volume. But no biggie either way. Just a comment.

bool local_volume_changed_timeout()
{
 _local_volume_timer = 0;
 if (_send_next_local_volume) {
  _send_next_local_volume = false;
  start_local_volume_timer();
 }
 return false; // G_SOURCE_REMOVE
}

96 + _accountservice_volume_timer = Timeout.add_seconds (2, accountservice_volume_changed_timeout);

Two seconds is a long time. What if I change volume in greeter and swipe away immediately. I'll see old volume.

Also, why don't we immediately call accountservice_volume_changed_timeout() and then set a timeout for 2 seconds later to check again (like we do for local volume -- change first, then set a timer for updates)? Surely if we get an AS notification and we haven't changed local volume recently, no reason to wait 2 seconds.

109 + // if the local value hasn't changed.
110 + if (_local_volume_timer == 0) {

What if local value has changed and the one second timer has expired while our two second AS timer was going? Or even if they were both on one second timers, we don't know which order glib will go through that second's callbacks. Maybe have start_local_volume_timer() call stop_account_service_volume_timer()? That way we can drop the check on _local_volume_timer in the AS callback completely and trust that the callback just won't happen if local volume is changed.

115 + return true; // G_SOURCE_CONTINUE

That seems risky. If we get an update for AS, we wait two seconds. In the meantime local volume is changed. When we get the AS callback, we see that and wait another two seconds. At the end of which we apply the AS volume from four seconds ago... Right? If I'm reading that correctly, seems bad. Another reason to call stop_account_service_volume_timer() when local volume is updated.

I mean, not that a user is going to be going back and forth changing volumes in two different places. But still.

review: Needs Fixing

[lp:~nick-dedekind/indicator-sound/account-services-update-heuristics]

444. By Nick Dedekind on 2014-04-16

review changes

[Nick Dedekind (nick-dedekind)]

> Functionality wise, it seems to work fine. Much snappier, and thank you for
> cleaning up after my mistake.
>
> Code comments:
>
> - I think I'd prefer if local_volume_changed_timeout() looked more like the
> following, so we don't duplicate logic about what to do when we change AS
> volume. But no biggie either way. Just a comment.
>
> bool local_volume_changed_timeout()
> {
> _local_volume_timer = 0;
> if (_send_next_local_volume) {
> _send_next_local_volume = false;
> start_local_volume_timer();
> }
> return false; // G_SOURCE_REMOVE
> }

Not sure I understand. If we do this, then we will never send updates to AS since we need to call
sync_volume_to_accountsservice. It's different to AS property update timeout as we want to send the first update immediately.
What the current code does is:
1) if the timeout hasn't been started, send an AS update immediately and start the timeout (for case 2).
2) if the timeout is already started, only send an AS update at the end of the timeout.

>
> 96 + _accountservice_volume_timer = Timeout.add_seconds (2,
> accountservice_volume_changed_timeout);
>
> Two seconds is a long time. What if I change volume in greeter and swipe away
> immediately. I'll see old volume.

The update will be delayed for 2 seconds. Could make it smaller.

>
> Also, why don't we immediately call accountservice_volume_changed_timeout()
> and then set a timeout for 2 seconds later to check again (like we do for
> local volume -- change first, then set a timer for updates)? Surely if we get
> an AS notification and we haven't changed local volume recently, no reason to
> wait 2 seconds.

If we call accountservice_volume_changed_timeout immediately, then the local value will be updated to the
asynchronous changes given by the AS property updates (which is what is causing the issue).

1) user set volume = 0.1
2) send async AS volume update -> 0.1
3) user set volume = 0.2
4) send async AS volume update -> 0.2
5) async property update from AS from step 2 -> set internal volume = 0.1
6) async property update from AS from step 2 -> set internal volume = 0.2

So we get 0.1 -> 0.2 -> 0.1 -> 0.2

>
> 109 + // if the local value hasn't changed.
> 110 + if (_local_volume_timer == 0) {
>
> What if local value has changed and the one second timer has expired while our
> two second AS timer was going? Or even if they were both on one second
> timers, we don't know which order glib will go through that second's
> callbacks. Maybe have start_local_volume_timer() call
> stop_account_service_volume_timer()? That way we can drop the check on
> _local_volume_timer in the AS callback completely and trust that the callback
> just won't happen if local volume is changed.

Done

>
> 115 + return true; // G_SOURCE_CONTINUE
>
> That seems risky. If we get an update for AS, we wait two seconds. In the
> meantime local volume is changed. When we get the AS callback, we see that
> and wait another two seconds. At the end of which we apply the AS volume from
> four seconds ago... Right? If I'm reading t...

[Nick Dedekind (nick-dedekind)]

6) async property update from AS from step 2 -> set internal volume = 0.2
* "from step 4"

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:444
http://jenkins.qa.ubuntu.com/job/indicator-sound-ci/132/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-amd64-ci/72
    SUCCESS: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-armhf-ci/71
        deb: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-armhf-ci/71/artifact/work/output/*zip*/output.zip

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/indicator-sound-ci/132/rebuild

review: Approve (continuous-integration)

[Michael Terry (mterry)]

> Not sure I understand. If we do this, then we will never
> send updates to AS since we need to call
> sync_volume_to_accountsservice.

I know. But look at my version of the method. It calls start_local_volume_timer() which will both kick off an update to AS and start a new timer. And it's better to have one code path for "things that should happen when we're updating AS" -- for example, you only added a call to stop_account_service_volume_timer() in one of those two places, but not the other.

> If we call accountservice_volume_changed_timeout immediately,
> then the local value will be updated to the asynchronous changes
> given by the AS property updates (which is what is causing the issue).
>
> 1) user set volume = 0.1
> 2) send async AS volume update -> 0.1
> 3) user set volume = 0.2
> 4) send async AS volume update -> 0.2
> 5) async property update from AS from step 2 -> set internal volume = 0.1
> 6) async property update from AS from step 4 -> set internal volume = 0.2
>
> So we get 0.1 -> 0.2 -> 0.1 -> 0.2

With the current branch, the gap between 4-5 is handled (because we don't update local immediately on first AS notification) but at the cost of not responding instantly to notifications we didn't cause (having to wait that one second).

What about doing these two things?
 A) Add back the "if (_local_volume_timer == 0)" guard, but inside start_account_service_volume_timer() instead of accountservice_volume_changed_timeout(). That is, if we have an active local timer, totally ignore the AS notification. This will prevent us from taking AS notifications that resulted from our own actions (as long as AS gets back to us within a second).
 B) If we get an AS notification (and no active local timer exists per above), and we don't have an active AS timer, update local volume (and start an AS timer like usual). This way, we can respond immediately to external notifications, but local notifications likely won't trigger us because of step A above.

If the system is swamped such that the gap between 4-5 is longer than a second (i.e. the local timer ends so we don't notice that there was a recent local volume change), this will have problems. But we already sort of had such problems because if the gap between 5-6 is longer than a second (or two with your original logic), we'll end up applying 0.1 as the volume for a bit. If the system is that swamped, we have no way to figure out which notifications are from us anyway. All we have is time proximity.

[Nick Dedekind (nick-dedekind)]

> > Not sure I understand. If we do this, then we will never
> > send updates to AS since we need to call
> > sync_volume_to_accountsservice.
>
> I know. But look at my version of the method. It calls
> start_local_volume_timer() which will both kick off an update to AS and start
> a new timer. And it's better to have one code path for "things that should
> happen when we're updating AS" -- for example, you only added a call to
> stop_account_service_volume_timer() in one of those two places, but not the
> other.

Hm. did you miss a line? did you mean:

bool local_volume_changed_timeout()
{
 _local_volume_timer = 0;
 if (_send_next_local_volume) {
  _send_next_local_volume = false;
  sync_volume_to_accountsservice.begin (_volume); <--- need to send AS update for local changes.
  start_local_volume_timer();
 }
 return false; // G_SOURCE_REMOVE
}

If this is the case, then it's exactly the same as my code, only that mine is more efficient by not cancelling and re-adding a timer.
I only added stop_account_service_volume_timer to start_local_volume_timer. only one place

> > If we call accountservice_volume_changed_timeout immediately,
> > then the local value will be updated to the asynchronous changes
> > given by the AS property updates (which is what is causing the issue).
> >
> > 1) user set volume = 0.1
> > 2) send async AS volume update -> 0.1
> > 3) user set volume = 0.2
> > 4) send async AS volume update -> 0.2
> > 5) async property update from AS from step 2 -> set internal volume = 0.1
> > 6) async property update from AS from step 4 -> set internal volume = 0.2
> >
> > So we get 0.1 -> 0.2 -> 0.1 -> 0.2
>
> With the current branch, the gap between 4-5 is handled (because we don't
> update local immediately on first AS notification) but at the cost of not
> responding instantly to notifications we didn't cause (having to wait that one
> second).
>
> What about doing these two things?
> A) Add back the "if (_local_volume_timer == 0)" guard, but inside
> start_account_service_volume_timer() instead of
> accountservice_volume_changed_timeout(). That is, if we have an active local
> timer, totally ignore the AS notification. This will prevent us from taking
> AS notifications that resulted from our own actions (as long as AS gets back
> to us within a second).
> B) If we get an AS notification (and no active local timer exists per above),
> and we don't have an active AS timer, update local volume (and start an AS
> timer like usual). This way, we can respond immediately to external
> notifications, but local notifications likely won't trigger us because of step
> A above.

C) If we get an AS update which wasn't sourced by the local change while the local timer is still active (but after the local change has already been applied to the AS) the update will be lost and the local value will no longer match. I maybe be wrong though...
The way it is currently will guarantee that the local value always matches the AS value and visa vera (although up to 1 second behind).

>
> If the system is swamped such that the gap between 4-5 is longer than a second
> (i.e. the local timer ends so we don't notice that there was a recent local...

[lp:~nick-dedekind/indicator-sound/account-services-update-heuristics]

445. By Michael Terry on 2014-04-18

Consolidate local_volume_changed_timeout

446. By Michael Terry on 2014-04-18

And make it so we update from an AS notification immediately if we haven't been messing with local volume recently

447. By Michael Terry on 2014-04-18

Whitespace change

[Michael Terry (mterry)]

> Hm. did you miss a line? did you mean:

No. Go back to my original function suggestion:

bool local_volume_changed_timeout()
{
 _local_volume_timer = 0;
 if (_send_next_local_volume) {
  _send_next_local_volume = false;
  start_local_volume_timer();
 }
 return false; // G_SOURCE_REMOVE
}

When start_local_volume_timer() is called, _local_volume_timer is 0. So a new AS sync will be kicked off already, without having to duplicate code. By setting _local_volume_timer to 0, we are setting the class state as if the user just started changing volume and all the normal code will be run that handles that.

> I only added stop_account_service_volume_timer to start_local_volume_timer. only one place

Right. But we want it called whether this is the first or third tick of the timer, eh? So in my version, it will be called each tick (because each tick goes back to start_local_volume_timer(). But in your version, only the first tick of the timer will stop the AS listener. (You could add a call to stop_account_service_volume_timer() in your version of local_volume_changed_timeout(), but why bother with the duplication?)

> C) If we get an AS update which wasn't sourced by the local
> change while the local timer is still active (but after the
> local change has already been applied to the AS) the update
> will be lost and the local value will no longer match. I maybe
> be wrong though...

But in that specific case we can queue up a one second timer without immediately updating volume.

> If you're convinced about your method, could you make the
> changes, test and and pastebin the changelog? I'm finiding it
> a bit hard to visualize logic.

Look at lp:~mterry/indicator-sound/as-update-modifications

Does that solve both of our concerns?

[Nick Dedekind (nick-dedekind)]

> > Hm. did you miss a line? did you mean:
>
> No. Go back to my original function suggestion:
>
> bool local_volume_changed_timeout()
> {
> _local_volume_timer = 0;
> if (_send_next_local_volume) {
> _send_next_local_volume = false;
> start_local_volume_timer();
> }
> return false; // G_SOURCE_REMOVE
> }
>
> When start_local_volume_timer() is called, _local_volume_timer is 0. So a new
> AS sync will be kicked off already, without having to duplicate code. By
> setting _local_volume_timer to 0, we are setting the class state as if the
> user just started changing volume and all the normal code will be run that
> handles that.
>
> > I only added stop_account_service_volume_timer to start_local_volume_timer.
> only one place
>
> Right. But we want it called whether this is the first or third tick of the
> timer, eh? So in my version, it will be called each tick (because each tick
> goes back to start_local_volume_timer(). But in your version, only the first
> tick of the timer will stop the AS listener. (You could add a call to
> stop_account_service_volume_timer() in your version of
> local_volume_changed_timeout(), but why bother with the duplication?)
>
> > C) If we get an AS update which wasn't sourced by the local
> > change while the local timer is still active (but after the
> > local change has already been applied to the AS) the update
> > will be lost and the local value will no longer match. I maybe
> > be wrong though...
>
> But in that specific case we can queue up a one second timer without
> immediately updating volume.
>
> > If you're convinced about your method, could you make the
> > changes, test and and pastebin the changelog? I'm finiding it
> > a bit hard to visualize logic.
>
> Look at lp:~mterry/indicator-sound/as-update-modifications
>
> Does that solve both of our concerns?

Looks good. I'm happy with the changes.
I've pushed your changes to this branch; So I'll review your revisions if you review mine ;)

[Nick Dedekind (nick-dedekind)]

LGTM

review: Approve (r445-447)

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:447
http://jenkins.qa.ubuntu.com/job/indicator-sound-ci/133/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-amd64-ci/73
    SUCCESS: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-armhf-ci/72
        deb: http://jenkins.qa.ubuntu.com/job/indicator-sound-trusty-armhf-ci/72/artifact/work/output/*zip*/output.zip

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/indicator-sound-ci/133/rebuild

review: Approve (continuous-integration)

[Michael Terry (mterry)]

Let's do it, looks good.

review: Approve

=== modified file 'src/volume-control.vala'
--- src/volume-control.vala	2014-04-01 21:13:13 +0000
+++ src/volume-control.vala	2014-04-30 09:32:43 +0000
@@ -47,6 +47,10 @@
 	private GreeterListInterface _greeter_proxy;
 	private Cancellable _mute_cancellable;
 	private Cancellable _volume_cancellable;
+	private uint _local_volume_timer = 0;
+	private uint _accountservice_volume_timer = 0;
+	private bool _send_next_local_volume = false;
+	private double _account_service_volume = 0.0;
 
 	public signal void volume_changed (double v);
 	public signal void mic_volume_changed (double v);
@@ -75,6 +79,8 @@
 			Source.remove (_reconnect_timer);
 			_reconnect_timer = 0;
 		}
+		stop_local_volume_timer();
+		stop_account_service_volume_timer();
 	}
 
 	/* PulseAudio logic*/
@@ -193,7 +199,7 @@
 					_reconnect_timer = Timeout.add_seconds (2, reconnect_timeout);
 				break;
 
-			default: 
+			default:
 				this.ready = false;
 				break;
 		}
@@ -335,7 +341,7 @@
 	public void set_volume (double volume)
 	{
 		if (set_volume_internal (volume))
-			sync_volume_to_accountsservice.begin (volume);
+			start_local_volume_timer();
 	}
 
 	void set_mic_volume_success_cb (Context c, int success)
@@ -377,8 +383,11 @@
 		Variant volume_variant = changed_properties.lookup_value ("Volume", new VariantType ("d"));
 		if (volume_variant != null) {
 			var volume = volume_variant.get_double ();
-			if (volume >= 0)
-				set_volume_internal (volume);
+			if (volume >= 0) {
+				_account_service_volume = volume;
+				// we need to wait for this to settle.
+				start_account_service_volume_timer();
+			}
 		}
 
 		Variant mute_variant = changed_properties.lookup_value ("Muted", new VariantType ("b"));
@@ -487,4 +496,65 @@
 			warning ("unable to sync volume to AccountsService: %s", e.message);
 		}
 	}
+
+	private void start_local_volume_timer()
+	{
+		// perform a slow sync with the accounts service. max at 1 per second.
+
+		// stop the AS update timer, as since we're going to be setting the volume.
+		stop_account_service_volume_timer();
+
+		if (_local_volume_timer == 0) {
+			sync_volume_to_accountsservice.begin (_volume);
+			_local_volume_timer = Timeout.add_seconds (1, local_volume_changed_timeout);
+		} else {
+			_send_next_local_volume = true;
+		}
+	}
+
+	private void stop_local_volume_timer()
+	{
+		if (_local_volume_timer != 0) {
+			Source.remove (_local_volume_timer);
+			_local_volume_timer = 0;
+		}
+	}
+
+	bool local_volume_changed_timeout()
+	{
+		_local_volume_timer = 0;
+		if (_send_next_local_volume) {
+			_send_next_local_volume = false;
+			start_local_volume_timer ();
+		}
+		return false; // G_SOURCE_REMOVE
+	}
+
+	private void start_account_service_volume_timer()
+	{
+		if (_accountservice_volume_timer == 0) {
+			// If we haven't been messing with local volume recently, apply immediately.
+			if (_local_volume_timer == 0 && !set_volume_internal (_account_service_volume)) {
+				return;
+			}
+			// Else check again in another second if needed.
+			// (if AS is throwing us lots of notifications, we update at most once a second)
+			_accountservice_volume_timer = Timeout.add_seconds (1, accountservice_volume_changed_timeout);
+		}
+	}
+
+	private void stop_account_service_volume_timer()
+	{
+		if (_accountservice_volume_timer != 0) {
+			Source.remove (_accountservice_volume_timer);
+			_accountservice_volume_timer = 0;
+		}
+	}
+
+	bool accountservice_volume_changed_timeout ()
+	{
+		_accountservice_volume_timer = 0;
+		start_account_service_volume_timer ();
+		return false; // G_SOURCE_REMOVE
+	}
 }