Closed Bug 1212398 Opened 9 years ago Closed 5 years ago

Intermittent test_parse_rule.html | Test timed out.

Categories

(Core :: Layout, defect, P3)

Product:
Core
Component:
Layout
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla67
Tracking Flags:
Tracking Status
firefox67 --- fixed

People

(Reporter: KWierso, Assigned: m_kato)

References

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered][stockwell disable-recommended])

Attachments

(1 file)

Bug 1212398 - Extend timeout value for test_parse_rule.html.
47 bytes, text/x-phabricator-request
Details | Review 
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
There are 41 failures in the past 7 days. All of them on android-4-3-armv7-api16 debug.
Most recent failure: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=154862962
Relevant part of the log: 
[task 2018-01-09T00:04:48.289Z] 00:04:48     INFO -  Buffered messages logged at 00:03:53
2148
[task 2018-01-09T00:04:48.289Z] 00:04:48     INFO -  360 INFO TEST-PASS | layout/style/test/test_parse_rule.html | #a:before {content: 'This is \a'}
2149
[task 2018-01-09T00:04:48.289Z] 00:04:48     INFO -  Buffered messages logged at 00:03:55
2150
[task 2018-01-09T00:04:48.290Z] 00:04:48     INFO -  361 INFO TEST-PASS | layout/style/test/test_parse_rule.html | .a::before {content: 'This is \a'}#a:: before {content: 'FAIL'}
2151
[task 2018-01-09T00:04:48.290Z] 00:04:48     INFO -  Buffered messages logged at 00:03:56
2152
[task 2018-01-09T00:04:48.290Z] 00:04:48     INFO -  362 INFO TEST-PASS | layout/style/test/test_parse_rule.html | .a::before {content: 'This is \a'}#a ::before {content: 'FAIL'}
2153
[task 2018-01-09T00:04:48.291Z] 00:04:48     INFO -  Buffered messages logged at 00:03:59
2154
[task 2018-01-09T00:04:48.291Z] 00:04:48     INFO -  363 INFO TEST-PASS | layout/style/test/test_parse_rule.html | #a::before {content: 'This is \a
2155
[task 2018-01-09T00:04:48.291Z] 00:04:48     INFO -  364 INFO TEST-PASS | layout/style/test/test_parse_rule.html | Sanity check for rule: div {background: blue}
2156
[task 2018-01-09T00:04:48.291Z] 00:04:48     INFO -  Buffered messages logged at 00:04:01
2157
[task 2018-01-09T00:04:48.292Z] 00:04:48     INFO -  365 INFO TEST-PASS | layout/style/test/test_parse_rule.html | #a {background: url() blue}
2158
[task 2018-01-09T00:04:48.292Z] 00:04:48     INFO -  Buffered messages logged at 00:04:04
2159
[task 2018-01-09T00:04:48.293Z] 00:04:48     INFO -  366 INFO TEST-PASS | layout/style/test/test_parse_rule.html | #a {background: url(怀) blue}
2160
[task 2018-01-09T00:04:48.293Z] 00:04:48     INFO -  367 INFO TEST-PASS | layout/style/test/test_parse_rule.html | Sanity check for rule: div {border-style: dotted}
2161
[task 2018-01-09T00:04:48.293Z] 00:04:48     INFO -  Buffered messages logged at 00:04:06
2162
[task 2018-01-09T00:04:48.293Z] 00:04:48     INFO -  368 INFO TEST-PASS | layout/style/test/test_parse_rule.html | div {border-style: dotted}#a {border: dotted 0 -moz-menuhover}
2163
[task 2018-01-09T00:04:48.294Z] 00:04:48     INFO -  Buffered messages logged at 00:04:07
2164
[task 2018-01-09T00:04:48.294Z] 00:04:48     INFO -  369 INFO TEST-PASS | layout/style/test/test_parse_rule.html | div {border-style: dotted}#a {border: solid 0-moz-menuhover}
2165
[task 2018-01-09T00:04:48.295Z] 00:04:48     INFO -  Buffered messages finished
2166
[task 2018-01-09T00:04:48.295Z] 00:04:48     INFO -  370 INFO TEST-UNEXPECTED-FAIL | layout/style/test/test_parse_rule.html | Test timed out.
2167
[task 2018-01-09T00:04:48.296Z] 00:04:48     INFO -      reportError@SimpleTest/TestRunner.js:121:7
2168
[task 2018-01-09T00:04:48.296Z] 00:04:48     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
2169
[task 2018-01-09T00:04:48.296Z] 00:04:48     INFO -  371 INFO TEST-OK | layout/style/test/test_parse_rule.html | took 325661ms
2170
[task 2018-01-09T00:04:48.297Z] 00:04:48     INFO -  372 ERROR /tests/layout/style/test/test_parse_rule.html logged result after SimpleTest.finish(): Test timed out.
2171
[task 2018-01-09T00:04:48.297Z] 00:04:48     INFO -  373 INFO None374 INFO TEST-START | layout/style/test/test_parse_url.html
2172
[task 2018-01-09T00:04:48.297Z] 00:04:48     INFO -  375 INFO TEST-OK | layout/style/test/test_parse_url.html | took 8491ms
2173
[task 2018-01-09T00:04:48.297Z] 00:04:48     INFO -  376 INFO None377 INFO TEST-START | layout/style/test/test_parser_diagnostics_unprintables.html
2174
[task 2018-01-09T00:06:09.491Z] 00:06:09     INFO -  378 INFO TEST-OK | layout/style/test/test_parser_diagnostics_unprintables.html | took 74547ms
2175
[task 2018-01-09T00:06:09.494Z] 00:06:09     INFO -  379 INFO None380 INFO TEST-START | layout/style/test/test_pixel_lengths.html
2176
[task 2018-01-09T00:06:09.496Z] 00:06:09     INFO -  381 INFO TEST-OK | layout/style/test/test_pixel_lengths.html | took 6566ms
2177
[task 2018-01-09T00:06:09.497Z] 00:06:09     INFO -  382 INFO None383 INFO TEST-START | layout/style/test/test_pointer-events.html
2178
[task 2018-01-09T00:07:24.075Z] 00:07:24     INFO -  384 INFO TEST-OK | layout/style/test/test_pointer-events.html | took 22777ms
2179
[task 2018-01-09T00:07:24.076Z] 00:07:24     INFO -  385 INFO None386 INFO TEST-START | layout/style/test/test_position_float_display.html
2180
[task 2018-01-09T00:07:24.084Z] 00:07:24     INFO -  387 INFO TEST-OK | layout/style/test/test_position_float_display.html | took 12160ms
2181
[task 2018-01-09T00:07:24.085Z] 00:07:24     INFO -  388 INFO None389 INFO TEST-START | Shutdown
2182
[task 2018-01-09T00:07:24.085Z] 00:07:24     INFO -  390 INFO Passed:  107173
2183
[task 2018-01-09T00:07:24.086Z] 00:07:24  WARNING -  391 INFO Failed:  2
2184
[task 2018-01-09T00:07:24.086Z] 00:07:24  WARNING -  One or more unittests failed.
2185
[task 2018-01-09T00:07:24.087Z] 00:07:24     INFO -  392 INFO Todo:    24
2186
[task 2018-01-09T00:07:24.088Z] 00:07:24     INFO -  393 INFO Mode:    non-e10s
2187
[task 2018-01-09T00:07:24.088Z] 00:07:24     INFO -  394 INFO Slowest: 325661ms - /tests/layout/style/test/test_parse_rule.html
2188
[task 2018-01-09T00:07:24.088Z] 00:07:24     INFO -  395 INFO SimpleTest FINISHED
2189
[task 2018-01-09T00:07:24.311Z] 00:07:24     INFO -  INFO | automation.py | Application ran for: 0:55:44.917355
2190
[task 2018-01-09T00:07:24.312Z] 00:07:24     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmp1Te9eGpidlog
2191
[task 2018-01-09T00:07:25.321Z] 00:07:25     INFO -  Stopping web server
2192
[task 2018-01-09T00:07:25.340Z] 00:07:25     INFO -  Stopping web socket server
2193
[task 2018-01-09T00:07:25.361Z] 00:07:25     INFO -  Stopping ssltunnel
2194
[task 2018-01-09T00:07:25.383Z] 00:07:25     INFO -  leakcheck | refcount logging is off, so leaks can't be detected!
2195
[task 2018-01-09T00:07:25.384Z] 00:07:25     INFO -  runtests.py | Running tests: end.

:jet Could you please take a look?
Flags: needinfo?(bugs)
Whiteboard: [stockwell needswork]
(In reply to Noemi Erli[:noemi_erli] from comment #19)
> There are 41 failures in the past 7 days. All of them on
> android-4-3-armv7-api16 debug.

Oh, Joy!

> :jet Could you please take a look?

OK. This is timing out after completing the last test in this file. Quite likely for the same reason we added this lovely workaround to this test:
https://searchfox.org/mozilla-central/source/layout/style/test/test_parse_rule.html#252

What if we knock that down to 0. Jan: WDYT?
Flags: needinfo?(bugs) → needinfo?(jh+bugzilla)
Sure, worth a try, although I guess that the gain from that won't be nearly as dramatic as the original one when going from the default 50 down to 4.
Flags: needinfo?(jh+bugzilla)
In the last 7 days we have 30 failures.
They occur on android-4-3-armv7-api16 and the affected builds type are debug and opt.
Failure log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=161925297&lineNumber=2660

[task 2018-02-13T12:38:57.766Z] 12:38:57     INFO -  \00000a '}
[task 2018-02-13T12:38:57.766Z] 12:38:57     INFO -  Buffered messages finished
[task 2018-02-13T12:38:57.766Z] 12:38:57     INFO -  346 INFO TEST-UNEXPECTED-FAIL | layout/style/test/test_parse_rule.html | Test timed out.
[task 2018-02-13T12:38:57.766Z] 12:38:57     INFO -      reportError@SimpleTest/TestRunner.js:121:7
[task 2018-02-13T12:38:57.766Z] 12:38:57     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
Flags: needinfo?(bugs)
Whiteboard: [stockwell unknown] → [stockwell needswork]
Apart from the quick fix of cutting down on any remaining session history overhead or simply requesting a longer timeout, this actually means that we've had some performance regression in that area.

While the time taken to complete the test had been borderline for some time already, the failure rate started really picking up in the week ending 2017-11-27 02:18 CET, which coincidentally was the week that Stylo was enabled by default on Android (bug 1366049).
(In reply to Jan Henning [:JanH] from comment #28)
> Apart from the quick fix of cutting down on any remaining session history
> overhead or simply requesting a longer timeout, this actually means that
> we've had some performance regression in that area.
> 
> While the time taken to complete the test had been borderline for some time
> already, the failure rate started really picking up in the week ending
> 2017-11-27 02:18 CET, which coincidentally was the week that Stylo was
> enabled by default on Android (bug 1366049).

That sounds... plausible. Stylo is known to be slower on ARM, see bug 1430706.
See Also: → 1430706
should we extend the timeout?
(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #30)
> should we extend the timeout?

Yes. We should also fix the test as per comment 21.
Kato-san: can you make that change? Thx!
Flags: needinfo?(bugs) → needinfo?(m_kato)
Assignee: nobody → m_kato
Flags: needinfo?(m_kato)
Debug build of Stylo's CSS parser is extreme slow due to no LTO.  Even if opt build, no-LTO is 2x-3x slower than LTO on  Android's real device.

(In reply to Cosmin Sabou [:CosminS] from comment #67)

This has an abrupt spike in failure rate after this merge: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&searchStr=android%2C4.3%2Capi16%2B%2Cdebug%2Cmochitests%2Ctest-android-em-4.3-arm7-api-16%2Fdebug-mochitest-57%2Cm%2857%29&selectedJob=230043476

https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?changeset=6924dd16f7b1e2e6ce71a8eb4cbe330d3e4745dc

maybe from Bug 1529607? kato, could you take a look over it? thank you.

This failure issue is that Android/arm build runs on emulator, and CSS parser of Stylo is a little slow than original C++ parser.

Flags: needinfo?(m_kato)

If we can change timeout value to a little long, this doesn't occur. Stylo's CSS parser is fast on x86 device, but arm is a little slow.

Based on comment 72 it sounds like the test was flaky and relying on timing so the test should be fixed by a relevant peer.

Flags: needinfo?(MattN+bmo)

Although debug build of Android/arm runs on emulator, test_parse_rule.html
sometimes run over 5 min. So we should extend timeout value for this.

Bug is actively being worked on, removing the disable whiteboard tag.

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]
Pushed by m_kato@ga2.so-net.ne.jp:
https://hg.mozilla.org/integration/autoland/rev/b43a92afda7d
Extend timeout value for test_parse_rule.html. r=emilio

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

Status: NEW → RESOLVED
Closed: 5 years ago
status-firefox67: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla67
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: