Closed Bug 1156045 Opened 6 years ago Closed 6 years ago

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

Categories

(Core :: JavaScript Engine, defect)

x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla40
Tracking Status
firefox39 --- fixed
firefox40 --- fixed
firefox-esr38 --- fixed

People

(Reporter: arai, Assigned: terrence)

Details

Attachments

(1 file, 1 obsolete file)

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)
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)
Flags: needinfo?(terrence)
(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...
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.
Flags: needinfo?(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.
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.
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
Assignee: nobody → arai.unmht
Attachment #8594878 - Flags: review?(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.
Attachment #8594878 - Flags: review?(terrence)
(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?
Flags: needinfo?(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.
Flags: needinfo?(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.
Err.. 10MiB and 50MiB, not 1 and 5.
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.
Assignee: arai.unmht → terrence
Attachment #8594878 - Attachment is obsolete: true
Status: NEW → ASSIGNED
Attachment #8596037 - Flags: review?(arai.unmht)
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?
Flags: needinfo?(sphink)
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.
Attachment #8596037 - Flags: review?(sphink)
Attachment #8596037 - Flags: review?(arai.unmht)
Attachment #8596037 - Flags: feedback+
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.
Yeah, I agree, filed as bug 1157354.
(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.
Flags: needinfo?(sphink)
Attachment #8596037 - Flags: review?(sphink) → review+
https://hg.mozilla.org/mozilla-central/rev/ffb9a4e7761e
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla40
You need to log in before you can comment on or make changes to this bug.