1506376 - Consider to make PCompositorBridge::DidComposite high priority message

Status: RESOLVED FIXED

(Core :: Layout, defect, P2)

Description

[Olli Pettay [:smaug][[e-mail]]]

Attachment: messageflood.html

If main thread's normal priority queue has lots of runnables to process, DidComposite doesn't get handled fast enough. And so having high priority vsync doesn't really help.

The test case posts 60 tasks which all take ~16ms to process (and then it doesn't do anything for 1 second and starts again). If refresh driver handling had higher priority, we'd see more than just one or two paints during the test time.

Patch coming, but need to see what tryserver says.

Comment 1

[Olli Pettay [:smaug][[e-mail]]]

Attachment: high_prio_DidComposite.diff

In general we really shouldn't use high prio queue for other than vsync, but DidComposite is kind of part of that.


remote: View your change here:
remote:   https://hg.mozilla.org/try/rev/260846f072852734e2d628747cdaf07a78fe98c2
remote: 
remote: Follow the progress of your build on Treeherder:
remote:   https://treeherder.mozilla.org/#/jobs?repo=try&revision=260846f072852734e2d628747cdaf07a78fe98c2
remote: 
remote: It looks like this try push has talos jobs. Compare performance against a baseline revision:
remote:   https://treeherder.mozilla.org/perf.html#/comparechooser?newProject=try&newRevision=260846f072852734e2d628747cdaf07a78fe98c2
remote: recorded changegroup in replication log in 0.027s

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 9024198 [details] [diff] [review]
high_prio_DidComposite.diff

Looks like we have broken code around this stuff :/

Comment 3

[Olli Pettay [:smaug][[e-mail]]]

Without the patch we skip paints quite often when typing to large Google Doc. With the patch basically never, and at least to me the behavior feels better.
So need to figure out the test breakage.

Comment 4

[Hiroyuki Ikezoe (:hiro)]

This would be a candidate of qf:responsiveness as per comment 3.

Comment 5

[Olli Pettay [:smaug][[e-mail]]]

Attachment: high_prio_composite.diff

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

tests + talos
https://treeherder.mozilla.org/#/jobs?repo=try&revision=1ea85727243bd583ab1c23f120a446ae9b2a6c6f
raptor
https://treeherder.mozilla.org/#/jobs?repo=try&revision=2fab440b2f0153fc30e30e7383071c91a7a873e5

Comment 7

[Olli Pettay [:smaug][[e-mail]]]

Attachment: high_prio_DidComposite_with_shutdown_changes.diff

tests: https://treeherder.mozilla.org/#/jobs?repo=try&revision=7f78f8cf61dfb6fc2bc22986a68da0c3ce9b21b8
raptor: https://treeherder.mozilla.org/#/jobs?repo=try&revision=5c1a210a4914f300bdfd8ea3f087518151dbe9ab

Comment 8

[Olli Pettay [:smaug][[e-mail]]]

(at least locally I didn't see the assertion)

Comment 9

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 9042258 [details] [diff] [review]
high_prio_DidComposite_with_shutdown_changes.diff

ok, this seems to be shutting down as expected. And the testcase starts to paint smoothly.

PrepareFinalDestroy is perhaps a bit odd name, but then is also AfterDestroy :)

We need the extra runnable because high priority tasks aren't always processed before normal priority runnable (the reason is to avoid starving normal priority queue)

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/cab981ef743b
Make PCompositorBridge::DidComposite high priority message, r=aosmond

Comment 11

[Noemi Erli[:noemi_erli]]

Backed out changeset cab981ef743b (Bug 1506376) for failures in browser_appmenu.js

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&selectedJob=227183203&searchStr=os%2Cx%2C10.10%2Copt%2Cmochitests%2Cwith%2Ce10s%2Ctest-macosx64%2Fopt-mochitest-browser-chrome-e10s-2%2Cm-e10s%28bc2%29&revision=cab981ef743b8e637d7d1bfcab49df0d4caaf3fb

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=227183203&repo=mozilla-inbound&lineNumber=1091

Backout: https://hg.mozilla.org/integration/mozilla-inbound/rev/0669f92557f313142e5b53e42f6f91633bdc1be4

Comment 12

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/4e1b5ab8c44d
Backed out changeset cab981ef743b for failures in browser_appmenu.js

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

Ahaa, the failure is basically bug 1489259.

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b0f67b8917f4
Make PCompositorBridge::DidComposite high priority message, r=aosmond

Comment 15

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5244b5aba6e3
Backed out changeset b0f67b8917f4 for bc failures at browser_appmenu.js. CLOSED TREE

Comment 16

[Olli Pettay [:smaug][[e-mail]]]

Attachment: reflows_in_browser_appmenu.js.diff

17 seems to have been the magic number.

Comment 17

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 9043383 [details] [diff] [review]
reflows_in_browser_appmenu.js.diff

Wrong bug

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/de5c7c2699c4
Make PCompositorBridge::DidComposite high priority message, r=aosmond

Comment 19

[Razvan Maries]

https://hg.mozilla.org/mozilla-central/rev/de5c7c2699c4

Comment 20

[Olli Pettay [:smaug][[e-mail]]]

Looks like we have too many broken tests to get this landed.

Comment 21

[Noemi Erli[:noemi_erli]]

Backed out changeset de5c7c2699c4 (Bug 1506376) for causing several devtools failures a=backout

Pushes with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&searchStr=windows%2C10%2Cx64%2Cdebug%2Cmochitests%2Cwith%2Ce10s%2Ctest-windows10-64%2Fdebug-mochitest-devtools-chrome-e10s-4%2Cm-e10s%28dt4%29&group_state=expanded&fromchange=c7fdf51b2b749cfde9df6742277c9fd2f7500a49&tochange=9f93017d5be057df482f938b4cff7872208214f1&selectedJob=228106474

Log failure examples:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=228117733&repo=mozilla-inbound&lineNumber=67139
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=228115216&repo=mozilla-inbound&lineNumber=4858
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=228106474&repo=mozilla-inbound&lineNumber=81164

Backout: https://hg.mozilla.org/mozilla-central/rev/0a9a4f8d79e97d6de743d4a95c915388906dde3b

Comment 22

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/de5c7c2699c4

Comment 23

[Olli Pettay [:smaug][[e-mail]]]

just for some testing:

remote: Follow the progress of your build on Treeherder:
remote: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b3441ff42e8a8871b1e56c6885c8a6fd49b84160
remote: recorded changegroup in replication log in 0.043s

Comment 24

[Olli Pettay [:smaug][[e-mail]]]

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

Comment 25

[Olli Pettay [:smaug][[e-mail]]]

Attachment: Bug 1506376, make DidComposite to use mediumhigh priority message

Comment 26

[Olli Pettay [:smaug][[e-mail]]]

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

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e9ec1b50f99a
make DidComposite to use mediumhigh priority message r=mattwoodrow

Comment 28

[Oana Pop-Rus]

Backed out changeset e9ec1b50f99a (bug 1506376) for devtools multiple failures in browser_animation_keyframes-graph_special-colors.js

Push that started the failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=pending%2Crunning%2Csuccess%2Csuperseded%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&searchStr=linux%2C18.04%2Cx64%2Casan%2Copt%2Cmochitests%2Ctest-linux1804-64-asan%2Fopt-mochitest-devtools-chrome-e10s-4%2Cm%28dt4%29&fromchange=9a223d507c94368a274b05f2f7bfd534b3f79e23&selectedJob=287396948

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=287396948&repo=autoland&lineNumber=2568
and https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=287381502&repo=autoland&lineNumber=2404

Backout: https://hg.mozilla.org/integration/autoland/rev/c32017c40f1904b0614607fbe3ec6cceffa91ce4

Comment 29

[Olli Pettay [:smaug][[e-mail]]]

/me kicks devtools tests

Comment 30

[Hiroyuki Ikezoe (:hiro)]

Hey, Daisuke, any insights on the devtools animation failures?

IIUC what the patch here does is to deliver each MozAfterPaint event more responsive. In other words, to deliver it (and do relevant stuff), JS scripts might not run responsive as before. If the failure happens on only ASAN build, skipping these tests there is an option I guess.

Comment 31

[Daisuke Akatsuka (:daisuke)]

Hi Hiro!
It seems that the following function might be affected by this patch at least.
https://searchfox.org/mozilla-central/source/devtools/server/actors/animation.js#847-868
However, as I have not confirmed on this patch and there are other possibilities, need to investigate, anyway.
So, as you said, if the failure will occur on ASAN only, I agree to skip the tests.
(After that, I think I can investigate the issue.)

Comment 32

[Olli Pettay [:smaug][[e-mail]]]

Attachment: Bug 1506376, remove useless private: from VsyncEvent struct

Depends on D61083

Comment 33

[Olli Pettay [:smaug][[e-mail]]]

Attachment: Bug 1506376, make parent process vsync handling to be blocked the same way as in child process

Because the code becomes more generic, the following renames are done:
mLastChildTick is renamed to mLastTick
mLastProcessedTickInChildProcess is renamed to mLastProcessedTickInChildProcess

To clarify which member variables are used in parent process only
mRefreshTickLock is renamed to mParentProcessRefreshTickLock and
new variables mRecentParentProcessVsync and mPendingParentProcessVsync are
added. (mRecentVsync and mRecentVsyncId don't anymore have the different
behavior in parent and child processes)

The basic idea is to keep the vsync compression in parent process in
NotifyVsync.
(In child processes it is handled by IPDL/IPC compression).
The main functionality change is in ParentProcessVsyncNotifier::Run.
That method doesn't anymore call mObserver->TickRefreshDriver(...)
but mObserver->NotifyParentProcessVsync(...), which then calls
NotifyVsync(...) on the main thread. That way parent process gets the
same vsync block-until behavior as what child process has.

Depends on D62032

Comment 34

[Olli Pettay [:smaug][[e-mail]]]

Trying something here...
https://treeherder.mozilla.org/#/jobs?repo=try&revision=2492088f13efdd2b7185813c8aaeb6e3e6e68eff
https://treeherder.mozilla.org/#/jobs?repo=try&revision=7b4c6da149c03f830f6aa2cf9b06866e2936ee2d

Comment 35

[Olli Pettay [:smaug][[e-mail]]]

Crossing fingers. Try push looked good, but this kind of changes do easily reveal other issues.

Comment 36

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/adbd602610a3
make DidComposite to use mediumhigh priority message r=mattwoodrow
https://hg.mozilla.org/integration/autoland/rev/621ec02db41c
remove useless private: from VsyncEvent struct r=mattwoodrow
https://hg.mozilla.org/integration/autoland/rev/fe7215eefa28
make parent process vsync handling to be blocked the same way as in child process r=farre

Comment 37

[Bogdan Tara[:bogdan_tara | bogdant]]

Backed out 3 changesets (Bug 1506376) for xpcshell failures

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=xpcshell&fromchange=f3dd227e1a4d1243fd0e7cdf5dd0421df3b8cd85&tochange=ccf0746ed3fb43ad7cd491e6d20c37e9a1997ed0&selectedJob=288941935

Backout link: https://hg.mozilla.org/integration/autoland/rev/ccf0746ed3fb43ad7cd491e6d20c37e9a1997ed0

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288941935&repo=autoland&lineNumber=1351

[task 2020-02-14T14:57:26.200Z] 14:57:26     INFO -  TEST-START | docshell/test/unit/test_browsing_context_structured_clone.js
[task 2020-02-14T14:57:26.807Z] 14:57:26  WARNING -  TEST-UNEXPECTED-FAIL | docshell/test/unit/test_browsing_context_structured_clone.js | xpcshell return code: 139
[task 2020-02-14T14:57:26.807Z] 14:57:26     INFO -  TEST-INFO took 606ms
[task 2020-02-14T14:57:26.807Z] 14:57:26     INFO -  >>>>>>>
[task 2020-02-14T14:57:26.807Z] 14:57:26     INFO -  docshell/test/unit/test_browsing_context_structured_clone.js | xpcw: cd /sdcard/tests/xpc/docshell/test/unit
[task 2020-02-14T14:57:26.807Z] 14:57:26     INFO -  docshell/test/unit/test_browsing_context_structured_clone.js | xpcw: xpcshell -r /sdcard/tests/xpc/c/httpd.manifest --greomni /data/local/xpcb/geckoview-androidTest.apk -m -s -e const _HEAD_JS_PATH = "/sdcard/tests/xpc/head.js"; -e const _MOZINFO_JS_PATH = "/sdcard/tests/xpc/p/mozinfo.json"; -e const _PREFS_FILE = "/sdcard/tests/xpc/user.js"; -e const _TESTING_MODULES_DIR = "/sdcard/tests/xpc/m"; -f /sdcard/tests/xpc/head.js -e const _HEAD_FILES = ["/sdcard/tests/xpc/docshell/test/unit/head_docshell.js"]; -e const _JSDEBUGGER_PORT = 0; -e const _TEST_FILE = ["test_browsing_context_structured_clone.js"]; -e const _TEST_NAME = "docshell/test/unit/test_browsing_context_structured_clone.js"; -e _execute_test(); quit(0);
[task 2020-02-14T14:57:26.807Z] 14:57:26     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-02-14T14:57:26.808Z] 14:57:26     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-02-14T14:57:26.808Z] 14:57:26     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-02-14T14:57:26.808Z] 14:57:26     INFO -  running event loop
[task 2020-02-14T14:57:26.808Z] 14:57:26     INFO -  docshell/test/unit/test_browsing_context_structured_clone.js | Starting test_BrowsingContext_structured_clone
[task 2020-02-14T14:57:26.808Z] 14:57:26     INFO -  (xpcshell/head.js) | test test_BrowsingContext_structured_clone pending (2)
[task 2020-02-14T14:57:26.808Z] 14:57:26     INFO -  TEST-PASS | docshell/test/unit/test_browsing_context_structured_clone.js | test_BrowsingContext_structured_clone - [test_BrowsingContext_structured_clone : 17] Got correct browsing context from StructuredClone deserialize - {} == {}
[task 2020-02-14T14:57:26.808Z] 14:57:26     INFO -  TEST-PASS | docshell/test/unit/test_browsing_context_structured_clone.js | test_BrowsingContext_structured_clone - [test_BrowsingContext_structured_clone : 24] Got correct browsing context from second StructuredClone deserialize - {} == {}
[task 2020-02-14T14:57:26.808Z] 14:57:26     INFO -  (xpcshell/head.js) | test function () {
[task 2020-02-14T14:57:26.809Z] 14:57:26     INFO -      [native code]
[task 2020-02-14T14:57:26.809Z] 14:57:26     INFO -  } pending (3)
[task 2020-02-14T14:57:26.809Z] 14:57:26     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (3)
[task 2020-02-14T14:57:26.809Z] 14:57:26     INFO -  docshell/test/unit/test_browsing_context_structured_clone.js | Segmentation fault
[task 2020-02-14T14:57:26.809Z] 14:57:26     INFO -  <<<<<<<
[task 2020-02-14T14:57:27.116Z] 14:57:27     INFO -  mozcrash Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/O1hMrh6ZQ9KcwJJHPa5pmA/artifacts/public/build/target.crashreporter-symbols.zip
[task 2020-02-14T14:57:29.433Z] 14:57:29     INFO -  mozcrash Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk /tmp/tmpa67gfG/6f42dff2-6c21-cc3e-03f4-6f6419146141.dmp /tmp/tmpYtdZAm
[task 2020-02-14T14:57:31.529Z] 14:57:31     INFO -  mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/6f42dff2-6c21-cc3e-03f4-6f6419146141.dmp
[task 2020-02-14T14:57:31.529Z] 14:57:31     INFO -  mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/6f42dff2-6c21-cc3e-03f4-6f6419146141.extra
[task 2020-02-14T14:57:31.530Z] 14:57:31  WARNING -  PROCESS-CRASH | docshell/test/unit/test_browsing_context_structured_clone.js | application crashed [@ mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::NotifyVsync(mozilla::VsyncEvent const&)]
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -  Crash dump filename: /tmp/tmpa67gfG/6f42dff2-6c21-cc3e-03f4-6f6419146141.dmp
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -  Operating system: Android
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -                    0.0.0 Linux 3.10.0+ #260 SMP PREEMPT Fri May 19 12:48:14 PDT 2017 x86_64
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -  CPU: amd64
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -       family 6 model 6 stepping 3
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -       4 CPUs
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -  GPU: UNKNOWN
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -  Crash reason:  SIGSEGV /SEGV_MAPERR
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -  Crash address: 0x20
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -  Process uptime: not available
[task 2020-02-14T14:57:31.531Z] 14:57:31     INFO -  Thread 0 (crashed)
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   0  libxul.so!mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::NotifyVsync(mozilla::VsyncEvent const&) [nsRefreshDriver.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 0 + 0x0]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rax = 0x0000000000000000   rdx = 0x0000000000000001
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rcx = 0x000072d042df5b40   rbx = 0x000072d0365adb20
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rsi = 0x00007fff4f54fb20   rdi = 0x0000000000000010
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f54fb10   rsp = 0x00007fff4f54fad0
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -       r8 = 0x000072d042700260    r9 = 0x0000000000000000
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      r10 = 0x0000000000000000   r11 = 0x0000000000000000
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      r12 = 0x00007fff4f54fb20   r13 = 0x00000000ffffffff
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      r14 = 0x000072d0365adb20   r15 = 0x000072d03659d200
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03daabd41
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: given as instruction pointer in context
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   1  libxul.so!mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::ParentProcessVsyncNotifier::Run() [nsRefreshDriver.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 536 + 0x3a]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f54fb50   rsp = 0x00007fff4f54fb20
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03daab603
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   2  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 1220 + 0x6]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550070   rsp = 0x00007fff4f54fb60
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03b33d9c4
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   3  libxul.so!<name omitted> [nsThreadUtils.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 481 + 0xd]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f5500a0   rsp = 0x00007fff4f550080
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03b340ae8
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   4  libxul.so!nsThreadManager::SpinEventLoopUntilInternal(nsINestedEventLoopCondition*, bool) [nsThreadManager.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 694 + 0x8d]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f5500f0   rsp = 0x00007fff4f5500b0
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03b340750
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   5  libxul.so!NS_InvokeByIndex + 0x8e
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550120   rsp = 0x00007fff4f550100
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03fde3c3a
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   6  libxul.so!XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [XPCWrappedNative.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 1145 + 0xd48]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550330   rsp = 0x00007fff4f550130
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03bc22c90
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   7  libxul.so!XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [XPCWrappedNativeJSOps.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 947 + 0x8]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550450   rsp = 0x00007fff4f550340
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03bc23ba3
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   8  libxul.so!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 569 + 0x102]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550520   rsp = 0x00007fff4f550460
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03eaff0b1
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -   9  libxul.so!Interpret(JSContext*, js::RunState&) [Interpreter.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 632 + 0xc]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f5509f0   rsp = 0x00007fff4f550530
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03eaf6629
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -  10  libxul.so!js::RunScript(JSContext*, js::RunState&) [Interpreter.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 449 + 0xb]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550a50   rsp = 0x00007fff4f550a00
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03eaea912
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -  11  libxul.so!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 604 + 0x8]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550b20   rsp = 0x00007fff4f550a60
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03eaff374
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -  12  libxul.so!js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) [BaselineIC.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 2910 + 0xa]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550e60   rsp = 0x00007fff4f550b30
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03f02de53
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -  13  0x266ad4307e88
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550ed8   rsp = 0x00007fff4f550e70
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x0000266ad4307e88
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -  14  0x72d03108ce60
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550f78   rsp = 0x00007fff4f550ee8
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03108ce60
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -  15  0x266ad430548f
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f550fe0   rsp = 0x00007fff4f550f88
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x0000266ad430548f
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -  16  libxul.so!js::jit::EnterBaselineInterpreterAtBranch(JSContext*, js::InterpreterFrame*, unsigned char*) [BaselineJIT.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 187 + 0xec]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f5511d0   rsp = 0x00007fff4f550ff0
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03f0c9665
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -  17  libxul.so!Interpret(JSContext*, js::RunState&) [Interpreter.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 1935 + 0x8]
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rbp = 0x00007fff4f5516a0   rsp = 0x00007fff4f5511e0
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      rip = 0x000072d03eaeb5be
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.537Z] 14:57:31     INFO -  18  libxul.so!js::RunScript(JSContext*, js::RunState&) [Interpreter.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 449 + 0xb]
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rbp = 0x00007fff4f551700   rsp = 0x00007fff4f5516b0
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rip = 0x000072d03eaea912
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -  19  libxul.so!js::ExecuteKernel(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value const&, js::AbstractFramePtr, JS::Value*) [Interpreter.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 825 + 0x5]
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rbp = 0x00007fff4f551780   rsp = 0x00007fff4f551710
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rip = 0x000072d03eb00605
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -  20  libxul.so!js::Execute(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value*) [Interpreter.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 858 + 0x19]
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rbp = 0x00007fff4f5517d0   rsp = 0x00007fff4f551790
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rip = 0x000072d03eb00746
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -  21  libxul.so!JS::EvaluateDontInflate(JSContext*, JS::ReadOnlyCompileOptions const&, JS::SourceText<mozilla::Utf8Unit>&, JS::MutableHandle<JS::Value>) [CompilationAndEvaluation.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 600 + 0x53d]
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rbp = 0x00007fff4f551cf0   rsp = 0x00007fff4f5517e0
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rip = 0x000072d03ebe2ac5
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -  22  libxul.so!XRE_XPCShellMain(int, char**, char**, XREShellData const*) [XPCShellImpl.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 1001 + 0x1a]
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rbp = 0x00007fff4f5520f0   rsp = 0x00007fff4f551d00
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      rip = 0x000072d03bc15fcb
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.538Z] 14:57:31     INFO -  23  xpcshell!main [xpcshell.cpp:fe7215eefa2860677714422c5251c0f2f70e52de : 66 + 0xb]
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      rbp = 0x00007fff4f552130   rsp = 0x00007fff4f552100
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      rip = 0x000072d042df87d1
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -  24  libc.so + 0x1c8d5
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      rbp = 0x00007fff4f552278   rsp = 0x00007fff4f552140
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      rip = 0x000072d0391238d5
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -  25  0x7fff4f5529ec
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      rbp = 0x00007fff4f5529d0   rsp = 0x00007fff4f552288
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      rip = 0x00007fff4f5529ec
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      Found by: previous frame's frame pointer
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -  26  0x7fff4f5fe000
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      rbp = 0x00007fff4f5529d0   rsp = 0x00007fff4f5523a8
[task 2020-02-14T14:57:31.539Z] 14:57:31     INFO -      rip = 0x00007fff4f5fe000
[task 2020-02-14T14:57:31.540Z] 14:57:31     INFO -      Found by: stack scanning
[task 2020-02-14T14:57:31.540Z] 14:57:31     INFO -  27  0x72d042d15000
[task 2020-02-14T14:57:31.540Z] 14:57:31     INFO -      rbp = 0x00007fff4f5529d0   rsp = 0x00007fff4f552418
[task 2020-02-14T14:57:31.540Z] 14:57:31     INFO -      rip = 0x000072d042d15000
[task 2020-02-14T14:57:31.540Z] 14:57:31     INFO -      Found by: stack scanning
[task 2020-02-14T14:57:31.540Z] 14:57:31     INFO -  28  xpcshell + 0x6f0
[task 2020-02-14T14:57:31.540Z] 14:57:31     INFO -      rbp = 0x00007fff4f5529d0   rsp = 0x00007fff4f552438
[task 2020-02-14T14:57:31.540Z] 14:57:31     INFO -      rip = 0x000072d042df86f0
[task 2020-02-14T14:57:31.540Z] 14:57:31     INFO -      Found by: stack scanning

Comment 38

[Bogdan Tara[:bogdan_tara | bogdant]]

There are some other failures which seem to have started with the backed out changes:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288942730&repo=autoland&lineNumber=2664

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288939649&repo=autoland&lineNumber=2288

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288942719&repo=autoland&lineNumber=3339

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288942712&repo=autoland&lineNumber=2621

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288939933&repo=autoland&lineNumber=2991

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288941744&repo=autoland&lineNumber=55954

This turned into perma fail: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288940037&repo=autoland&lineNumber=2634

Comment 39

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/88c4e60eff6c
make DidComposite to use mediumhigh priority message r=mattwoodrow
https://hg.mozilla.org/integration/autoland/rev/040e29ea6089
remove useless private: from VsyncEvent struct r=mattwoodrow
https://hg.mozilla.org/integration/autoland/rev/503f96afd632
make parent process vsync handling to be blocked the same way as in child process r=farre

Comment 40

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/88c4e60eff6c
https://hg.mozilla.org/mozilla-central/rev/040e29ea6089
https://hg.mozilla.org/mozilla-central/rev/503f96afd632

Comment 41

[Alexandru Ionescu (needinfo me) [:alexandrui]]

Hi, Olli. I assume the below regression is also a WONT FIX, just like 1616047. Do I assume correctly?
== Change summary for alert #24973 (as of Tue, 18 Feb 2020 06:26:08 GMT) ==

Regressions:

4% raptor-tp6m-allrecipes-geckoview-cold loadtime android-hw-g5-7-0-arm7-api-16 pgo 6,486.75 -> 6,750.83
1% raptor-tp6m-allrecipes-geckoview-cold loadtime android-hw-g5-7-0-arm7-api-16 pgo 6,567.75 -> 6,646.38

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=24973

Comment 42

[Olli Pettay [:smaug][[e-mail]]]

Thinking that. It is somewhat expected that loadtime might decrease in some cases a tiny bit but responsive basically should improve.

Comment 43

[Julian Descottes [:jdescottes]]

Also spotted performance regression in devtools, https://treeherder.mozilla.org/perf.html#/alerts?id=24952&hideDwnToInv=0

• 25% slower when expanding many nodes in the inspector markup view
• 5% slower when to open the network panel
• 5% slower when to open the inspector panel

Comment 44

[Olli Pettay [:smaug][[e-mail]]]

Given what is tested in those cases, it seems very much expected. I'd expect that we get smoother paints while expanding dom tree etc.