1055152 - Many Object.defineProperty jstests frequently timing out with debug shells

Status: RESOLVED FIXED

(Core :: JavaScript Engine: JIT, defect)

Description

[Jeff Walden [:Waldo]]

I rebased my tree yesterday to find that a bunch of jstests (shell-only jstests, I should note) seemed to be failing due to timeouts.  From shell scrollback to one such (partial) batch of failures:

[jwalden@find-waldo-now src]$ python tests/jstests.py dbg/js/src/js ecma_5/Object/15.2.3.6
[ 2| 0| 0| 0]   4% =>                                                 | 150.0s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-10-of-32.js
[ 2| 1| 1| 0]   6% ==>                                                | 150.0s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-18-of-32.js
[ 2| 2| 2| 0]   8% ===>                                               | 150.0s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-23-of-32.js
[ 2| 3| 3| 0]  10% ====>                                              | 150.0s
TIMEOUT - ecma_5/Object/15.2.3.6-middle-redefinition-4-of-8.js
[ 2| 4| 4| 0]  12% =====>                                             | 150.0s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-14-of-32.js
[ 2| 5| 5| 0]  14% ======>                                            | 150.0s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-22-of-32.js
[ 2| 6| 6| 0]  16% =======>                                           | 150.0s
TIMEOUT - ecma_5/Object/15.2.3.6-redefinition-2-of-4.js
[ 4| 7| 7| 0]  22% ==========>                                        | 174.2s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-01-of-32.js
[ 6| 8| 8| 0]  29% =============>                                     | 300.0s
TIMEOUT - ecma_5/Object/15.2.3.6-middle-redefinition-8-of-8.js
[ 6| 9| 9| 0]  31% ==============>                                    | 300.0s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-13-of-32.js
[ 6|10|10| 0]  33% ================>                                  | 300.1s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-30-of-32.js
[ 6|11|11| 0]  35% =================>                                 | 300.1s
TIMEOUT - ecma_5/Object/15.2.3.6-redefinition-3-of-4.js
[ 6|12|12| 0]  37% ==================>                                | 300.6s
TIMEOUT - ecma_5/Object/15.2.3.6-middle-redefinition-1-of-8.js
[ 6|13|13| 0]  39% ===================>                               | 305.5s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-15-of-32.js
[ 6|14|14| 0]  41% ====================>                              | 307.6s
TIMEOUTS
    ecma_5/Object/15.2.3.6-dictionary-redefinition-10-of-32.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-18-of-32.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-23-of-32.js
    ecma_5/Object/15.2.3.6-middle-redefinition-4-of-8.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-14-of-32.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-22-of-32.js
    ecma_5/Object/15.2.3.6-redefinition-2-of-4.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-01-of-32.js
    ecma_5/Object/15.2.3.6-middle-redefinition-8-of-8.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-13-of-32.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-30-of-32.js
    ecma_5/Object/15.2.3.6-redefinition-3-of-4.js
    ecma_5/Object/15.2.3.6-middle-redefinition-1-of-8.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-15-of-32.js
FAIL (partial run -- interrupted by user)

These tests have almost all consistently passed without timeouts with regular debug, no-optimize builds on my system.  (The exception: ecma_5/Object/15.2.3.6-dictionary-redefinition-*-of-*.js have timed out semi-consistently for me, but I bumped it from x-of-8 to x-of-32 shortly before this bug's changes landed.  No timeouts with the 32-way split at the time.)

Bug 1004831's changes -- or rather, one of these three (I had to skip 55f95c3b5dbe because of "Assertion failure: success, at /home/jwalden/moz/slots/js/src/jit/JitcodeMap.cpp:107", and I had to skip 0cc8cbeb849e because of "Assertion failure: success, at /home/jwalden/moz/slots/js/src/jit/JitcodeMap.cpp:143") -- are the cause of the significant increase in timeouts:

Due to skipped revisions, the first bad revision could be any of:
changeset:   199243:55f95c3b5dbe
user:        Kannan Vijayan <[e-mail]>
date:        Wed Aug 13 11:59:55 2014 -0400
summary:     Bug 1004831 - Part 4 - Register native to bytecode mappings when new IonCode is generated. r=h4writer

changeset:   199244:0cc8cbeb849e
user:        Kannan Vijayan <[e-mail]>
date:        Wed Aug 13 11:59:56 2014 -0400
summary:     Bug 1004831 - Part 5 - Add mapping entries for baseline jitcode and ion IC jitcode. r=h4writer

changeset:   199245:410a7457f588
user:        Kannan Vijayan <[e-mail]>
date:        Wed Aug 13 11:59:58 2014 -0400
summary:     Bug 1004831 - Part 6 - Fixups to ensure that entries get rejigged curretly during BaselineDebugModeOSR. r=h4writer

The consequence of this is that I can't test my patches, because I can't be sure my patches work on these timing-out tests, so this is a blocker for me.

Comment 1

[Jeff Walden [:Waldo]]

The default test timeout is 150 seconds, I believe.  Even bumping to 300s isn't enough for at least some of these tests to pass again:

[jwalden@find-waldo-now src]$ python tests/jstests.py dbg/js/src/js --timeout 300
[ 244|   0|   0| 469]  10% ===>                                       | 313.3s
TIMEOUT - ecma_5/Object/15.2.3.6-middle-redefinition-4-of-8.js
[ 244|   1|   1| 469]  10% ===>                                       | 313.4s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-14-of-32.js
[ 244|   2|   2| 469]  10% ===>                                       | 313.6s
TIMEOUT - ecma_5/Object/15.2.3.6-dictionary-redefinition-22-of-32.js
[ 247|   3|   3| 469]  10% ===>                                       | 314.2s
TIMEOUT - ecma_5/Object/15.2.3.6-redefinition-2-of-4.js
[ 251|   4|   4| 469]  10% ===>                                       | 322.7s
TIMEOUTS
    ecma_5/Object/15.2.3.6-middle-redefinition-4-of-8.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-14-of-32.js
    ecma_5/Object/15.2.3.6-dictionary-redefinition-22-of-32.js
    ecma_5/Object/15.2.3.6-redefinition-2-of-4.js
FAIL (partial run -- interrupted by user)

Retrying with 600s seems to pass, so somewhere in the 300-600 range things start working again.  But I don't much think it's a good idea to bump the limit if it causes others' iloops to take so much longer to run.  There seems to be a pathology here that'll affect more than just this code.

On the other hand, if the effect is truly limited to debug builds only, and it's something that these tests particularly trigger, we could conditionally spot-disable just the one test, like we did already like so for another assertion in js/src/tests/ecma_5/Object/defineProperty-setup.js:

if (typeof enableStackWalkingAssertion === "function")
  enableStackWalkingAssertion(false);

Comment 2

[Luke Wagner [:luke]]

(In reply to Jeff Walden [:Waldo] (remove +bmo to email) from comment #1)
> if (typeof enableStackWalkingAssertion === "function")
>   enableStackWalkingAssertion(false);

Oh, hah, this function was removed a while ago.

Comment 3

[Kannan Vijayan [:djvj]]

Attachment: disable-verification-of-n2b.patch

This just disables the verification calls in JitIterator.

For me, it brought ecma_5/Object/15.2.3.6-dictionary-redefinition-10-of-32.js down from 1m45s to 20s.. so it should eliminate these timeout issues.

Comment 4

[Jeff Walden [:Waldo]]

Comment on attachment 8475503 [details] [diff] [review]
disable-verification-of-n2b.patch

Review of attachment 8475503 [details] [diff] [review]:
-----------------------------------------------------------------

rs=me

Comment 5

[Kannan Vijayan [:djvj]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/6e84c39a1420

Comment 6

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/6e84c39a1420