1667419 - Include Talos timing information in gecko profiles

Status: NEW

(Testing :: Performance, task, P3)

Description

[Greg Tatum [:gregtatum]]

Per Florian: When looking at the talos zip file, it would be valuable to see the time reported by Talos for each of the runs.

I'm assuming we'll need to add profiler markers for this, and then surface them in the Firefox Profiler UI. This bug can serve to track this work, and then additional bugs can be filed in the different components to implement it.

This is an idea where what we see in our testing performance infrastructure should tightly match what we see in profiles, so it's easy to do comparisons.

Comment 1

[Greg Tatum [:gregtatum]]

I'm going to narrow this bug down a bit into properly using and labeling interval markers to show test timing.

This can be accomplished with something like:

const startTime = performance.now();

// Do something.

ChromeUtils.addProfilerMarker("Talos", startTime, "Name of what just happened");

• Here is an example of DAMP implementing this well.

Talos is using markers in the following files:
https://searchfox.org/mozilla-central/search?q=ChromeUtils.addProfilerMarker&path=talos&case=false&regexp=false

Modifying this API can probably give us mostly what we need: https://searchfox.org/mozilla-central/source/testing/talos/talos/talos-powers/api.js#176-197

Here is a current Talos profile showing only instant markers: https://share.firefox.dev/3l0ugZt
Here is a DAMP profile, which is implementing this style of markers nicely: https://share.firefox.dev/2Gprwpq

Comment 2

[Kimberly Sereduck :kimberlythegeek]

As Greg mentioned above, I'm attempting to replicate behavior used in DAMP tests. When a marker is added using ChromeUtils.addProfilerMarker, and a start_time is supplied, the marker shows up as an interval spanning the duration from start_time to the time at which addProfilerMarker() is called

see: https://searchfox.org/mozilla-central/source/testing/talos/talos/tests/devtools/addon/content/damp.js#193

I've been able to run the DAMP tests locally, but it fails to complete:

19:42:47     INFO -  PID 4635 | Loading test 'webconsole/complicated.js'
19:42:47     INFO -  PID 4635 | Executing test 'webconsole/complicated.js'
19:42:48     INFO -  PID 4635 | Open toolbox on 'webconsole'
19:42:48     INFO -  PID 4635 | Open toolbox - Wait for tab target
19:42:48     INFO -  PID 4635 | Open toolbox - Call showToolbox
19:42:48     INFO -  PID 4635 | Open toolbox - Wait for "toolbox-created"
19:42:48     INFO -  PID 4635 | Open toolbox - Wait for showToolbox to resolve
19:42:48     INFO -  PID 4635 | Wait for pending paints on 'complicated.webconsole.open'
19:42:48     INFO -  PID 4635 | 'complicated.webconsole.open.settle.DAMP' took 26.445815999999468ms.
19:42:48     INFO -  PID 4635 | Garbage collect
19:42:49     INFO -  PID 4635 | Reload page on 'complicated.webconsole'
19:42:53     INFO -  PID 4635 | [TEST_LOG] Still waiting for the following messages:
19:42:53     INFO -  PID 4635 | Layout was forced before the page was fully loaded. (✕1)
19:42:53     INFO -  PID 4635 | ---

Nicolas--are you still the owner of these tests, and do you have any insight?

Comment 3

[Florian Quèze [:florian]]

There's documentation in https://searchfox.org/mozilla-central/source/devtools/docs/tests/performance-tests.md (especially the subtest parameter) that should let you workaround this error by running only a subset of DAMP until you get an answer about the test itself.

Comment 4

[Nicolas Chevobbe [:nchevobbe]]

I'm able to run ./mach talos-test --activeTests damp --subtests complicated.webconsole --cycles 1 --tppagecycles 1 as well as ./mach talos-test --activeTests damp --cycles 1 --tppagecycles 1 without troubles.
Maybe you hit an intermittent where this message is not emitted (https://searchfox.org/mozilla-central/search?q=ForcedLayoutStart&path=&case=false&regexp=false), but I don't think I ever saw any try failure on this.

Comment 5

[Kimberly Sereduck :kimberlythegeek]

:florian :nchevobbe Thanks! I was able to run other tests, but complicated.webconsole is still encountering this error. I updated my repo and rebuilt, but the outcome was the same

Comment 6

[Nicolas Chevobbe [:nchevobbe]]

Kimberly, are you calling this on top of a given patch, or just on central? Does it works if you comment this entry https://searchfox.org/mozilla-central/rev/f82d5c549f046cb64ce5602bfd894b7ae807c8f8/testing/talos/talos/tests/devtools/addon/content/tests/webconsole/complicated.js#24-27 ?

Comment 7

[Kimberly Sereduck :kimberlythegeek]

Apologies for not getting back to this sooner, was on PTO last Friday.

Yes--after comments those lines, the test did complete successfully. Thank you!