1156045 - Output exceeded 52428800 bytes, remaining output has been truncated (output was 52492419 bytes) in spidermonkey shell opt build.

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Tooru Fujisawa [:arai]]

At least it happens on linux64 warnaserr build, in jstests with --tbpl enabled.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=2a8e743957b0

> TEST-PASS | ecma/GlobalObject/1
> Output exceeded 52428800 bytes, remaining output has been truncated (output was 52492419 bytes)
> program finished with exit code 0
> elapsedTime=2138.485023
> ========= Finished 'mock_mozilla -r ...' (results: 0, elapsed: 35 mins, 47 secs) (at 2015-04-17 03:38:17.690639) =========


It didn't happen on try push at 2015-03-12:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=8c4ac78c085f
> Failure summary is empty

But happened on try push at 2014-03-14:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=71ff16219635
> Output exceeded 52428800 bytes, remaining output has been truncated (output was 52432729 bytes)

Comment 1

[Tooru Fujisawa [:arai]]

shortening args in each line may reduce output size (up to -25%)
e.g.
from
TEST-KNOWN-FAIL | js1_5/extensions/regress-352281.js | (args: "--ion-eager --ion-offthread-compile=off --ion-check-range-analysis --ion-extra-checks --no-sse3 --no-threads") | (SKIP)
to
TEST-KNOWN-FAIL | js1_5/extensions/regress-352281.js | (flags-FOO) | (SKIP)

any idea about shortened names for each flags? can we have short option for each variant? (like -I for '--ion-eager --ion-offthread-compile=off')
> TBPL_FLAGS = [
>     [], # no flags, normal baseline and ion
>     ['--ion-eager', '--ion-offthread-compile=off'], # implies --baseline-eager
>     ['--ion-eager', '--ion-offthread-compile=off',
>      '--ion-check-range-analysis', '--ion-extra-checks', '--no-sse3', '--no-threads'],
>     ['--baseline-eager'],
>     ['--baseline-eager', '--no-fpu'],
>     ['--no-baseline', '--no-ion'],
> ]

or any other better solution?


also, in more general, can we mark "Output exceeded" as a kind of failure in treeherder? (it seems to be overlooked about 1 month)

Comment 2

[Jan de Mooij [:jandem]]

(In reply to Tooru Fujisawa [:arai] from comment #1)
> shortening args in each line may reduce output size (up to -25%)

I think the problem is not the args but spammy JS tests. Things like this:

TEST-PASS | ecma/Date/15.9.5.10-4.js | (args: "--baseline-eager --no-fpu") | (new Date(-2208988800000)).getDate() = 31 expected: 31
TEST-PASS | ecma/Date/15.9.5.10-4.js | (args: "--baseline-eager --no-fpu") | (new Date(-2208902400000)).getDate() = 1 expected: 1

...and hundreds more lines from this test...

$ grep '15.9.5.10-4.js' ~/Downloads/log1 | wc -l
2208

Maybe we can only print the detailed info when the test fails? We should probably also check what mochitests do. I also wonder how much faster these tests would run without the excessive logging...

Comment 3

[Tooru Fujisawa [:arai]]

Thank you!
suppressing the detailed messages for succeeded/skipped tests reduces 85% of the entire log, wow!
https://treeherder.mozilla.org/#/jobs?repo=try&revision=9775f0730bf0

I'll post the patch after some more tests.

Comment 4

[Terrence Cole [:terrence]]

We're not supposed to be printing at all from tests. I thought we went through the suites a few months ago and made sure they weren't, so I guess this must be from recently added tests.

Comment 5

[Emanuel Hoogeveen [:ehoogeveen]]

The default for jstests.py and jit_test.py is to only print on failure (to display assertion messages), with the latter also printing on timeouts (because it doesn't differentiate between timeouts and other failures). I guess this is from the --tinderbox flag (given arai's try run) bypassing that stuff.

Comment 6

[Tooru Fujisawa [:arai]]

Attachment: Print the detailed info only when the test fails in jstests with --tinderbox option.

Made --tinderbox option to print detailed info only if the test fails.

Green on try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f81b88fea679

Comment 7

[Terrence Cole [:terrence]]

Comment on attachment 8594878 [details] [diff] [review]
Print the detailed info only when the test fails in jstests with --tinderbox option.

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

I don't think this is doing what you think it is. ResultsSink appears to only be used by jstests.py, not jit-tests.py; indeed, the jit-tests runs in the try run show that successful results are still being printed.

Comment 8

[Tooru Fujisawa [:arai]]

(In reply to Terrence Cole [:terrence] from comment #7)
> Comment on attachment 8594878 [details] [diff] [review]
> Print the detailed info only when the test fails in jstests with --tinderbox
> option.
> 
> Review of attachment 8594878 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I don't think this is doing what you think it is. ResultsSink appears to
> only be used by jstests.py, not jit-tests.py; indeed, the jit-tests runs in
> the try run show that successful results are still being printed.

Sorry if my commit message was wrong.
I'm going to suppress extra message printed by test itself (e.g. in comment #2) if the test doesn't fail, and keep results printed in both case.

I didn't touch jit-test.py, since it seems to print no other message than result (PASS/FAIL, path, exit code, args),
after this patch applied, jstests.py also prints minimum result for each file (PASS/FAIL, path, args).

Does this make sense?

Comment 9

[Terrence Cole [:terrence]]

(In reply to Tooru Fujisawa [:arai] from comment #8)
>
> Does this make sense?

No, this still doesn't make any sense to me. The succeeding file is ~1MiB and the failing file is >5MiB, so something else /must/ be going on here.

Comment 10

[Terrence Cole [:terrence]]

And, looking at the actual test output, it's pretty obvious what the proximate cause is: the "succeeding" run's jstests.py invocation is only running with args="" and the "failing" run is running with the full set of tbpl flags.

And the reason the files are so big at all is that the jstests.py harness is outputting a detailed result message of every assertion -- the intent is certainly to squelch the test output on success, so we should do that to, but the real problem here is that we are not running all tests.

Comment 11

[Terrence Cole [:terrence]]

Err.. 10MiB and 50MiB, not 1 and 5.

Comment 12

[Terrence Cole [:terrence]]

Attachment: jstests_only_print_output_on_failure-v0.diff

The reason the logs are so big is that we're printing all assertion output, even on success. That is not the intent: it should only be shown if result.result != PASS, so this patch simply adds that condition before printing the test's output.

Comment 13

[Terrence Cole [:terrence]]

We appear to be skipping the full set of --tbpl tests in autospider sometimes because of this:

if [[ "$VARIANT" = "warnaserr" ]]; then
    export JSTESTS_EXTRA_ARGS=--tbpl
fi

Steve, do you remember what's up with this?

Comment 14

[Tooru Fujisawa [:arai]]

Comment on attachment 8596037 [details] [diff] [review]
jstests_only_print_output_on_failure-v0.diff

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

Thanks, this seems to be simpler and better than mine :)
forwarding r? to sfink, since I'm not a module peer.

>We appear to be skipping the full set of --tbpl tests in autospider sometimes because of this:
It's because --tbpl takes so long time for other variants, and hit timeout (mostly debug builds)
see bug 1101662 comment #11.

Comment 15

[Terrence Cole [:terrence]]

Yes, probably because we're running all the tests without the jits. I'd think we could use a --tbpl-debug that just runs the fastest 3 or 4 variants.

Comment 16

[Tooru Fujisawa [:arai]]

Yeah, I agree, filed as bug 1157354.

Comment 17

[Steve Fink [:sfink] [:s:]]

(In reply to Tooru Fujisawa [:arai] from comment #14)
> Comment on attachment 8596037 [details] [diff] [review]
> jstests_only_print_output_on_failure-v0.diff
> 
> >We appear to be skipping the full set of --tbpl tests in autospider sometimes because of this:
> It's because --tbpl takes so long time for other variants, and hit timeout
> (mostly debug builds)
> see bug 1101662 comment #11.

Right.

(In reply to Terrence Cole [:terrence] from comment #15)
> Yes, probably because we're running all the tests without the jits. I'd
> think we could use a --tbpl-debug that just runs the fastest 3 or 4 variants.

Yes. Though... uh... "--tinderbox" and "--tbpl" are perhaps not the best names for these options. We really ought to make them self-descriptive instead of referring to obsolete continuous integration systems.

Comment 18

[Terrence Cole [:terrence]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=360bf586431a

Comment 19

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ffb9a4e7761e

Comment 20

[Carsten Book [:Tomcat]]

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

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/b8a4ed23ed26

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr38/rev/1c666cd1d63e