846158 - Busy wait for Preferences:Data event in robocop

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Geoff Brown [:gbrown]]

Something has gone wrong with the recent robocop work around improving our handling of Preferences messages. Something is spinning, checking far too often for a new event.

Consider (probably typical): https://tbpl.mozilla.org/php/getParsedLog.php?id=20166730&tree=Mozilla-Inbound&full=1

02-27 18:56:01.022 D/Robocop (10411): Waking up on handleMessage
02-27 18:56:01.022 D/Robocop (10411): received event Preferences:Data
02-27 18:56:01.042 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.042 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.042 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.042 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.053 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.053 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.053 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.053 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.053 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.053 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.053 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.053 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.062 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.062 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.062 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.062 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.062 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.062 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.062 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.062 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.072 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.072 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.072 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.072 D/Robocop (10411): unblocked on expecter for Preferences:Data
02-27 18:56:01.072 D/Robocop (10411): unblocked on expecter for Preferences:Data

I don't know that this is causing any problems or test failures, but it looks scary.

Comment 1

[:Margaret Leibovic]

This is probably a result of the new while loops we added to wait for the correct preference, but I'm not familiar enough with this code to know what this logging means. Does this mean that we're receiving this many Preferences:Data messages?

Comment 2

[Geoff Brown [:gbrown]]

Attachment: clear mEventReceived once event expecter unblocks

At issue here is that the EventExpecter is "one-shot", rather than re-usable. The intended usage is something like:

EventExpecter exp1 = expectGeckoEvent(event)
exp1.blockForEvent()
...
EventExpecter exp2 = expectGeckoEvent(event)
exp2.blockForEvent()

rather than:

EventExpecter exp1 = expectGeckoEvent(event)
exp1.blockForEvent()
exp2.blockForEvent()

If you "re-use" an EventExpecter in this way, the second blockForEvent() will return immediately, because the mEventReceived flag is still set from when the first event was received and unblocked the blockForEvent.

The distribution tests introduced:
            while (!requestId.equals("testDistribution")) {
                data = new JSONObject(eventExpecter.blockForEventData());
                requestId = data.getString("requestId");
            }
which works, but in a busy wait. The first event received unblocks the Expecter and sets the flag; if it does not have the correct requestId, the next blockForEventData call returns immediately...and keeps doing so until the correct requestId is received.

While looking into this, I found another place where an EventExpecter was accidentally re-used, resulting in a no-op (see testAddonManager).

Rather than changing the tests, this patch changes the EventExpecter to allow re-use, by clearing the mEventReceived flag when an expecter returns successfully from a block call. I am hoping this is more intuitive and less error prone than the existing approach, but I'm open to suggestions...

Passes try: https://tbpl.mozilla.org/?tree=Try&rev=a2d11805ea18

Comment 3

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 720748 [details] [diff] [review]
clear mEventReceived once event expecter unblocks

Review of attachment 720748 [details] [diff] [review]:
-----------------------------------------------------------------

Good find, but the patch as is means that eventReceived() will start returning false after a call to blockUntilClear(). eventReceived() is only used in one test and it isn't affected by this, but I'd still like to make sure that method doesn't break its contract. Add a new member variable that's returned from eventReceived() that is set to true at the same time as mEventReceived but never gets set back to false.

Comment 4

[Geoff Brown [:gbrown]]

Attachment: clear mEventReceived once event expecter unblocks - updated for review comments

Revised accordingly. Thanks.

Comment 5

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 721109 [details] [diff] [review]
clear mEventReceived once event expecter unblocks - updated for review comments

Review of attachment 721109 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good, thanks!

Comment 6

[Geoff Brown [:gbrown]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/94e0b7a6523d

Comment 7

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/94e0b7a6523d