Closed Bug 1714589 Opened 3 years ago Closed 4 months ago

Windows spidermonkey sometimes exceeds its max-run-time

Categories

(Core :: JavaScript Engine, defect, P2)

Product:
Core
Component:
JavaScript Engine
Type:
defect

Tracking

()

Status:
RESOLVED INACTIVE

People

(Reporter: gbrown, Unassigned)

References

(Blocks 1 open bug)

Details

Blocks: 1589796

Failures consistently show an exit status of 1 for jsapi-tests:

[task 2021-06-01T21:30:39.461Z] mozmake[1]: Leaving directory 'z:/task_1622566371/obj-spider/js/src'
[task 2021-06-01T21:30:39.466Z] exit status 0 for '(make-nonempty)'
[task 2021-06-01T21:30:39.466Z] exit status 0 for 'make check'
[task 2021-06-01T21:30:39.466Z] exit status 0 for 'make check-jit-test'
[task 2021-06-01T21:30:39.466Z] exit status 1 for 'jsapi-tests'
[task 2021-06-01T21:30:39.466Z] exit status 0 for 'jstests'
[task 2021-06-01T21:30:39.476Z] + BUILD_STATUS=1
[task 2021-06-01T21:30:39.476Z] + upload=1
[task 2021-06-01T21:30:39.477Z] + '[' -n '' ']'
[task 2021-06-01T21:30:39.477Z] + '[' 1 = 1 ']'
[task 2021-06-01T21:30:39.477Z] + cp -rL ./obj-spider/dist/bin/js ./obj-spider/dist/bin/jsapi-tests ./obj-spider/dist/bin/js-gdb.py Z:/task_1622566371/public/build
[task 2021-06-01T21:30:39.731Z] + cp -L ./obj-spider/mozinfo.json Z:/task_1622566371/public/build/target.mozinfo.json
[task 2021-06-01T21:30:39.754Z] + for f in '"$MOZ_FETCHES_DIR/clang/bin/llvm-symbolizer"*'
[task 2021-06-01T21:30:39.754Z] + gzip -c Z:/task_1622566371/fetches/clang/bin/llvm-symbolizer.exe
[task 2021-06-01T21:30:40.050Z] + break
[task 2021-06-01T21:30:40.050Z] + '[' -n 20210601172148 ']'
[task 2021-06-01T21:30:40.050Z] + '[' -n 8f6458084f5fc594734d392858e6c7f345307f7f ']'
[task 2021-06-01T21:30:40.050Z] + cat
[task 2021-06-01T21:30:40.063Z] + cp Z:/task_1622566371/src/mozconfig.autospider Z:/task_1622566371/public/build
[task 2021-06-01T21:30:40.074Z] + exit 1

I don't see test failures in jsapi-tests, but they do not appear to complete:

[task 2021-06-01T18:23:18.382Z] TEST-PASS | testThreadingThreadVectorMoveConstruct | ok
[task 2021-06-01T18:23:18.382Z] testThreadingThreadId
[task 2021-06-01T18:23:18.382Z] TEST-PASS | testThreadingThreadId | ok
[task 2021-06-01T18:23:18.382Z] testThreadingThreadSetName
[task 2021-06-01T18:23:18.382Z] TEST-PASS | testThreadingThreadSetName | ok
[task 2021-06-01T18:23:18.382Z] testThreadingThreadDetach
[task 2021-06-01T18:23:18.382Z] TEST-PASS | testThreadingThreadDetach | ok
[task 2021-06-01T18:23:18.382Z] testThreadingThreadJoin
[task 2021-06-01T18:23:18.382Z] TEST-PASS | testThreadingThreadJoin | ok
[taskcluster 2021-06-01T18:24:23.476Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622573063.641
[taskcluster 2021-06-01T18:41:23.767Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622574083.902
[taskcluster 2021-06-01T18:58:24.006Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622575104.132
[taskcluster 2021-06-01T19:15:24.238Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622576124.347
[taskcluster 2021-06-01T19:32:24.494Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622577144.587
[taskcluster 2021-06-01T19:49:24.696Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622578164.772
[taskcluster 2021-06-01T20:06:24.870Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622579184.939
[taskcluster 2021-06-01T20:23:25.141Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622580205.203
[taskcluster 2021-06-01T20:40:25.387Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622581225.44
[taskcluster 2021-06-01T20:57:25.642Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/G23JGgkSRfOMYCH04M2vkA/0/on/us-east-1/i-0ae56a2aaad4e1889/until/1622582245.684
[task 2021-06-01T21:13:07.979Z] testThreadiin directory z:\task_1622566371\obj-spider, running ['mozmake', 'check-jstests']
[task 2021-06-01T21:13:08.007Z] c:/mozilla-build/bin/mozmake -C js/src check-jstests

This is slightly inconsistent from one failed task to the next: different tests seem to hang, but usually one of the testThreadingThread* tests.

Component: General → JavaScript Engine
Product: Testing → Core
Version: Default → unspecified

It looks like the task calls autospider.py:

[task 2021-06-02T21:59:55.210Z] + python3 Z:/task_1622670305/src/js/src/devtools/automation/autospider.py --platform=win64 plain

which calls the jsapi-test binary:
https://searchfox.org/mozilla-central/rev/bf8d5de8528036c09590009720bc172882845b80/js/src/devtools/automation/autospider.py#572-582
using run_command:
https://searchfox.org/mozilla-central/rev/bf8d5de8528036c09590009720bc172882845b80/js/src/devtools/automation/autospider.py#369
which just uses Popen. I don't see any provision for a timeout, so I'm confused: how does jsapi-test end, apparently without completing tests, without crashing, and without timing out?

Oh, automation.py has a timer that will kill its child processes 12600 seconds (3.5 hours) after automation.py starts:
https://searchfox.org/mozilla-central/rev/bf8d5de8528036c09590009720bc172882845b80/js/src/devtools/automation/autospider.py#349-357

[task 2021-06-02T21:59:55.210Z] + python3 Z:/task_1622670305/src/js/src/devtools/automation/autospider.py --platform=win64 plain
...
[task 2021-06-03T01:29:55.571Z] testThreadiin directory z:\task_1622670305\obj-spider, running ['mozmake', 'check-jstests']

Steve, any idea what this might be? Could this be a synchronization issue where the parent process never sync with the child?

Flags: needinfo?(sphink)
Severity: -- → S4
Priority: -- → P2

I tried to re-create this problem on try with better logging. I'm not sure what to conclude, other than that there seems to be an intermittent hang shortly after testThreadingThreadJoin or testThreadingUnlockGuard.
https://treeherder.mozilla.org/jobs?repo=try&revision=facfb0afba46662cbf95a02bb5029e1797444add

Status: NEW → RESOLVED
Closed: 4 months ago
Flags: needinfo?(sphink)
Resolution: --- → INACTIVE
You need to log in before you can comment on or make changes to this bug.