1986531 - Unclear how to match up browsertime values with profiles

Status: NEW

(Testing :: Performance, defect, P3)

Description

[Markus Stange [:mstange]]

The test-linux1804-64-shippable-qr/opt-browsertime-responsiveness-firefox-facebook-nav job appears to do 5 profiling iterations, and produces 10 "loadtime" values for each iteration. But the profile it produces only contains a single page load. Which of the 50 loadtime numbers does it correspond to?

We're trying to diagnose bug 1985795. It would be quite useful if we could confirm that we're seeing the measured time in the profile.

We're looking at this job: fbnav job

profile_facebook-nav.zip only contains a single file, facebook-nav-pageload-cold/browser-cycle-1.json.gz - and this isn't actually a gz file, it's just plain JSON.

I've also found that there are four more profile files inside the browsertime-profiler.tgz artifact, at these paths:

facebook-nav/profiling/pages/www_facebook_com/friends/data/geckoProfile-1.json.gz
facebook-nav/profiling/pages/www_facebook_com/groups/data/geckoProfile-1.json.gz
facebook-nav/profiling/pages/www_facebook_com/landing/data/geckoProfile-1.json.gz
facebook-nav/profiling/pages/www_facebook_com/marketplace/data/geckoProfile-1.json.gz

Which of these is the page that gets measured in the loadtime results?

Why do we get 10 loadtime values but only one profile per iteration? Why are all iterations "iteration 1" and overwriting their profile files?

Comment 1

[Markus Stange [:mstange]]

Attachment: live_backing.log

Comment 2

[Markus Stange [:mstange]]

(In reply to Markus Stange [:mstange] from comment #0)

profile_facebook-nav.zip only contains a single file, facebook-nav-pageload-cold/browser-cycle-1.json.gz - and this isn't actually a gz file, it's just plain JSON.

Wait - it's not just one file! It's four files! But they all have identical paths!

% zipinfo /Users/mstange/Downloads/profile_facebook-nav.zip
Archive:  /Users/mstange/Downloads/profile_facebook-nav.zip
Zip file size: 13351386 bytes, number of entries: 4
?rw-------  2.0 unx 22645519 b- defN 25-Aug-27 19:56 facebook-nav-pageload-cold/browser-cycle-1.json.gz
?rw-------  2.0 unx 18962217 b- defN 25-Aug-27 19:56 facebook-nav-pageload-cold/browser-cycle-1.json.gz
?rw-------  2.0 unx 15561549 b- defN 25-Aug-27 19:56 facebook-nav-pageload-cold/browser-cycle-1.json.gz
?rw-------  2.0 unx 13127348 b- defN 25-Aug-27 19:56 facebook-nav-pageload-cold/browser-cycle-1.json.gz
4 files, 70296633 bytes uncompressed, 13350660 bytes compressed:  81.0%

Comment 3

[Greg Mierzwinski [:sparky]]

We don't gather the loadtime metrics, or any other metrics, from the extra gecko profiling run so those 10 loadtime values that you're seeing are from the non-profiling runs and there are 10 of those.

This section of the log corresponds to the profiling run: https://treeherder.mozilla.org/logviewer?job_id=524477699&repo=autoland&task=dm8G-JwET4SgvJybeGjLYw.0&lineNumber=1448-1504

If you need to get the metrics for the profiling run, you can find them in the browsertime.json file in the browsertime-profiler.tgz archive. They should be found at /browsertime-profiler/facebook-nav/profiling/ within the archive.

I agree there's definitely a bug (or some) in the profile_*.zip file though. There should be all four profiles there. Seems like something is broken here: https://searchfox.org/firefox-main/source/testing/raptor/raptor/gecko_profile.py#208

Comment 4

[Markus Stange [:mstange]]

I see, that resolves the remaining mystery. Can we make it clearer in the log that the logged values are about the non-profiling runs?

---

So I think there are two levels of collision happening:

• Profiles of the four different sub-pages collide into one page profile
• Profiles from the 5 iterations are colliding into cycle-1 profiles

I can also see "iteration 1" printed for each of the five iterations in the log.

Comment 5

[Greg Mierzwinski [:sparky]]

Sure, I've filed a bug to make that clearer.

Regarding the collisions, I'm only seeing one which is:

• Profiles of the four different sub-pages collide into one pageload profile in the profile_*.zip archive.

I'm not entirely sure where the 5 iterations are coming from, can you elaborate on that issue? From the logs and artifacts, I see that we are correctly producing 1 profile for each of the sub-pages and there is only 1 test iteration being done for each of them resulting in 4 different geckoProfile-1.json.gz files per subfolder in the browsertime-profiler.tgz archive.

Comment 6

[Markus Stange [:mstange]]

Oh, you're right. I was confused. All the iteration 1 runs are actually loading different pages. Ok everything makes sense now.

Comment 7

[Greg Mierzwinski [:sparky]]

Oh, and regarding the iteration 1 being printed multiple times, it's because we're navigating to each of those sub-pages consecutively within the same browser session. So to browsertime, it's all happening in a single iteration - browsertime changes the iteration count when a new browser session is launched. See the test here: https://searchfox.org/firefox-main/source/testing/raptor/raptor/tests/interactive/browsertime-responsiveness.toml#46-61

Comment 8

[BugBot [:suhaib / :marco/ :calixte]]

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

For more information, please visit BugBot documentation.