Open Bug 2018901 Opened 4 months ago Updated 26 days ago

Closing a tab from within a JavaScript "keydown" event handler can be delayed by more than 500 ms

Categories

(GeckoView :: General, defect)

All
Android
defect

Tracking

(Not tracked)

People

(Reporter: whimboo, Unassigned, NeedInfo)

References

(Blocks 1 open bug)

Details

Attachments

(3 files)

In bug 2012793, we observed an issue with the testrunner package when a WebDriver test synthesizes a keydown event on a link that closes the current browsing context. In most cases, there is a delay of more than 500 ms before the browsing context (tab) actually closes. It’s currently unclear what causes this delay. For details, see bug 2012793, comment 17.

As given by Olivia it might be similar to what has been seen on bug 2011351 before.

Note that the test failure cannot be seen when we do full test jobs for Wdspec around each 20 pushes or so, but it can be reproduced all the time when just running the single test.

To see the failure, run the following steps:

  1. Update https://searchfox.org/firefox-main/source/testing/web-platform/meta/webdriver/tests/bidi/input/perform_actions/key.py.ini#5 and remove the entry for Android
  2. Update https://searchfox.org/firefox-main/source/testing/web-platform/tests/webdriver/tests/bidi/input/perform_actions/key.py#24 and remove all other test methods (or rename test_ to tst_ to not run them)
  3. Run mach wpt --no-install --setpref="remote.log.level=Trace" --webdriver-arg=-vv testing/web-platform/tests/webdriver/tests/bidi/input/perform_actions/key.py

Ted, is there anything that we could help to get this investigated? Some more specific logs which are not included yet? Or a recorded Gecko profile if helpful?

Flags: needinfo?(tcampbell)

Unfortunately, I could not reproduce the intermittent failure locally or over the CI. I followed the steps in the Description of this ticket, but it did not help me reproduce it.
I also pushed up a couple of trys tring to run the test, but did not have any luck to actually be able to trigger it. Here're the try runs I pushed:
https://treeherder.mozilla.org/jobs?repo=try&revision=0a28fc1dcffbb7e43d93b33b56ee3d56900355eb
https://treeherder.mozilla.org/jobs?repo=try&revision=5edaaf7aafe1c77a36b28d76cabec9b97add8ee4
https://treeherder.mozilla.org/jobs?repo=try&revision=2213df35840ff3b2272e8791f98e6d83b2f02725
https://treeherder.mozilla.org/jobs?repo=try&revision=6e594efbfb269e0c5877b9d23e901d4926b45894

Here's the mach command I used:
./mach try fuzzy testing/web-platform/tests/webdriver/tests/bidi/input/perform_actions

The strange thing is that none of these jobs on try actually run the wanted tests from the given test path. All the other BiDi tests were running but not the tests within input/perform_actions as if they would have been excluded.

Florian, not sure if any change landed recently which could have affected mach try fuzzy and the test selection logic?

Flags: needinfo?(tcampbell) → needinfo?(florian)

I pushed a new try build as well with the meta data file removed and only running tests in testing/web-platform/tests/webdriver/tests/bidi/input/perform_actions/:

https://treeherder.mozilla.org/jobs?repo=try&landoInstance=lando-prod-2025&landoCommitID=38067

Kaya, it works just fine for me and the error is still there an causing nearly permanent failures:

https://treeherder.mozilla.org/jobs?repo=try&revision=7e6f98684d7f996fca963714365ea231102f3a4b&selectedTaskRun=SsHkpn1NTK-knG31txVo_Q.0

I assume that you pushed something wrongly to try?

Flags: needinfo?(florian) → needinfo?(kkaya)

Hi Kaya, do you have an update? Thanks.

I was able to reproduce this locally on an aarch64 Android emulator, running the single test_key_down_closes_browsing_context against test_runner. The test does not fail at idle, but reproduces fairly reliably (around 15/30 = 50% failure rate over n=30) once I put both the host and the emulator under CPU load. That at least gave me a local repro to iterate on without needing CI churn. The bug is real and matches the original failure mode (Failed: DID NOT RAISE NoSuchFrameException). I haven't pinned down the root cause yet, but I wanted to share what I've ruled out and where the data is currently pointing — happy to hear your thoughts on any of this.

Things I tried that did NOT meaningfully change the failure rate or the timing distribution:

  1. The bug 2011351 — setting dom.input_events.security.minNumTicks=0 and dom.input_events.security.minTimeElapsedInMS=0 for the test. Over n=30 baseline vs n=30 with the prefs, failure rate was very similar, and the KeyDownclose-cleanup timing distribution was effectively identical (median ~600ms passing / ~1000ms failing in both conditions). That suggests the UserInputEventsAllowed gate is probably not the dominant factor here, though a second opinion might be good before discarding this lead entirely.
  2. Removing the aEvent.preventDefault() in the DOMWindowClose handler at GeckoViewContent.sys.mjs. The hypothesis I had was that the Java round-trip (DOMWindowCloseeventDispatcher.sendRequest("GeckoView:DOMWindowClose")GeckoSession.onCloseRequest → app's closeSessionsession.close() JNI back into Gecko) was the dominant delay source under load. If that were true, letting Gecko's nsGlobalWindowOuter::FinalClose() run synchronously without the round-trip should have dramatically reduced the discard latency. It didn't — over n=10 with the patch under the same load, the failure rate and the timing distribution were indistinguishable from baseline. So the Java callback round-trip on its own doesn't appear to be the dominant bottleneck either, at least on this setup.

Looking at what's left in the parent-process close pipeline:

FinalClose()
  → BrowsingContext::SetClosed(true)        // synchronous, immediate
  → nsCloseEvent::PostCloseEvent()          // event-loop hop
    → (later)
      → ReallyCloseWindow()
        → treeOwnerAsWin->Destroy()
          → BrowsingContext::Discard()
            → "browsing-context-discarded" observer
              → BiDi tree updates

The dominant delay seems to be somewhere between FinalClose() posting nsCloseEvent and the browsing-context-discarded observer firing, i.e. event-loop scheduling under CPU pressure in the parent. That would also explain why neither the input-events gate nor the Java round-trip on its own moves the needle — both are upstream of this hop. This is still a hypothesis though — capturing a Gecko profiler trace of a failing run (e.g. with ipcmessages,stackwalk,js) would likely confirm or refute it. (I plan to do it once I have some cycles to take a look more into this - if necessary.)

Also, one thing worth flagging: nsGlobalWindowOuter::FinalClose() does call BrowsingContext::SetClosed(true) synchronously, before the event-loop hop. If that turns out to be the right signal and we confirmed it's safe, it might be possible for BiDi to treat it as "context is getting discarded" for validation purposes, without waiting for the full Discard() to fire. Just flagging it as a possible direction, not a recommendation yet.

Flags: needinfo?(kkaya)

Thank you for the update, Kaya. It’s appreciated. As discussed on Slack, this is most likely a timing issue that primarily affects automation scenarios with enforced timing. Regular users may not notice it, although it could feel slightly laggy; in any case, clicking a link that closes the current window or tab is probably a relatively rare scenario.

Nevertheless, having a Gecko profile would be very helpful. It would allow others to assist with the investigation if needed, without first having to figure out how to reproduce the issue locally.

For now, we may have to keep the test marked as PASS/FAIL.

Attached video 1.mp4

normal cpu load - single tab

Attached video 2.mp4

normal cpu load - 2 tabs

Attached video 3.mp4

cpu pressure on host&emulator - 2 tabs

Agreed, I will soon provide a profile and its reading as a comment here. For now, here's some other findings regarding the state of Fenix on this issue:

The codepath is structurally identical between the test runner and Fenix, but I don't think this is something user-visible on Fenix. This seems to me more of a webdriver BiDi issue than a Fenix issue (i.e. I assume that  a real keystroke doesn't come bundled with an automated follow-up action asserting the context is already gone within ~500 ms — only BiDi's test pipeline does that, which is why only BiDi sees the race.).

I wrote this test local site to check this behaviour on Fenix end:

<!doctype html>
<meta name="viewport" content="width=device-width">
<style>
  body { font: 24px sans-serif; margin: 2em; }
  input { font: 24px sans-serif; padding: .6em; width: 100%; box-sizing: border-box; }
  p { color: #555; }
</style>
<p>Press any key on the input. Tab should close.</p>
<input onkeydown="window.close()" autofocus value="">

See the behavior in the videos 1&2. So, when there's no other tab, the ui is already buggy a bit. The tab count is updated instantly, but the page is sort of there, but the resources are already released (the background of keyboard is black). In the case when there's already other tabs (the second video), the tabs update instantly and everything works fine.

The videos 1&2 are the cases when there was the normal cpu load, I then put some pressure on the host and the emulator to test both scenarios again and see if there's any bug or not (especially in the second case when there's a tab already which is not buggy with normal cpu load).

And according to my findings when there's pressure on host and emulator cpu, the behavior is almost identical, it is just a short period of white background when the keyboard is closed when there are multiple tabs open and the test website is closed. You can see it in the video 3. Don't think this looks like a severe bug on Fenix end considering how I setup the testing environment (maybe some lower end devices will be impacted by it).

The severity field is not set for this bug.
:owlish, could you have a look please?

For more information, please visit BugBot documentation.

Flags: needinfo?(bugzeeeeee)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: