Closed Bug 1527959 Opened 5 years ago Closed 1 year ago

Don't speculatively update screen orientation when Gecko requests orientation changes

Categories

(GeckoView :: General, defect, P5)

Product:
GeckoView
Component:
General
Platform:
x86_64
Android
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression)

The interesting bits here are coming from the adb log:

02-14 17:15:00.080 2390 2407 I Gecko : 1550164500080 Marionette DEBUG 741 -> [0,5,"Marionette:SetScreenOrientation",{"orientation":"lAnDsCaPe"}]
02-14 17:15:00.080 2390 2407 D GeckoScreenOrientation: locking to LANDSCAPE
02-14 17:15:00.090 2390 2390 I Choreographer: Skipped 38 frames! The application may be doing too much work on its main thread.
02-14 17:15:00.090 1410 1669 D EGL_emulation: eglMakeCurrent: 0x762ebe103e80: ver 2 0 (tinfo 0x762ebe11a2e0)
02-14 17:15:00.090 2390 2423 D EGL_emulation: eglMakeCurrent: 0x762ebe36c720: ver 2 0 (tinfo 0x762ebe360880)
02-14 17:15:00.090 2390 2390 D GeckoApplication: onConfigurationChanged: en_US, background: false
02-14 17:15:00.090 2390 2390 D GeckoLocales: No selected locale. No correction needed.
02-14 17:15:00.090 2390 2390 D GeckoApp: onConfigurationChanged: en_US
02-14 17:15:00.120 1410 1669 D EGL_emulation: eglMakeCurrent: 0x762ebe103e80: ver 2 0 (tinfo 0x762ebe11a2e0)
02-14 17:15:00.180 1318 1697 I ActivityManager: Config changes=480 {1.0 310mcc260mnc [en_US] ldltr sw400dp w640dp h376dp 320dpi nrml land finger qwerty/v/v dpad/v s.11}
02-14 17:15:00.280 1318 1362 I InputReader: Reconfiguring input devices. changes=0x00000004
02-14 17:15:00.280 1318 1362 I InputReader: Device reconfigured: id=0, name='qwerty2', size 800x1280, orientation 1, mode 1, display id 0
02-14 17:15:00.300 1318 1362 I InputReader: Reconfiguring input devices. changes=0x00000004
02-14 17:15:00.300 2390 2407 D GeckoScreenOrientation: updating to new orientation LANDSCAPE
02-14 17:15:00.300 2390 2407 I Gecko : 1550164500300 Marionette DEBUG 741 <- [1,5,null,{"value":null}]
02-14 17:15:00.300 2390 2390 D GeckoScreenOrientation: updating to new orientation PORTRAIT_PRIMARY
02-14 17:15:00.340 2390 2407 I Gecko : 1550164500340 Marionette DEBUG 741 -> [0,6,"Marionette:GetScreenOrientation",{}]
02-14 17:15:00.340 2390 2407 I Gecko : 1550164500340 Marionette DEBUG 741 <- [1,6,null,{"value":"portrait-primary"}]

The orientation first gets locked correctly to landscape, but then out of a sudden it gets updated to PORTRAIT_PRIMARY. I wonder if Android somehow restricts that mode and reverts back?

I can actually reproduce it locally but only when the display of the Android emulator is going to turn off. At this point those failures appear.

Geoff, I assume we have to make sure that the display will never turn off. Maybe it's a system setting which we haven't set yet, or will it have to be set manually which I find shouldn't be done.

Flags: needinfo?(gbrown)

How are you running the android emulator? If you run 'mach android-emulator --force-update --version x86-7.0' that should give the same android image as in continuous integration. When I do that, the screen stays on (I waited 20 minutes, no keyboard or mouse movement). It should stay on indefinitely because the setting Developer Options > Stay Awake is On.

Flags: needinfo?(gbrown)

I was using it without --force-update. I don't think that I have to update it all the time, and that shouldn't make a difference, right?

So actually my problem was most likely that earlier today I changed the battery from charging to discharging. And as such the screen turned off because it wasn't charging, which is required for this developer setting.

But anyway even after restarting the emulator with your command the screen still turns off after 1min, which is the default sleep time inside the display settings.

--force-update shouldn't make a difference unless you have previously changed the state of the OS -- updated system settings or whatever. In continuous integration, each task starts with a "clean" android image -- as though --force-update was used.

If the battery was not charging, I would expect the screen to turn off after 1 min. How do you change the battery to discharging?

But anyway even after restarting the emulator with your command the screen still turns off after 1min, which is the default sleep time inside the display settings.

I cannot explain that.

I'll try to get some screenshots from try...

Let's look at more examples:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=228757835&repo=try&lineNumber=2738

02-15 23:36:03.830 2396 2414 I Gecko : 1550273763830 Marionette DEBUG 676 -> [0,5,"Marionette:SetScreenOrientation",{"orientation":"lAnDsCaPe"}]
02-15 23:36:03.830 2396 2414 D GeckoScreenOrientation: locking to LANDSCAPE
02-15 23:36:03.910 2396 2429 D EGL_emulation: eglMakeCurrent: 0x7d8095f55c00: ver 2 0 (tinfo 0x7d80a40bca60)
02-15 23:36:03.930 1335 1348 I ActivityManager: Config changes=480 {1.0 310mcc260mnc [en_US] ldltr sw400dp w640dp h376dp 320dpi nrml land finger qwerty/v/v dpad/v s.11}
02-15 23:36:03.930 2396 2396 I Choreographer: Skipped 43 frames! The application may be doing too much work on its main thread.
02-15 23:36:03.930 2396 2429 D EGL_emulation: eglMakeCurrent: 0x7d8095f55c00: ver 2 0 (tinfo 0x7d80a40bca60)
02-15 23:36:03.930 2396 2396 D GeckoApplication: onConfigurationChanged: en_US, background: false
02-15 23:36:03.930 2396 2396 D GeckoLocales: No selected locale. No correction needed.
02-15 23:36:03.930 2396 2396 D GeckoApp: onConfigurationChanged: en_US
02-15 23:36:04.070 1335 1351 W art : Long monitor contention with owner Binder:1335_1 (1348) at void com.android.server.am.ActivityManagerService.setRequestedOrientation(android.os.IBinder, int)(ActivityManagerService.java:4750) waiters=0 in void com.android.server.am.ActivityStackSupervisor.handleDisplayChanged(int) for 160ms
02-15 23:36:04.070 1335 1381 I InputReader: Reconfiguring input devices. changes=0x00000004
02-15 23:36:04.070 1335 1381 I InputReader: Device reconfigured: id=0, name='qwerty2', size 800x1280, orientation 1, mode 1, display id 0
02-15 23:36:04.070 1335 1616 W art : Long monitor contention with owner Binder:1335_1 (1348) at void com.android.server.am.ActivityManagerService.setRequestedOrientation(android.os.IBinder, int)(ActivityManagerService.java:4750) waiters=1 in int com.android.server.am.ActivityManagerService.getActivityStackId(android.os.IBinder) for 140ms
02-15 23:36:04.070 2396 2414 D GeckoScreenOrientation: updating to new orientation LANDSCAPE
02-15 23:36:04.070 2396 2396 D GeckoScreenOrientation: updating to new orientation PORTRAIT_PRIMARY
02-15 23:36:04.070 2396 2414 I Gecko : 1550273764070 Marionette DEBUG 676 <- [1,5,null,{"value":null}]
02-15 23:36:04.130 2396 2414 I Gecko : 1550273764130 Marionette DEBUG 676 -> [0,6,"Marionette:GetScreenOrientation",{}]
02-15 23:36:04.130 2396 2414 I Gecko : 1550273764130 Marionette DEBUG 676 <- [1,6,null,{"value":"portrait-primary"}]

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=228754996&repo=try&lineNumber=2749

02-15 23:02:03.980 2385 2403 I Gecko : 1550271723980 Marionette DEBUG 676 -> [0,5,"Marionette:SetScreenOrientation",{"orientation":"lAnDsCaPe"}]
02-15 23:02:03.980 2385 2403 D GeckoScreenOrientation: locking to LANDSCAPE
02-15 23:02:04.040 1313 1800 I ActivityManager: Config changes=480 {1.0 310mcc260mnc [en_US] ldltr sw400dp w640dp h376dp 320dpi nrml land finger qwerty/v/v dpad/v s.11}
02-15 23:02:04.050 2385 2385 I Choreographer: Skipped 46 frames! The application may be doing too much work on its main thread.
02-15 23:02:04.050 2385 2418 D EGL_emulation: eglMakeCurrent: 0x704e7416a7a0: ver 2 0 (tinfo 0x704e740ea8a0)
02-15 23:02:04.050 1313 1356 I InputReader: Reconfiguring input devices. changes=0x00000004
02-15 23:02:04.050 1313 1356 I InputReader: Device reconfigured: id=0, name='qwerty2', size 800x1280, orientation 1, mode 1, display id 0
02-15 23:02:04.050 1313 1356 I InputReader: Reconfiguring input devices. changes=0x00000004
02-15 23:02:04.060 2385 2385 D GeckoApplication: onConfigurationChanged: en_US, background: false
02-15 23:02:04.060 2385 2385 D GeckoLocales: No selected locale. No correction needed.
02-15 23:02:04.060 2385 2385 D GeckoApp: onConfigurationChanged: en_US
02-15 23:02:04.170 1313 1761 W art : Long monitor contention with owner Binder:1313_8 (1800) at void com.android.server.am.ActivityManagerService.setRequestedOrientation(android.os.IBinder, int)(ActivityManagerService.java:4750) waiters=1 in android.content.pm.UserInfo com.android.server.am.UserController.getCurrentUser() for 150ms
02-15 23:02:04.170 2385 2403 D GeckoScreenOrientation: updating to new orientation LANDSCAPE
02-15 23:02:04.170 2385 2403 I Gecko : 1550271724170 Marionette DEBUG 676 <- [1,5,null,{"value":null}]
02-15 23:02:04.180 2385 2385 D GeckoScreenOrientation: updating to new orientation PORTRAIT_PRIMARY
02-15 23:02:04.200 2385 2403 I Gecko : 1550271724200 Marionette DEBUG 676 -> [0,6,"Marionette:GetScreenOrientation",{}]
02-15 23:02:04.210 2385 2403 I Gecko : 1550271724210 Marionette DEBUG 676 <- [1,6,null,{"value":"portrait-primary"}]

:JanH - hg logs suggest you are familiar with GeckoScreenOrientation. Can you tell what's happening here (logs in comment 7 and 8)? Where does the portrait-primary come from?

(This test usually runs fine on Android 4.3 emulator; when we try to run on Android 7.0 x86_64 emulator, it fails like this intermittently.)

Flags: needinfo?(jh+bugzilla)
OS: Unspecified → Android
Hardware: Unspecified → x86_64

No immediate idea - I'd need to dig out my debug logging from then and maybe expand it a little in order to have a clue on what could be going on there.

I added some debug logging here:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3f53a0d43685240dcef95412373e4b47f4fbfa7

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=229667620&repo=try&lineNumber=2832

https://taskcluster-artifacts.net/Vqt7yl47QrCyG1dfR-kelw/0/public/test_info//logcat-emulator-5554.log

02-21 16:21:04.250 2395 2417 D GeckoScreenOrientation: request for new orientation LANDSCAPE
02-21 16:21:04.250 2395 2417 D GeckoScreenOrientation: updating to new orientation LANDSCAPE
02-21 16:21:04.250 2395 2417 D GeckoScreenOrientation: update complete for LANDSCAPE_PRIMARY
02-21 16:21:04.250 2395 2417 I Gecko : 1550766064250 Marionette DEBUG 741 <- [1,5,null,{"value":null}]
02-21 16:21:04.260 2395 2395 D GeckoScreenOrientation: request for new orientation PORTRAIT_PRIMARY
02-21 16:21:04.260 2395 2395 D GeckoScreenOrientation: updating to new orientation PORTRAIT_PRIMARY
02-21 16:21:04.260 2395 2395 W System.err: java.lang.Exception
02-21 16:21:04.260 2395 2395 W System.err: at org.mozilla.gecko.GeckoScreenOrientation.update(GeckoScreenOrientation.java:166)
02-21 16:21:04.260 2395 2395 W System.err: at org.mozilla.gecko.GeckoScreenOrientation.update(GeckoScreenOrientation.java:143)
02-21 16:21:04.260 2395 2395 W System.err: at org.mozilla.geckoview.GeckoRuntime.orientationChanged(GeckoRuntime.java:399)
02-21 16:21:04.260 2395 2395 W System.err: at org.mozilla.geckoview.GeckoView.onConfigurationChanged(GeckoView.java:450)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.View.dispatchConfigurationChanged(View.java:10418)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1311)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewGroup.dispatchConfigurationChanged(ViewGroup.java:1315)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewRootImpl.updateConfiguration(ViewRootImpl.java:3337)
02-21 16:21:04.260 2395 2395 W System.err: at android.view.ViewRootImpl$ViewRootHandler.handleMessage(ViewRootImpl.java:3494)
02-21 16:21:04.260 2395 2395 W System.err: at android.os.Handler.dispatchMessage(Handler.java:102)
02-21 16:21:04.260 2395 2395 W System.err: at android.os.Looper.loop(Looper.java:154)
02-21 16:21:04.260 2395 2395 W System.err: at android.app.ActivityThread.main(ActivityThread.java:6077)
02-21 16:21:04.260 2395 2395 W System.err: at java.lang.reflect.Method.invoke(Native Method)
02-21 16:21:04.260 2395 2395 W System.err: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
02-21 16:21:04.260 2395 2395 W System.err: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
02-21 16:21:04.280 2395 2395 D GeckoScreenOrientation: update complete for PORTRAIT_PRIMARY

Okay, I see what is going on now:

The orientation locking API in Gecko apparently traditionally expects that as soon as the orientation locking call returns, the new orientation is returned when querying it (at least some/this? Marionette test(s) expect this - I ran into that during bug 1476106).
For the Android app the new orientation doesn't really take effect though, until after Android actually processes the change and sends out a configurationChanged message.

What happens now is that on the new emulator for some reason the Android configuration change sometimes takes longer to reach the app, by which time the test has already started requesting the next orientation change.
So the call to lock the orientation to landscape also sets the new screen orientation, but during that time the previous configuration change to portrait mode arrives, and, once the synchronization block (see https://hg.mozilla.org/integration/autoland/rev/e936ef6b4b50 for my reason behind that) becomes free, immediately follows that notification and resets Gecko's screen orientation back to portrait.
Things will return back to normal once the configuration change for the change to landscape arrives (which it does a bit further down the log), but in the mean time things are in a somewhat inconsistent state.

Flags: needinfo?(jh+bugzilla)

Thanks Jan! That is helpful information, and lead me to the following conclusion:

So Marionette currently assumes that the win.screen.mozLockOrientation() is synchronous which indeed is not the case:
https://developer.mozilla.org/en-US/docs/Web/API/Screen/lockOrientation#Return_value

It means that setScreenOrientation()[1] has to wait for the onorientationchange event [2].

[1] https://searchfox.org/mozilla-central/rev/b36e97fc776635655e84f2048ff59f38fa8a4626/testing/marionette/driver.js#2995
[2] https://developer.mozilla.org/en-US/docs/Web/API/Screen/onorientationchange

It should be an easy fix.

Assignee: nobody → hskupin
Status: NEW → ASSIGNED

In that case I think the logic in GeckoScreenOrientation needs changing so that the call to (un)lock doesn't update the screen orientation itself, otherwise you could run into the same problem, like

  1. lock() call succeeds, updates itself the screen orientation in Gecko, which fires the orientationchange event and unblocks Marionette.
  2. Marionette proceeds and calls lock() again with the next orientation.
  3. Eventually we receive Android's configuration change message for the lock() call at 1.) and we're back at comment #13.

I.e. in that case I think we should only ever update the screen orientation in response to Android telling us about it, although that introduces a different problem: AFAIK onConfigurationChange isn't fired for 180°-rotations, so we never learn about those. The current logic means that if a lock call results in a 180° flip, at least the lock call itself updates the screen orientation to the correct new value.

Jan, so you are saying a change in Gecko is needed too? If yes, can you please file a new bug in the appropriate component and mark it blocking this one?

Flags: needinfo?(jh+bugzilla)

blocking this one

Although I think in practice this needs to work the other way around: While the Marionette test change by itself (wait for event before querying new orientation) won't solve this intermittent issue, the GeckoView changes proposed above cannot be made until the tests start waiting for the orientation change event instead of assuming that locking the orientation speculatively updates the current orientation.

Depends on: 1529938

I think you should go ahead with making the initial test change in bug 1529938 (and assuming it doesn't make the current intermittents noticeable worse, already land it), and when that is in place, I can try fiddling with the GeckoView screen orientation logic.

Assignee: hskupin → jh+bugzilla
Status: ASSIGNED → NEW
Component: Marionette → General
Flags: needinfo?(jh+bugzilla)
Product: Testing → GeckoView
Version: Version 3 → Trunk

Jan, mind updating the bugs summary to it reflects the changes you are planning to do? Thanks.

Flags: needinfo?(jh+bugzilla)
Flags: needinfo?(jh+bugzilla)
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_screen_orientation.py TestScreenOrientation.test_set_orientation_with_mixed_casing | AssertionError: u'portrait-primary' != 'landscape-primary' → Don't speculatively update screen orientation when Gecko requests orientation changes

Supposedly a DisplayListener would be the way forward and catch 180° rotations, too.
The only drawback is that this solution only works from API17 onwards, so for API16 we still need to rely on the current logic.

(In reply to Jan Henning [:JanH] from comment #21)

Supposedly a DisplayListener would be the way forward and catch 180° rotations, too.
The only drawback is that this solution only works from API17 onwards, so for API16 we still need to rely on the current logic.

Unfortunately there's another problem: It seems that when onDisplayChanged() fires, the Configuration has not yet been updated to account for the new orientation [1], so we cannot simply retrieve the current orientation from the Configuration for updating our screen orientation.
So instead we should simply get the rotation from the display, except that that reports its orientation in terms of the various Surface.ROTATION_xy constants, which don't necessarily have a guaranteed mapping to ORIENTATION_LANDSCAPE/ORIENTATION_LANDSCAPE from the Configuration. On a normal phone Surface.ROTATION_0 will almost certainly correspond to ORIENTATION_PORTRAIT, but that might not be true for entirely all devices.

I suppose we can deduce a mapping between Surface.ROTATION_xy and ORIENTATION_LANDSCAPE/ORIENTATION_LANDSCAPE by just getting the actual display resolution once and comparing it with the current rotation, so the above shouldn't be a fundamental problem, although of course it doesn't make the code any nicer.

[1] Which in a way seems logical - rotation first adjusts the display size, and then eventually in response to that the activity updates its configuration, too.

Assignee: jh+bugzilla → nobody
Severity: normal → S3

My understand is that this is already fixed. Feel free to reopen this if you can reproduce this.

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.