Closed Bug 1487506 Opened 7 years ago Closed 6 years ago

Intermittent test262/built-ins/RegExp/CharacterClassEscapes/character-class-non-digit-class-escape-flags-u.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") | (TIMEOUT) [300.1 s]

Categories

(Core :: JavaScript Engine, defect, P1)

Product:
Core
Component:
JavaScript Engine
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla65
Tracking Flags:
Tracking Status
firefox64 --- wontfix
firefox65 --- fixed

People

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

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(1 file)

Disable some assertions that together take up about half of the runtime of a test that times out in debug builds on infra
3.72 KB, patch
Details | Diff | Splinter Review
Filed by: ncsoregi [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=196707846&repo=autoland https://queue.taskcluster.net/v1/task/JSxj4jdtTj63PMexyZwyRw/runs/0/artifacts/public/logs/live_backing.log [task 2018-08-30T17:04:44.781Z] TEST-PASS | non262/Date/regress-452786.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") [0.2 s] [task 2018-08-30T17:04:44.781Z] {"action": "test_start", "jitflags": [], "pid": 107221, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "non262/Date/regress-452786.js", "thread": "main", "time": 1535648684.611909} [task 2018-08-30T17:04:44.782Z] {"action": "test_end", "extra": {"jitflags": [], "pid": 107221, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so"}, "jitflags": [], "pid": 107221, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "status": "PASS", "test": "non262/Date/regress-452786.js", "thread": "main", "time": 1535648684.78171} [task 2018-08-30T17:04:44.961Z] TEST-PASS | non262/Date/constructor-convert-all-arguments.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") [0.2 s] [task 2018-08-30T17:04:44.961Z] {"action": "test_start", "jitflags": [], "pid": 107231, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "non262/Date/constructor-convert-all-arguments.js", "thread": "main", "time": 1535648684.790425} [task 2018-08-30T17:04:44.962Z] {"action": "test_end", "extra": {"jitflags": [], "pid": 107231, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so"}, "jitflags": [], "pid": 107231, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "status": "PASS", "test": "non262/Date/constructor-convert-all-arguments.js", "thread": "main", "time": 1535648684.961653} [task 2018-08-30T17:04:45.093Z] TEST-UNEXPECTED-FAIL | test262/built-ins/RegExp/CharacterClassEscapes/character-class-non-digit-class-escape-flags-u.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") | (TIMEOUT) [300.1 s] [task 2018-08-30T17:04:45.094Z] {"action": "test_start", "jitflags": [], "pid": 104077, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "test262/built-ins/RegExp/CharacterClassEscapes/character-class-non-digit-class-escape-flags-u.js", "thread": "main", "time": 1535648385.025578} [task 2018-08-30T17:04:45.094Z] {"action": "test_end", "extra": {"jitflags": [], "pid": 104077, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so"}, "jitflags": [], "pid": 104077, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "status": "FAIL", "test": "test262/built-ins/RegExp/CharacterClassEscapes/character-class-non-digit-class-escape-flags-u.js", "thread": "main", "time": 1535648685.093962} [task 2018-08-30T17:04:45.177Z] TEST-PASS | non262/String/normalize-generateddata-part2.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") [18.1 s] [task 2018-08-30T17:04:45.178Z] {"action": "test_start", "jitflags": [], "pid": 104452, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "non262/String/normalize-generateddata-part2.js", "thread": "main", "time": 1535648667.044102} [task 2018-08-30T17:04:45.178Z] {"action": "test_end", "extra": {"jitflags": [], "pid": 104452, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so"}, "jitflags": [], "pid": 104452, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "status": "PASS", "test": "non262/String/normalize-generateddata-part2.js", "thread": "main", "time": 1535648685.178009} [task 2018-08-30T17:04:45.198Z] TEST-PASS | non262/Date/15.9.4.2.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") [0.2 s]
Retriggers were green.
Flags: needinfo?(aryx.bugmail)
This bug failed 35 times in the last 7 days. Failures only occur on linux64 on debug build type. Log: https://treeherder.mozilla.org/logviewer.html#?job_id=202903992&repo=mozilla-inbound&lineNumber=117574 [task 2018-10-02T16:40:24.873Z] TEST-PASS | non262/regress/regress-698028-3.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") [0.1 s] [task 2018-10-02T16:40:24.873Z] {"action": "test_start", "jitflags": [], "pid": 102605, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "non262/regress/regress-698028-3.js", "thread": "main", "time": 1538498424.739182} [task 2018-10-02T16:40:24.873Z] {"action": "test_end", "extra": {"jitflags": [], "pid": 102605, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so"}, "jitflags": [], "pid": 102605, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "status": "PASS", "test": "non262/regress/regress-698028-3.js", "thread": "main", "time": 1538498424.873242} [task 2018-10-02T16:40:24.880Z] TEST-PASS | non262/regress/regress-452498-129.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") [0.1 s] [task 2018-10-02T16:40:24.880Z] {"action": "test_start", "jitflags": [], "pid": 102615, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "non262/regress/regress-452498-129.js", "thread": "main", "time": 1538498424.7505672} [task 2018-10-02T16:40:24.880Z] {"action": "test_end", "extra": {"jitflags": [], "pid": 102615, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so"}, "jitflags": [], "pid": 102615, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "status": "PASS", "test": "non262/regress/regress-452498-129.js", "thread": "main", "time": 1538498424.88017} [task 2018-10-02T16:40:24.900Z] TEST-UNEXPECTED-FAIL | test262/built-ins/RegExp/CharacterClassEscapes/character-class-non-digit-class-escape-flags-u.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") | (TIMEOUT) [300.0 s] [task 2018-10-02T16:40:24.900Z] {"action": "test_start", "jitflags": [], "pid": 53517, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "test262/built-ins/RegExp/CharacterClassEscapes/character-class-non-digit-class-escape-flags-u.js", "thread": "main", "time": 1538498124.880033} [task 2018-10-02T16:40:24.901Z] {"action": "test_end", "extra": {"jitflags": [], "pid": 53517, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so"}, "jitflags": [], "pid": 53517, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "status": "FAIL", "test": "test262/built-ins/RegExp/CharacterClassEscapes/character-class-non-digit-class-escape-flags-u.js", "thread": "main", "time": 1538498424.900684} [task 2018-10-02T16:40:24.942Z] TEST-PASS | non262/regress/regress-479353.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") [0.1 s] [task 2018-10-02T16:40:24.942Z] {"action": "test_start", "jitflags": [], "pid": 102625, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "non262/regress/regress-479353.js", "thread": "main", "time": 1538498424.793633} [task 2018-10-02T16:40:24.943Z] {"action": "test_end", "extra": {"jitflags": [], "pid": 102625, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so"}, "jitflags": [], "pid": 102625, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "status": "PASS", "test": "non262/regress/regress-479353.js", "thread": "main", "time": 1538498424.942764} [task 2018-10-02T16:40:24.958Z] TEST-PASS | non262/regress/regress-567152.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") [0.1 s] [task 2018-10-02T16:40:24.959Z] {"action": "test_start", "jitflags": [], "pid": 102635, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "non262/regress/regress-567152.js", "thread": "main", "time": 1538498424.8323421} [task 2018-10-02T16:40:24.959Z] {"action": "test_end", "extra": {"jitflags": [], "pid": 102635, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so"}, "jitflags": [], "pid": 102635, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "status": "PASS", "test": "non262/regress/regress-567152.js", "thread": "main", "time": 1538498424.959088} [task 2018-10-02T16:40:24.959Z] TEST-KNOWN-FAIL | non262/regress/regress-404755.js | (args: "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so") | (SKIP) [0.0 s] [task 2018-10-02T16:40:24.960Z] {"action": "test_start", "jitflags": [], "pid": 72942, "shell_args": "--dll /builds/worker/workspace/breakpad-tools/libbreakpadinjector.so", "source": "jstests", "test": "non262/regress/regress-404755.js", "thread": "main", "time": 1538498424.960023} sdetar: Can you please take a look at this bug?
Flags: needinfo?(sdetar)
QA Contact: sdetar
Whiteboard: [stockwell needswork]
Jason, could you help me find the right person on our team to look at this bug?
Flags: needinfo?(sdetar) → needinfo?(jorendorff)
I took a quick look. This is a timeout due to a slow test. The test builds a string about 2 million characters long, then does a string.replace(regexp) on it such that the regexp matches 2 million times, matching each character individually. In a build with --disable-debug --enable-optimize, this takes about 0.1 seconds to run on my MacBook. In a build with --disable-debug --disable-optimize, it takes 0.6 seconds. In a build with --enable-debug --enable-optimize, it takes 23 seconds. In a build with --enable-debug --disable-optimize, it takes 5 minutes. I guess the immediate question is, why do we never get out of the interpreter?
There's some relevant discussion in https://mozilla.logbot.info/jsapi/20181005 (not yet there as I'm writing this, but it should appear later, I think.) I would normally just add a `slow script` line to js/src/tests/jstests.list and drop this; but there are multiple weird things going on here. Cc-ing André, who has previously looked at slow test262 tests... but this runs in 0.1 second in an opt build. Blaming the test in anyway has to be missing the point. The real question is why debug builds are sooooooo unreasonably slow on this.
One more time: --disable-debug --enable-optimize: 0.230 seconds --enable-debug --enable-optimize: 22.678 seconds I can buy --enable-optimize being a 5x or even 13x speedup, because we lean so hard on basic C++ compiler optimizations (inlining, constant propagation, DCE). But it's bad that --disable-debug is a >100x speedup. The test isn't slow. An assertion somewhere in our C++ is slow.
Assignee: nobody → jorendorff
Status: NEW → ASSIGNED
Brian, I think this might be JS_HAS_PROTECTED_DATA_CHECKS. Would you mind taking a look? The attached patch cuts out a few other assertions too; it halves the run time, in an --enable-debug --enable-optimize build.
Assignee: jorendorff → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(jorendorff) → needinfo?(bhackett1024)
QA Contact: sdetar
(In reply to Jason Orendorff [:jorendorff] from comment #15) > Brian, I think this might be JS_HAS_PROTECTED_DATA_CHECKS. Would you mind > taking a look? > > The attached patch cuts out a few other assertions too; it halves the run > time, in an --enable-debug --enable-optimize build. It's unfortunate the TLS accesses are so slow, but it would be fine to disable the protected data checks or change them to only run in certain builds (is there a configuration that is more debug-y than --enable-debug? It seems like we've had issues with slow DEBUG checks before...). These were added for the changes for cooperatively multithreaded runtimes but AFAIK there are no plans to resume that work.
Flags: needinfo?(bhackett1024)
I want to check to see if these assertions make the tests as a whole noticeably slower -- more likely they only affect a handful of tests. I don't have time for it today. The fix might be to skip the test, something like // |reftest| skip-if(this.getBuildConfiguration&&getBuildConfiguration().debug)
Assignee: nobody → jorendorff
Priority: P5 → P3
This has failed 3 of the last 6 SM(arm64) runs on Beta. Anything we can do to bump the priority of this bug and improve the reliability of this Tier 1 test suite?
Flags: needinfo?(jorendorff)
In the last 7 days there have been 50 occurrences on Linux 64 debug.
There are 45 failures in the last 7 days. They occur on linux64 debug. Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=210204026&repo=autoland&lineNumber=126978 jorendorff: Hi, Do you have any updates on this? Thank you!
Bumping to P1 in hopes of finding time to fix it next week.
Priority: P3 → P1
status-firefox64: --- → affected
status-firefox65: --- → affected
Flags: needinfo?(jorendorff)
Flags: needinfo?(jorendorff)
Fixed by revision fa95b1364b4a (bug 1508680, 2018 November 21) importing a new version of the test from upstream. It looks like the fix is riding the trains; recent reports are only in mozilla-beta and most recently only mozilla-release.
Status: NEW → RESOLVED
Closed: 6 years ago
Flags: needinfo?(jorendorff)
Resolution: --- → FIXED
Assignee: jorendorff → jcoppeard
status-firefox64: affected → wontfix
status-firefox65: affected → fixed
Target Milestone: --- → mozilla65
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: