Closed Bug 1556395 Opened 7 years ago Closed 7 years ago

Investigate performance regression on many DevTools tests

Tracking

(firefox69 fixed)

Status:

RESOLVED FIXED

Milestone:

Firefox 69

Tracking Flags:

Tracking

Status

firefox69

---

fixed

People

(Reporter: jdescottes, Assigned: jdescottes)

References

Details

Attachments

(1 file)

Bug 1556395 - Clear devtools.testing pref to Fix DAMP test performance regression 7 years ago Julian Descottes [:jdescottes] 47 bytes, text/x-phabricator-request		Details \| Review

Julian Descottes [:jdescottes]

Assignee

Description

•

7 years ago

•

Edited

== Change summary for alert #21149 (as of Wed, 29 May 2019 12:46:03 GMT) ==

Regressions:

1003% damp simple.styleeditor.close.DAMP linux64-shippable-qr opt e10s stylo 985% damp simple.styleeditor.close.DAMP windows10-64-shippable-qr opt e10s stylo 891% damp simple.styleeditor.close.DAMP linux64-shippable opt e10s stylo 885% damp simple.styleeditor.close.DAMP windows7-32-shippable opt e10s stylo 839% damp simple.styleeditor.close.DAMP windows10-64-shippable opt e10s stylo 833% damp console.objectexpanded.close.DAMP windows7-32-shippable opt e10s stylo 829% damp simple.netmonitor.close.DAMP windows7-32-shippable opt e10s stylo 794% damp simple.netmonitor.close.DAMP windows10-64-shippable opt e10s stylo 791% damp simple.netmonitor.close.DAMP windows10-64-shippable-qr opt e10s stylo 731% damp simple.netmonitor.close.DAMP linux64-shippable-qr opt e10s stylo 698% damp simple.netmonitor.close.DAMP linux64-shippable opt e10s stylo 673% damp console.objectexpanded.close.DAMP windows10-64-shippable opt e10s stylo 606% damp complicated.webconsole.close.DAMP linux64-shippable-qr opt e10s stylo 577% damp complicated.webconsole.close.DAMP linux64-shippable opt e10s stylo [ ... check the alert for details, there are regressions on most devtools 5% damp cold.inspector.open.DAMP windows10-64-shippable opt e10s stylo 5% damp custom.jsdebugger.project-search.DAMP linux64-shippable-qr opt e10s stylo 5% damp simple.webconsole.reload.DAMP linux64-shippable opt e10s stylo 5% damp complicated.styleeditor.open.DAMP linux64-shippable-qr opt e10s stylo 5% damp cold.jsdebugger.open.DAMP windows10-64-shippable-qr opt e10s stylo 3% damp complicated.jsdebugger.open.DAMP linux64-shippable opt e10s stylo 3% damp custom.jsdebugger.reload.DAMP linux64-shippable opt e10s stylo 3% damp custom.inspector.manyrules.selectnode linux64-shippable-qr opt e10s stylo 10.39 -> 114.69
10.91 -> 118.34
11.34 -> 112.34
11.69 -> 115.11
12.55 -> 117.88
16.92 -> 157.88
13.88 -> 128.85
14.77 -> 132.08
15.03 -> 133.90
15.84 -> 131.61
15.77 -> 125.94
18.05 -> 139.50
42.90 -> 302.66
41.37 -> 279.99
tests, open, reload, close etc... too long to display here]
429.11 -> 452.61
2,287.18 -> 2,412.22
83.20 -> 87.64
640.85 -> 671.93
686.81 -> 718.37
1,038.50 -> 1,069.15
768.21 -> 790.51
644.68 -> 661.89

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=21149
Pushlog https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=c7fbeec36c29d05a6c1a27fa10bbc2d3c67c6343&tochange=ad2f980e236395a7e1e32cf0e37f4d5216d8dda5

Julian Descottes [:jdescottes]

Assignee

Comment 1

•

7 years ago

First of all, the reason why the pushlog contains so many changesets is that damp tests were not able to run for a while on autoland. This was finally fixed by Bug 1554724, which in turns is the last changeset from our pushlog.
This means that any retrigger for intermediary changesets needs to include the patch from Bug 1554724, otherwise DAMP will not run.

Investigation

My investigation so far leads me to believe that this issue is GC related.

Subsequent runs are slower than the first run

The first reason is that if you look at successive results for a single test, the first test will be much faster than the others. For instance, if we compare the results for custom.webconsole before the regression:

15:41:39     INFO -  PID 1995 | [#38] custom.webconsole.open.DAMP  Cycles:5  Average:525.88  Median:520.19  stddev:21.88 (4.2%)  stddev-sans-first:25.00
15:41:39     INFO -  PID 1995 | Values: 520.2  561.7  529.0  513.3  505.2
15:41:39     INFO -  PID 1995 |
15:41:39     INFO -  PID 1995 | [#39] custom.webconsole.reload.DAMP  Cycles:5  Average:6737.73  Median:6742.13  stddev:64.93 (1.0%)  stddev-sans-first:74.92
15:41:39     INFO -  PID 1995 | Values: 6742.1  6665.4  6690.3  6758.6  6832.2
15:41:39     INFO -  PID 1995 |
15:41:39     INFO -  PID 1995 | [#40] custom.webconsole.close.DAMP  Cycles:5  Average:88.26  Median:87.98  stddev:5.87 (6.7%)  stddev-sans-first:5.44
15:41:39     INFO -  PID 1995 | Values: 82.0  96.1  83.4  88.0  91.8

and after the regression:

15:11:23     INFO -  PID 3544 | [#38] custom.webconsole.open.DAMP  Cycles:5  Average:1221.73  Median:1400.71  stddev:400.23 (28.6%)  stddev-sans-first:23.70
15:11:23     INFO -  PID 3544 | Values: 506.7  1379.6  1433.6  1388.1  1400.7
15:11:23     INFO -  PID 3544 |
15:11:23     INFO -  PID 3544 | [#39] custom.webconsole.reload.DAMP  Cycles:5  Average:6799.75  Median:6804.43  stddev:102.85 (1.5%)  stddev-sans-first:113.48
15:11:23     INFO -  PID 3544 | Values: 6745.5  6932.0  6662.4  6854.4  6804.4
15:11:23     INFO -  PID 3544 |
15:11:23     INFO -  PID 3544 | [#40] custom.webconsole.close.DAMP  Cycles:5  Average:363.78  Median:408.46  stddev:134.60 (33.0%)  stddev-sans-first:22.30
15:11:23     INFO -  PID 3544 | Values: 125.5  408.5  435.3  401.1  448.5

As you can see the first value of custom.webconsole.open.DAMP is only of 506.7 for the first pagecycle, but then it jumps to ~1400. Note that this observation is only valid for the first overall cycle. For subsequent cycles, all the pagecycles are consistently slow. As a reminder we run 5 cycles each running 5 pagecycles. Between each cycle Firefox is normally restarted.

So it seems that the first run of the tests performs similarly to before the regression, but afterwards, we get much slower.

GC spotted on simple.styleeditor.close

simple.styleeditor.close is the biggest regression in terms of percentage, so I tried focusing on it. I tried generating perf profiles for both before and after the regression, but so far the job keeps crashing for the "before regression" push. Nevertheless, since the first pagecycle is much faster than the second pagecycle, I tried comparing those:

first pagecycle: https://perfht.ml/2Ijk1xF
second pagecycle: https://perfht.ml/2Iv68Nd
overall profile https://profiler.firefox.com/from-url/https%3A%2F%2Fqueue.taskcluster.net%2Fv1%2Ftask%2FZr_Cp_nlSIi3Q25rWs_jDg%2Fruns%2F0%2Fartifacts%2Fpublic%2Ftest_info%2Fprofile_damp.zip

You can see that for the first pagecycle, onceToolboxDestroyed is only 10ms, while for the second pagecycle, it takes 110ms. And expanding the stack we can see that it triggered a GC.

Julian Descottes [:jdescottes]

Assignee

Comment 2

•

7 years ago

Smaller regression window: https://hg.mozilla.org/integration/autoland/pushloghtml?tochange=5d11d295d7d4c0431ea0a772a763a876f4fd0ef5&fromchange=50beca34e93930de1a33b44f23faa0906487ce97

Julian Descottes [:jdescottes]

Assignee

Comment 3

•

7 years ago

Regression window is down to https://hg.mozilla.org/integration/autoland/pushloghtml?tochange=e509c39c7da853164469222c4bc2a57d0a012181&fromchange=49be991ad4d9ab41ddd6dd829edf62a2154fbfea

I suspect Bug 1439369:

--- a/testing/talos/talos/tests/devtools/addon/content/tests/debugger/custom.js
+++ b/testing/talos/talos/tests/devtools/addon/content/tests/debugger/custom.js 
 const EXPECTED_FUNCTION = "window.hitBreakpoint()";
 
 module.exports = async function() {
   const tab = await testSetup(PAGES_BASE_URL + "custom/debugger/index.html");
   Services.prefs.setBoolPref("devtools.debugger.features.map-scopes", false);
+  Services.prefs.setBoolPref("devtools.testing", true);

devtools.testing will trigger additional logging and processing and in general should not be used for performance tests. At the very least we should flip it back when we finish the test.

Julian Descottes [:jdescottes]

Assignee

Comment 4

•

7 years ago

Attached file Bug 1556395 - Clear devtools.testing pref to Fix DAMP test performance regression — Details

Julian Descottes [:jdescottes]

Assignee

Updated

•

7 years ago

Assignee: nobody → jdescottes

Status: NEW → ASSIGNED

Julian Descottes [:jdescottes]

Assignee

Comment 5

•

7 years ago

The patch attached here mostly gets us back to pre-regression levels:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&newProject=try&newRevision=ace56c2137496655d2810df9b01baa5a94aa52d8&originalSignature=1759151&newSignature=1759151&framework=12&originalRevision=749f9617fc06057228ccb7f67d848613afd0854c

The highlights are:

inspector expandall and custom open still regressed (Bug 1556729)
custom.debugger.open/reload/close/stepIn tests still show a regression, but that might be due to devtools.testing now being true during this test

Pulsebot

Comment 6

•

7 years ago

Pushed by jdescottes@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/769370df893e Clear devtools.testing pref to Fix DAMP test performance regression r=davidwalsh

Julian Descottes [:jdescottes]

Assignee

Updated

•

7 years ago

Blocks: 1557064

Arthur Iakab [arthur_iakab]

Comment 7

•

7 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/769370df893e

Status: ASSIGNED → RESOLVED

Closed: 7 years ago

status-firefox69: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → Firefox 69

You need to log in before you can comment on or make changes to this bug.

Bugzilla

Investigate performance regression on many DevTools tests

Categories

(DevTools :: General, defect)

Tracking

(firefox69 fixed)

People

(Reporter: jdescottes, Assigned: jdescottes)

References

Details

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Comment 1

Investigation

Subsequent runs are slower than the first run

GC spotted on simple.styleeditor.close

Comment 2

Comment 3

Comment 4

Updated

Comment 5

Comment 6

Updated

Comment 7

Attachment

General

Description

File Name

Content Type