1359002 - Investigate e10s toolkit/components/perfmonitoring/tests/browser/browser_compartments.js | Sanity check (parent process: 0): totalSystemTime of component is not impossibly larger than that of process: 64097 <= 61005 - false == true - JS frame :: chrome:/

Status: RESOLVED FIXED

(Toolkit :: Performance Monitoring, defect, P5)

Description

[:Gijs (he/him)]

We used a workaround to shut up the intermittent orange in bug 1352664 but we should still figure out why the test is failing the way it is.

+++ This bug was initially created as a clone of Bug #1352664 +++

https://treeherder.mozilla.org/logviewer.html#?job_id=87991592&repo=autoland

16:41:45     INFO - TEST-PASS | toolkit/components/perfmonitoring/tests/browser/browser_compartments.js | Searching by title, the frames don't show up in the list of components - true == true - 
16:41:45     INFO - Searching for window title 'Main frame for test browser_compartments.js 0.845897513513775' in [] (I hope to find it)
16:41:45     INFO - Searching by title, we didn't find the main frame
16:41:45     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.com/browser/toolkit/components/perfmonitoring/tests/browser/browser_compartments.html?test=0.0453446058246062" line: 0}]
16:41:45     INFO - Setting titles
16:41:45     INFO - Buffered messages finished
16:41:45     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/perfmonitoring/tests/browser/browser_compartments.js | Sanity check (parent process: 0): totalSystemTime of component is not impossibly larger than that of process: 64097 <= 61005 - false == true - JS frame :: chrome://mochitests/content/browser/toolkit/components/perfmonitoring/tests/browser/browser_compartments.js :: ok :: line 85
16:41:45     INFO - Stack trace:
16:41:45     INFO -     chrome://mochitests/content/browser/toolkit/components/perfmonitoring/tests/browser/browser_compartments.js:ok:85
16:41:45     INFO -     chrome://mochitests/content/browser/toolkit/components/perfmonitoring/tests/browser/browser_compartments.js:leq:88
16:41:45     INFO -     chrome://mochitests/content/browser/toolkit/components/perfmonitoring/tests/browser/browser_compartments.js:monotinicity_tester/frameCheck<:168
16:41:45     INFO -     setInterval handler*monotinicity_tester@chrome://mochitests/content/browser/toolkit/components/perfmonitoring/tests/browser/browser_compartments.js:206:18
16:41:45     INFO -     test@chrome://mochitests/content/browser/toolkit/components/perfmonitoring/tests/browser/browser_compartments.js:234:5
16:41:45     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
16:41:45     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
16:41:45     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
16:41:45     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
16:41:45     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
16:41:45     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
16:41:45     INFO -     receiveMessage@resource://testing-common/ContentTask.jsm:113:9
16:41:45     INFO - Titles set
16:41:45     INFO - Searching for frame title 'Subframe for test browser_compartments.js 0.9269153926364134' in [] (I hope not to find it)
16:41:45     INFO - TEST-PASS | toolkit/components/perfmonitoring/tests/browser/browser_compartments.js | Searching by title, the frames don't show up in the list of components - true == true -




(In reply to :Gijs from comment #17)
> (In reply to David Teller [:Yoric] (please use "needinfo") from comment #14)
> > (In reply to :Gijs (away until Tuesday 18) from comment #12)
> > > Uh, OK... should we just disable the test? Is there something we can do to
> > > debug? Under what circumstances does time (according to the perf monitoring
> > > system / computer) flow backwards?
> > 
> > Unspecified by the OS, but typically, each CPU (or even each core, depending
> > on the architecture) has a different clock, so this may happen whenever the
> > OS reschedules the thread/process to another CPU/core. Also, I believe the
> > clocks readjust themselves to each other from time to time, unpredictably.
> > So, in practice, whenever.
> 
> Actually, I think the problem here is with the code and/or test, not with
> clocks. AIUI the snapshot code includes both parent and child process time,
> here: 
> 
> https://dxr.mozilla.org/mozilla-central/source/toolkit/components/
> perfmonitoring/PerformanceStats.jsm#847-860
> 
> Which would explain why the time for any given component in the child
> process could easily surpass the total time for the parent process, because
> they're in different processes. So if the parent is idle and the child
> isn't, the child time is going to be (much) larger.
> 
> I don't think we can make meaningful assertions about the totalSystemTime of
> the parent process against the totalSystemTime of a component in the child
> process. Am I missing something?

(In reply to David Teller [:Yoric] (please use "needinfo") from comment #18)
> While the clock issues exist, it's entirely possible that I missed an
> unrelated problem. I don't have time to check today, but I'll try to check
> by the end of the week.

Ni Yoric to confirm/deny my diagnosis. :-)

Comment 1

[David Teller [:Yoric] - still alive but not very active]

You are correct, this check only makes sense for `totalUserTime`, not `totalSystemTime`.

Comment 2

[:Gijs (he/him)]

Attachment: Bug 1359002 - stop checking the total time of processes against compartment data from all processes,

Review commit: https://reviewboard.mozilla.org/r/135498/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/135498/

Comment 3

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8863725 [details]
Bug 1359002 - stop checking the total time of processes against compartment data from all processes,

https://reviewboard.mozilla.org/r/135498/#review138520

I'm not even sure that `totalUserTime` makes sense either. I'd go for simply removing the loop.

Comment 4

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8863725 [details]
Bug 1359002 - stop checking the total time of processes against compartment data from all processes,

https://reviewboard.mozilla.org/r/135498/#review138868

Comment 5

[:Gijs (he/him)]

Comment on attachment 8863725 [details]
Bug 1359002 - stop checking the total time of processes against compartment data from all processes,

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/135498/diff/1-2/

Comment 6

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 8863725 [details]
Bug 1359002 - stop checking the total time of processes against compartment data from all processes,

https://reviewboard.mozilla.org/r/135498/#review138944

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2f7d8cabe3c8
stop checking the total time of processes against compartment data from all processes, r=Yoric

Comment 8

[Iris Hsiao [:ihsiao]]

https://hg.mozilla.org/mozilla-central/rev/2f7d8cabe3c8