Closed Bug 1753572 Opened 3 years ago Closed 3 years ago

Intermittent toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for preallocated content processes should be at least the sum of what the first requestProcInfo returned. - 208 >= 209 - JS frame :: chrome://mochi

Categories

(Core :: DOM: Content Processes, defect, P5)

Product:
Core
Component:
DOM: Content Processes
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
99 Branch
Tracking Flags:
Tracking Status
firefox-esr91 --- unaffected
firefox97 --- unaffected
firefox98 --- fixed
firefox99 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: florian)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Bug 1753572 - Fix rounding of preallocated process CPU times in browser_test_powerMetrics.js, r=chutten.
48 bytes, text/x-phabricator-request
Details | Review

Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=366685322&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UjL5-rKrQ56TKDTLD0QyTg/runs/0/artifacts/public/logs/live_backing.log

[task 2022-02-04T06:14:14.534Z] 06:14:14     INFO - TEST-START | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js
[task 2022-02-04T06:14:14.951Z] 06:14:14     INFO - TEST-INFO | started process screencapture
[task 2022-02-04T06:14:15.070Z] 06:14:15     INFO - TEST-INFO | screencapture: exit 0
[task 2022-02-04T06:14:15.071Z] 06:14:15     INFO - Buffered messages logged at 06:14:14
[task 2022-02-04T06:14:15.071Z] 06:14:15     INFO - Entering test bound 
[task 2022-02-04T06:14:15.072Z] 06:14:15     INFO - CPU time from ProcInfo before calling testFlushAllChildren:
[task 2022-02-04T06:14:15.072Z] 06:14:15     INFO -   pid: 6618, type = parent, cpu time = 1342.604041ms
[task 2022-02-04T06:14:15.072Z] 06:14:15     INFO -   pid: 6626, type = preallocated, cpu time = 68.45275ms
[task 2022-02-04T06:14:15.073Z] 06:14:15     INFO -   pid: 6623, type = web, cpu time = 127.945958ms
[task 2022-02-04T06:14:15.073Z] 06:14:15     INFO -   pid: 6620, type = web, cpu time = 91.94275ms
[task 2022-02-04T06:14:15.074Z] 06:14:15     INFO -   pid: 6625, type = preallocated, cpu time = 75.67075ms
[task 2022-02-04T06:14:15.074Z] 06:14:15     INFO -   pid: 6622, type = privilegedabout, cpu time = 113.077041ms
[task 2022-02-04T06:14:15.074Z] 06:14:15     INFO -   pid: 6627, type = preallocated, cpu time = 65.743416ms
[task 2022-02-04T06:14:15.074Z] 06:14:15     INFO -   pid: 6619, type = extension, cpu time = 161.200333ms
[task 2022-02-04T06:14:15.074Z] 06:14:15     INFO - CPU time for each label:
[task 2022-02-04T06:14:15.075Z] 06:14:15     INFO -   parent.active = undefined
[task 2022-02-04T06:14:15.075Z] 06:14:15     INFO -   parent.active.playing-audio = undefined
[task 2022-02-04T06:14:15.075Z] 06:14:15     INFO -   parent.active.playing-video = undefined
[task 2022-02-04T06:14:15.075Z] 06:14:15     INFO -   parent.inactive = 1345
[task 2022-02-04T06:14:15.075Z] 06:14:15     INFO -   parent.inactive.playing-audio = undefined
[task 2022-02-04T06:14:15.075Z] 06:14:15     INFO -   parent.inactive.playing-video = undefined
[task 2022-02-04T06:14:15.076Z] 06:14:15     INFO -   prealloc = 208
[task 2022-02-04T06:14:15.076Z] 06:14:15     INFO -   privilegedabout = 113
[task 2022-02-04T06:14:15.076Z] 06:14:15     INFO -   rdd = undefined
[task 2022-02-04T06:14:15.076Z] 06:14:15     INFO -   socket = undefined
[task 2022-02-04T06:14:15.076Z] 06:14:15     INFO -   web.background = 52
[task 2022-02-04T06:14:15.076Z] 06:14:15     INFO -   web.background-perceivable = undefined
[task 2022-02-04T06:14:15.077Z] 06:14:15     INFO -   web.foreground = 254
[task 2022-02-04T06:14:15.077Z] 06:14:15     INFO -   extension = 161
[task 2022-02-04T06:14:15.077Z] 06:14:15     INFO -   gpu = undefined
[task 2022-02-04T06:14:15.077Z] 06:14:15     INFO -   gmplugin = undefined
[task 2022-02-04T06:14:15.077Z] 06:14:15     INFO -   utility = undefined
[task 2022-02-04T06:14:15.077Z] 06:14:15     INFO -   __other__ = undefined
[task 2022-02-04T06:14:15.077Z] 06:14:15     INFO - CPU time from ProcInfo after calling testFlushAllChildren:
[task 2022-02-04T06:14:15.078Z] 06:14:15     INFO -   pid: 6618, type = parent, cpu time = 1355.785375ms
[task 2022-02-04T06:14:15.078Z] 06:14:15     INFO -   pid: 6626, type = preallocated, cpu time = 68.653875ms
[task 2022-02-04T06:14:15.078Z] 06:14:15     INFO -   pid: 6623, type = web, cpu time = 128.136958ms
[task 2022-02-04T06:14:15.078Z] 06:14:15     INFO -   pid: 6620, type = web, cpu time = 92.024458ms
[task 2022-02-04T06:14:15.079Z] 06:14:15     INFO -   pid: 6625, type = preallocated, cpu time = 75.814041ms
[task 2022-02-04T06:14:15.079Z] 06:14:15     INFO -   pid: 6622, type = privilegedabout, cpu time = 113.254166ms
[task 2022-02-04T06:14:15.079Z] 06:14:15     INFO -   pid: 6627, type = preallocated, cpu time = 65.903833ms
[task 2022-02-04T06:14:15.079Z] 06:14:15     INFO -   pid: 6619, type = extension, cpu time = 161.350333ms
[task 2022-02-04T06:14:15.079Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | The sum of CPU time used by all process types should match totalCpuTimeMs - 2133 == 2133 - 
[task 2022-02-04T06:14:15.080Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported parent cpu time should be at least what the first requestProcInfo returned - 1345 >= 1342 - 
[task 2022-02-04T06:14:15.080Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported parent cpu time should be at most what the second requestProcInfo returned - 1345 <= 1356 - 
[task 2022-02-04T06:14:15.080Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no media was played so the CPU time for parent.active.playing-audio should be undefined - "undefined" === "undefined" - 
[task 2022-02-04T06:14:15.080Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no media was played so the CPU time for parent.active.playing-video should be undefined - "undefined" === "undefined" - 
[task 2022-02-04T06:14:15.080Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no media was played so the CPU time for parent.inactive.playing-audio should be undefined - "undefined" === "undefined" - 
[task 2022-02-04T06:14:15.080Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no media was played so the CPU time for parent.inactive.playing-video should be undefined - "undefined" === "undefined" - 
[task 2022-02-04T06:14:15.081Z] 06:14:15     INFO - Buffered messages finished
[task 2022-02-04T06:14:15.081Z] 06:14:15     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for preallocated content processes should be at least the sum of what the first requestProcInfo returned. - 208 >= 209 - JS frame :: chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js :: <TOP_LEVEL> :: line 170
[task 2022-02-04T06:14:15.081Z] 06:14:15     INFO - Stack trace:
[task 2022-02-04T06:14:15.081Z] 06:14:15     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js:null:170
[task 2022-02-04T06:14:15.081Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | we used some CPU time in a foreground tab, but don't know how much as the process might have started as preallocated - 113 >= 1 - 
[task 2022-02-04T06:14:15.081Z] 06:14:15     INFO - no rdd process existed when we started our test, but some might have existed before
[task 2022-02-04T06:14:15.081Z] 06:14:15     INFO - no socket process existed when we started our test, but some might have existed before
[task 2022-02-04T06:14:15.082Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for extension process should be at least what the first requestProcInfo returned. - 161 >= 161 - 
[task 2022-02-04T06:14:15.082Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for extension process should be at most what the second requestProcInfo returned. - 161 <= 162 - 
[task 2022-02-04T06:14:15.082Z] 06:14:15     INFO - no gpu process existed when we started our test, but some might have existed before
[task 2022-02-04T06:14:15.082Z] 06:14:15     INFO - no gmplugin process existed when we started our test, but some might have existed before
[task 2022-02-04T06:14:15.082Z] 06:14:15     INFO - no utility process existed when we started our test, but some might have existed before
[task 2022-02-04T06:14:15.082Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | web.background should be at least the time we spent. - 52 >= 51 - 
[task 2022-02-04T06:14:15.082Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | we used some CPU time in a foreground tab, but don't know how much - 254 >= 1 - 
[task 2022-02-04T06:14:15.083Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | CPU time should only be recorded in the web.background-perceivable label - "undefined" === "undefined" - 
[task 2022-02-04T06:14:15.083Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no CPU time should be recorded in the __other__ label - "undefined" === "undefined" - 
[task 2022-02-04T06:14:15.083Z] 06:14:15     INFO - GPU time for each label:
[task 2022-02-04T06:14:15.083Z] 06:14:15     INFO -   parent.active = undefined
[task 2022-02-04T06:14:15.083Z] 06:14:15     INFO -   parent.active.playing-audio = undefined
[task 2022-02-04T06:14:15.083Z] 06:14:15     INFO -   parent.active.playing-video = undefined
[task 2022-02-04T06:14:15.083Z] 06:14:15     INFO -   parent.inactive = undefined
[task 2022-02-04T06:14:15.084Z] 06:14:15     INFO -   parent.inactive.playing-audio = undefined
[task 2022-02-04T06:14:15.084Z] 06:14:15     INFO -   parent.inactive.playing-video = undefined
[task 2022-02-04T06:14:15.084Z] 06:14:15     INFO -   prealloc = undefined
[task 2022-02-04T06:14:15.084Z] 06:14:15     INFO -   privilegedabout = undefined
[task 2022-02-04T06:14:15.084Z] 06:14:15     INFO -   rdd = undefined
[task 2022-02-04T06:14:15.084Z] 06:14:15     INFO -   socket = undefined
[task 2022-02-04T06:14:15.084Z] 06:14:15     INFO -   web.background = undefined
[task 2022-02-04T06:14:15.084Z] 06:14:15     INFO -   web.background-perceivable = undefined
[task 2022-02-04T06:14:15.084Z] 06:14:15     INFO -   web.foreground = undefined
[task 2022-02-04T06:14:15.085Z] 06:14:15     INFO -   extension = undefined
[task 2022-02-04T06:14:15.085Z] 06:14:15     INFO -   gpu = undefined
[task 2022-02-04T06:14:15.085Z] 06:14:15     INFO -   gmplugin = undefined
[task 2022-02-04T06:14:15.085Z] 06:14:15     INFO -   utility = undefined
[task 2022-02-04T06:14:15.085Z] 06:14:15     INFO -   __other__ = undefined
[task 2022-02-04T06:14:15.085Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | The sum of GPU time used by all process types should match totalGpuTimeMs - "undefined" == "undefined" - 
[task 2022-02-04T06:14:15.085Z] 06:14:15     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no GPU time should be recorded in the __other__ label - "undefined" === "undefined" - 
[task 2022-02-04T06:14:15.085Z] 06:14:15     INFO - Leaving test bound 
[task 2022-02-04T06:14:15.086Z] 06:14:15     INFO - GECKO(6618) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2022-02-04T06:14:15.086Z] 06:14:15     INFO - GECKO(6618) | MEMORY STAT | vsize 409884MB | residentFast 322MB | heapAllocated 137MB
[task 2022-02-04T06:14:15.086Z] 06:14:15     INFO - TEST-OK | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | took 415ms
[task 2022-02-04T06:14:15.086Z] 06:14:15     INFO - checking window state
[task 2022-02-04T06:14:15.086Z] 06:14:15     INFO - TEST-START | toolkit/components/processtools/tests/browser/browser_test_procinfo.js

Florian this seems to be from bug 1747138, can you please take a look?

Flags: needinfo?(florian)
Regressed by: 1747138
Assignee: nobody → florian
Status: NEW → ASSIGNED

(In reply to Andreea Pavel [:apavel] from comment #1)

Florian this seems to be from bug 1747138, can you please take a look?

Yes, sorry for that. It's a simple rounding error. I'm glad I put enough info() calls in the test to have enough information to debug this failure just by reading the test log:

[task 2022-02-04T06:14:15.072Z] 06:14:15     INFO - CPU time from ProcInfo before calling testFlushAllChildren:
[task 2022-02-04T06:14:15.072Z] 06:14:15     INFO -   pid: 6626, type = preallocated, cpu time = 68.45275ms
...
[task 2022-02-04T06:14:15.074Z] 06:14:15     INFO -   pid: 6625, type = preallocated, cpu time = 75.67075ms
...
[task 2022-02-04T06:14:15.074Z] 06:14:15     INFO -   pid: 6627, type = preallocated, cpu time = 65.743416ms
...
[task 2022-02-04T06:14:15.074Z] 06:14:15     INFO - CPU time for each label:
...
[task 2022-02-04T06:14:15.076Z] 06:14:15     INFO -   prealloc = 208

Math.floor(68.45275+75.67075+65.743416) = 209
Math.floor(68.45275)+Math.floor(75.67075)+Math.floor(65.743416) = 208

Flags: needinfo?(florian)
Has Regression Range: --- → yes
Pushed by fqueze@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/dcc22e051168 Fix rounding of preallocated process CPU times in browser_test_powerMetrics.js, r=chutten.

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

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
status-firefox99: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 99 Branch

Set release status flags based on info from the regressing bug 1747138

status-firefox97: --- → unaffected
status-firefox98: --- → affected
status-firefox-esr91: --- → unaffected

The patch landed in nightly and beta is affected.
:florian, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(florian)

(In reply to Release mgmt bot [:marco/ :calixte] from comment #8)

The patch landed in nightly and beta is affected.
:florian, is this bug important enough to require an uplift?

It's a simple test-only change, it might be worth uplifting to avoid having failures on the beta channel, but I thought these kind of patches didn't require requesting approval. Ryan, has this changed?

Flags: needinfo?(florian) → needinfo?(ryanvm)

Nope, test-only changes can still land without approval.

Flags: needinfo?(ryanvm)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: