Closed Bug 1762922 Opened 2 years ago Closed 2 years ago

Reduce runtime of damp-webconsole job

Categories

(DevTools :: Console, task)

Product:
DevTools
Component:
Console
Type:
task

Tracking

(firefox101 fixed)

Status:
RESOLVED FIXED
Milestone:
101 Branch
Tracking Flags:
Tracking Status
firefox101 --- fixed

People

(Reporter: jdescottes, Assigned: nchevobbe)

References

Details

Attachments

(1 file)

Bug 1762922 - [devtools] Don't gargageCollect between log-in-loop-content-process tests. r=jdescottes.
48 bytes, text/x-phabricator-request
Details | Review

After Bug 1759666, the runtime of the damp-webconsole job jumped from 25mn to 45mn.

We should try to fix this and get damp-webconsole closer to the other DAMP jobs (10-15mn).
Looking at the logs, it seems the GCs are responsible for most of the time spent in the test:

[task 2022-04-03T23:30:41.907Z] 23:30:41     INFO -  PID 2959 | Loading test 'webconsole/log-in-loop-content-process.js'
[task 2022-04-03T23:30:41.907Z] 23:30:41     INFO -  PID 2959 | Executing test 'webconsole/log-in-loop-content-process.js'
[task 2022-04-03T23:30:41.915Z] 23:30:41     INFO -  PID 2959 | Wait for a pageshow event for browsing context 83
[task 2022-04-03T23:30:41.980Z] 23:30:41     INFO -  PID 2959 | Received pageshow event for 83
[task 2022-04-03T23:30:42.170Z] 23:30:42     INFO -  PID 2959 | Start "console.log-in-loop-content-process-string"
[task 2022-04-03T23:30:42.288Z] 23:30:42     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:30:44.338Z] 23:30:44     INFO -  PID 2959 | Start "console.log-in-loop-content-process-number"
[task 2022-04-03T23:30:44.439Z] 23:30:44     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:30:46.516Z] 23:30:46     INFO -  PID 2959 | Start "console.log-in-loop-content-process-bigint"
[task 2022-04-03T23:30:46.588Z] 23:30:46     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:30:48.589Z] 23:30:48     INFO -  PID 2959 | Start "console.log-in-loop-content-process-null"
[task 2022-04-03T23:30:48.665Z] 23:30:48     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:30:50.685Z] 23:30:50     INFO -  PID 2959 | Start "console.log-in-loop-content-process-undefined"
[task 2022-04-03T23:30:50.769Z] 23:30:50     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:30:52.770Z] 23:30:52     INFO -  PID 2959 | Start "console.log-in-loop-content-process-nan"
[task 2022-04-03T23:30:52.843Z] 23:30:52     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:30:54.837Z] 23:30:54     INFO -  PID 2959 | Start "console.log-in-loop-content-process-bool"
[task 2022-04-03T23:30:54.911Z] 23:30:54     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:30:56.909Z] 23:30:56     INFO -  PID 2959 | Start "console.log-in-loop-content-process-infinity"
[task 2022-04-03T23:30:56.982Z] 23:30:56     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:30:58.990Z] 23:30:58     INFO -  PID 2959 | Start "console.log-in-loop-content-process-symbol"
[task 2022-04-03T23:30:59.073Z] 23:30:59     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:01.072Z] 23:31:01     INFO -  PID 2959 | Start "console.log-in-loop-content-process-array"
[task 2022-04-03T23:31:01.222Z] 23:31:01     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:03.211Z] 23:31:03     INFO -  PID 2959 | Start "console.log-in-loop-content-process-typedarray"
[task 2022-04-03T23:31:03.337Z] 23:31:03     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:05.337Z] 23:31:05     INFO -  PID 2959 | Start "console.log-in-loop-content-process-set"
[task 2022-04-03T23:31:05.603Z] 23:31:05     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:07.610Z] 23:31:07     INFO -  PID 2959 | Start "console.log-in-loop-content-process-map"
[task 2022-04-03T23:31:07.901Z] 23:31:07     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:09.938Z] 23:31:09     INFO -  PID 2959 | Start "console.log-in-loop-content-process-object"
[task 2022-04-03T23:31:10.246Z] 23:31:10     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:12.281Z] 23:31:12     INFO -  PID 2959 | Start "console.log-in-loop-content-process-node"
[task 2022-04-03T23:31:12.350Z] 23:31:12     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:14.409Z] 23:31:14     INFO -  PID 2959 | Start "console.log-in-loop-content-process-nodelist"
[task 2022-04-03T23:31:14.721Z] 23:31:14     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:16.797Z] 23:31:16     INFO -  PID 2959 | Start "console.log-in-loop-content-process-promise"
[task 2022-04-03T23:31:16.925Z] 23:31:16     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:18.990Z] 23:31:18     INFO -  PID 2959 | Start "console.log-in-loop-content-process-error"
[task 2022-04-03T23:31:19.117Z] 23:31:19     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:21.155Z] 23:31:21     INFO -  PID 2959 | Start "console.log-in-loop-content-process-document"
[task 2022-04-03T23:31:21.274Z] 23:31:21     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:23.316Z] 23:31:23     INFO -  PID 2959 | Start "console.log-in-loop-content-process-window"
[task 2022-04-03T23:31:23.580Z] 23:31:23     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:25.629Z] 23:31:25     INFO -  PID 2959 | Start "console.log-in-loop-content-process-date"
[task 2022-04-03T23:31:25.716Z] 23:31:25     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:27.778Z] 23:31:27     INFO -  PID 2959 | Start "console.log-in-loop-content-process-longstring"
[task 2022-04-03T23:31:27.862Z] 23:31:27     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:29.994Z] 23:31:29     INFO -  PID 2959 | Garbage collect
[task 2022-04-03T23:31:32.099Z] 23:31:32     INFO -  PID 2959 | webconsole/log-in-loop-content-process.js took 50193ms.

With ~2 seconds per GC and 21 test types, we have a test which takes almost a minute for a single run, times 25.

Potential solutions:

  • reduce the amount of GC
  • extract the new test to a dedicated sub-suite
  • run this test only once per browser? (make it a cold test)

Not urgent, but we tried to split DAMP exactly to avoid long runtimes, and this puts us back almost where we started.

Removing the call to GC seems to bring down the runtime to ~27mn (https://treeherder.mozilla.org/jobs?repo=try&revision=bbc7378b367ef24f291378e4cd27d14f430e36b0&selectedTaskRun=InzzTf9AQX6hKd_1HXsL3Q.0)
I'm waiting for other runs to finish to see the impact on variance

This makes damp-webconsole job run faster, with the test variance still looking
good enough.
If we see that we get unstable numbers at some point, we'll evaluate other options
to minimize the job duration.

Assignee: nobody → nchevobbe
Status: NEW → ASSIGNED
Attachment #9270829 - Attachment description: Bug 1762922 - [devtools] Don't gargageCollect betweeni log-in-loop-content-process tests. r=jdescottes. → Bug 1762922 - [devtools] Don't gargageCollect between log-in-loop-content-process tests. r=jdescottes.
Pushed by nchevobbe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/f9298b5d058f
[devtools] Don't gargageCollect between log-in-loop-content-process tests. r=jdescottes,perftest-reviewers,sparky.

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

Status: ASSIGNED → RESOLVED
Closed: 2 years ago
status-firefox101: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 101 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: