Closed Bug 1288709 Opened 9 years ago Closed 7 years ago

Intermittent browser/modules/test/browser_UsageTelemetry.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

Categories

(Toolkit :: Telemetry, defect, P1)

Product:
Toolkit
Component:
Telemetry
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla51
Tracking Flags:
Tracking Status
firefox50 --- fixed
firefox51 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [measurement:client][stockwell fixed:other])

Attachments

(1 file, 2 obsolete files)

bug1288709.patch
16.43 KB, patch
Dexter
: review+
Details | Diff | Splinter Review
Blocks: 1271304
Priority: -- → P3
Whiteboard: [measurement:client]
Priority: P3 → P2
Priority: P2 → P1
As far as I can tell, nothing obvious stands out of the longs. By examining [1], I've noticed one weird thing: > 15:38:02 INFO - 357 INFO TEST-START | browser/modules/test/browser_UsageTelemetry.js > [...] > 15:38:52 INFO - 358 INFO checking window state > 15:38:52 INFO - 359 INFO Entering test bound test_tabsAndWindows There seems to be a 50s delay between the TEST-START line and when the first test inside the file actually gets executed. Any clue on why this could be happening or any idea about who could know? [1] - https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-aurora&job_id=3382735#L14702
Flags: needinfo?(gfritzsche)
That seems odd, but i don't have a good idea about this. There could be side-effects from a previous bug, the test harness having some issues, ...? Maybe someone on #fxteam knows better?
Flags: needinfo?(gfritzsche)
(In reply to Georg Fritzsche [:gfritzsche] from comment #7) > That seems odd, but i don't have a good idea about this. > There could be side-effects from a previous bug, the test harness having > some issues, ...? > Maybe someone on #fxteam knows better? Gijs mentioned bug 1068156: unfortunately, the logged timestamps cannot be trusted.
(In reply to Alessio Placitelli [:Dexter] from comment #8) > Gijs mentioned bug 1068156: unfortunately, the logged timestamps cannot be > trusted. Ok, I dug deeper into this [1] and succeed in printing the timestamps on each test run. > 07:25:29 INFO - 166 INFO Entering test bound test_tabsAndWindows Custom Timestamp: 2016-09-01T14:24:38.543Z > 07:25:29 INFO - 192 INFO Entering test bound test_subsessionSplit Custom Timestamp: 2016-09-01T14:24:53.089Z > 07:25:29 INFO - 206 INFO Entering test bound test_URIAndDomainCounts Custom Timestamp: 2016-09-01T14:25:03.347Z > 07:25:29 INFO - 226 INFO Entering test bound test_privateMode Custom Timestamp: 2016-09-01T14:25:19.862Z > 07:25:29 INFO - 234 INFO Entering test bound test_sessionRestore Custom Timestamp: 2016-09-01T14:25:24.866Z It looks like this test is taking more than one minute to complete. As far as I can tell: - |test_tabsAndWindows| takes 15s to complete. - |test_subsessionSplit| takes 32s to complete. - |test_URIAndDomainCounts| takes 16s to complete. - |test_privateMode| takes 6s - |test_sessionRestore| might take a bit more than the others. This tests are loading a lot of testing URIs, so that might be why it's slow (sometimes). Our best shot is probably to split it. [1] - https://treeherder.mozilla.org/#/jobs?repo=try&revision=1d3d089de282&selectedJob=26764229 [2] - https://dxr.mozilla.org/mozilla-central/rev/b7f7ae14590aced450bb0b0469dfb38edd2c0ace/testing/mochitest/browser-test.js#3
Attached patch bug1288709.patch (obsolete) — — Splinter Review
Gijs, would it be reasonable to request a longer timeout for this test? The slowdown only happens when loading URIs on debug e10s. We will keep this test as it is, without adding new test to the files. Tests for new probes will live in a separate test file.
Assignee: nobody → alessio.placitelli
Status: NEW → ASSIGNED
Attachment #8787575 - Flags: review?(gijskruitbosch+bugs)
Comment on attachment 8787575 [details] [diff] [review] bug1288709.patch Review of attachment 8787575 [details] [diff] [review]: ----------------------------------------------------------------- Because these are already a bunch of separate tasks, they should be relatively easy to split up, which will help with narrowing down issues with the timeouts/tests. So I think it would be preferable to split off the private mode and session store tasks to a separate file, moving the helpers to a helper JSM that you load from both tests: let helpers = {}; Cu.import(getRootDirectory(gTestPath) + "myhelpers.jsm", helpers); let {browserLocationChanged, checkScalars, checkScalar} = helpers; (promiseBrowserStateRestored can just be in the new file that has the session store task)
Attachment #8787575 - Flags: review?(gijskruitbosch+bugs)
(In reply to :Gijs Kruitbosch from comment #11) > Comment on attachment 8787575 [details] [diff] [review] > bug1288709.patch > > Review of attachment 8787575 [details] [diff] [review]: > ----------------------------------------------------------------- > > Because these are already a bunch of separate tasks, they should be > relatively easy to split up, which will help with narrowing down issues with > the timeouts/tests. So I think it would be preferable to split off the > private mode and session store tasks to a separate file, moving the helpers > to a helper JSM that you load from both tests: > > let helpers = {}; > Cu.import(getRootDirectory(gTestPath) + "myhelpers.jsm", helpers); > let {browserLocationChanged, checkScalars, checkScalar} = helpers; > > (promiseBrowserStateRestored can just be in the new file that has the > session store task) Hm, in fact, looks like the other helpers are only used from the first few tasks, so maybe you can just leave them in this file. If you do this, make sure you use "hg copy" to create the second file to preserve blame and make review a bit easier. :P
Attached patch bug1288709.patch (obsolete) — — Splinter Review
Thanks Gijs, that's a good suggestion! I've moved the private mode / session restore tests to a separate file. I left the helpers in the files they were used in, as they are not shared across these tests.
Attachment #8787575 - Attachment is obsolete: true
Attachment #8787590 - Flags: review?(gijskruitbosch+bugs)
Comment on attachment 8787590 [details] [diff] [review] bug1288709.patch Review of attachment 8787590 [details] [diff] [review]: ----------------------------------------------------------------- rs=me Thanks for doing this!
Attachment #8787590 - Flags: review?(gijskruitbosch+bugs) → review+
Attached patch bug1288709.patch — — Splinter Review
Attachment #8787590 - Attachment is obsolete: true
Attachment #8787592 - Flags: review+
(In reply to :Gijs Kruitbosch from comment #14) > rs=me > > Thanks for doing this! You're welcome! The last patch only updates the commit message, which was referring to the old version of the code.
Keywords: checkin-needed
Pushed by ryanvm@gmail.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/36add2d31a75 Split the browser_UsageTelemetry.js test. r=gijs
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/36add2d31a75
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
status-firefox51: --- → fixed
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla51
this has started failing more frequently in the last week, right now on linux32[-stylo] debug; :dexter, I know you fixed this test case a year ago, any chance this is something you could take a quick look at? possibly just wait and see if this continues to fail more frequently is an option as well.
Status: RESOLVED → REOPENED
Flags: needinfo?(alessio.placitelli)
Resolution: FIXED → ---
Depends on: 1400202
(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #25) > this has started failing more frequently in the last week, right now on > linux32[-stylo] debug; > > :dexter, I know you fixed this test case a year ago, any chance this is > something you could take a quick look at? possibly just wait and see if > this continues to fail more frequently is an option as well. I'm dealing with this in bug 1400202. Some new test cases where added to the test file and they take longer on linux32 + stylo. Not sure why.
Flags: needinfo?(alessio.placitelli)
This is now very frequent, near perma-fail, on linux32-debug. Thanks for your efforts :Dexter!
Whiteboard: [measurement:client] → [measurement:client][stockwell needswork]
(In reply to Geoff Brown [:gbrown] from comment #30) > This is now very frequent, near perma-fail, on linux32-debug. > > Thanks for your efforts :Dexter! Cheers! Let's hope bug 1400202 fixes this. It's in review now ;)
(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #34) > I see r+ in bug 1400202 :) Heh, yeah :D Are we good to close this again (let's hope it's for good this time!)?
Flags: needinfo?(jmaher)
I see one case of this today: https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1288709&startday=2017-09-18&endday=2017-09-20&tree=all possible we close this and open a new bug for any fallout?
Flags: needinfo?(jmaher)
(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #36) > I see one case of this today: > https://brasstacks.mozilla.com/orangefactor/ > ?display=Bug&bugid=1288709&startday=2017-09-18&endday=2017-09-20&tree=all > > possible we close this and open a new bug for any fallout? Sure! Let's flag :panos on the fallout though, as these tests are owned by his team rather then the us (Telemetry folks) ;-)
Whiteboard: [measurement:client][stockwell needswork] → [measurement:client][stockwell fixed:other]
Status: REOPENED → RESOLVED
Closed: 8 years ago → 7 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: