669412 - Fennec reftest logs have blocks of "before 389120, after 389120, break 05900000" interrupting test output mid-line

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Daniel Holbert [:dholbert]]

Fennec reftest logs have blocks of text like this:
> http://tinderbox.mozilla.org/showlog.cgi?log=Try/1309798375.1309799832.2127.gz#err0
that interject into test output mid-line, making the test output impossible to read & to pass into reftest-analyzer without hand-editing the text.

A few examples from this shortlog (with long lines & repeated lines portions snipped out):
http://tinderbox.mozilla.org/showlog.cgi?log=Try/1309798375.1309799832.2127.gz

In this case, the REFTEST TEST-START line is interrupted:
{
> REFTEST TEST-START | http://10.250.48.211:30089/tests/layout/reftests/svg/as-image/img-width-meet-2.html
> REFTEST TEST-START | http://10.250.48.211:30089/tests/layout/reftests/svg/as-ibefore 389120, after 389120, break 05900000
> before 389120, after 389120, break 05900000
> before 389120, after 389120, break 05900000
> before 389120, after 389120, break 05900000
[***SNIP -- removed 110 instances of this same line***]
> before 389120, after 389120, break 05900000
> before 389120, after 389120, break 05900000
> before 389120, after 389120, break 05900000
> mage/img-width-meet-2-ref.html
> REFTEST TEST-PASS | http://10.250.48.211:30089/tests/layout/reftests/svg/as-image/img-width-meet-2.html | image comparison (==)
}


And in this case, the "IMAGE 2" data URI is interrupted, mid-URI:
{
> REFTEST TEST-UNEXPECTED-FAIL | http://10.250.48.211:30089/tests/layout/reftests/svg/as-image/border-image-simple-1.html | image comparison (==) 
> REFTEST   IMAGE 1 (TEST): data:image/png;base64,iV[***SNIP***]ggg==
> REFTEST   IMAGE 2 (REFERENCE): data:image/png;base64,iV[***SNIP***]ZAQIbefore 389120, after 389120, break 05900000
> before 389120, after 389120, break 05900000
[***SNIP***]
> before 389120, after 389120, break 05900000
> before 389120, after 389120, break 05900000
> AACQ[***SNIP***]QmCC
> REFTEST number of differing pixels: 1164
}

Comment 1

[Daniel Holbert [:dholbert]]

(In reply to comment #0)
> Fennec reftest logs have blocks of text like this:
> > http://tinderbox.mozilla.org/showlog.cgi?log=Try/1309798375.1309799832.2127.gz#err0

Sorry, copy-paste fail.  I of course meant blocks of text like this:
> before 389120, after 389120, break 05900000

Comment 2

[Josh Matthews [:jdm]]

I'm pretty sure this occurs because we're combining the output logs of two processes, the xpcshell one running httpd.js and generating the gc messages, and the main fennec process output on device.

Comment 3

[cmtalbert]

Oh sorry, missed this bug.  Yes, I'm pretty sure comment 2 is correct.  For some of the "build Faster" stuff we're looking into different ways to use the httpd.js server or to better separate it from the underlying test harness.  

Usually httpd.js is silent to a fault (literally).  Is there a reason why this message is left in?  Or is the message coming out of Gecko and is only triggered by the httpd.js xpcshell process?

If the message is coming up out of Gecko, then one of the items on our list for running this entire shebang faster should fix it -- we're going to investigate using a packaged httpd.js/xpcshell+friends from an opt build for our webserver.  There's no need (and no use really) in using a debug build for the webserver.  That should nix these messages.

If that's what's happening here (messages bubbling up out of gecko) then we can move the mobile architecture to that new system in parallel (as the mobile setup already contains the proper buildbot steps to do it, they just need to be redirected to an opt build).

Comment 4

[Josh Matthews [:jdm]]

Yes, it's a message from Gecko, not the httpd.js code.

Comment 5

[Josh Matthews [:jdm]]

My mistake, it was actually xpcshell-specific. It's now also gone. http://hg.mozilla.org/mozilla-central/rev/16c077af20cf

Comment 6

[Daniel Holbert [:dholbert]]

(In reply to comment #5)
> My mistake, it was actually xpcshell-specific.

Is xpcshell running during reftests?  Note that comment 0 is a reftest log.

> It's now also gone.
> http://hg.mozilla.org/mozilla-central/rev/16c077af20cf

Not gone -- just ran across it in a services-central reftest log:
http://tinderbox.mozilla.org/showlog.cgi?log=Services-Central/1311825329.1311827077.2035.gz
Android Tegra 250 services-central opt test reftest-2 on 2011/07/27 20:55:29

In that log (as in comment 0), it interrupts the reftest snapshot :-/

It's in the most recent reftest logs on m-c, too:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1311813929.1311814796.10546.gz
Android Tegra 250 mozilla-central opt test reftest-1 on 2011/07/27 17:45:29
{
before 438272, after 438272, break 057ff000
}

Comment 7

[Daniel Holbert [:dholbert]]

aha, it's in ipc/testshell/XPCShellEnvironment.cpp:

405 static JSBool
406 GC(JSContext *cx,
407    uintN argc,
408    jsval *vp)
409 {
410     JSRuntime *rt;
411     uint32 preBytes, postBytes;
412 
413     rt = JS_GetRuntime(cx);
414     preBytes = JS_GetGCParameter(rt, JSGC_BYTES);
415     JS_GC(cx);
416     postBytes = JS_GetGCParameter(rt, JSGC_BYTES);
417     fprintf(stdout, "before %lu, after %lu, break %08lx\n",
418            (unsigned long)preBytes, (unsigned long)postBytes,
http://mxr.mozilla.org/mozilla-central/source/ipc/testshell/XPCShellEnvironment.cpp#405

Comment 8

[Daniel Holbert [:dholbert]]

Attachment: fix: remove noisy fprintf

Comment 9

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Comment on attachment 549138 [details] [diff] [review]
fix: remove noisy fprintf

rs=me

Comment 10

[Daniel Holbert [:dholbert]]

http://hg.mozilla.org/integration/mozilla-inbound/rev/4f686c29a28e

Comment 11

[Marco Bonardo [:mak]]

http://hg.mozilla.org/mozilla-central/rev/4f686c29a28e

Comment 12

[Daniel Holbert [:dholbert]]

Grr, this seems to still be happening:
http://tinderbox.mozilla.org/showlog.cgi?log=Mozilla-Inbound/1313095651.1313097152.28852.gz
{REFTEST TEST-START | http://10.250.48.201:30061/tbefore 393216, after 393216, break 05800000
before 393216, after 393216, break 05800000
[...]
before 393216, after 393216, break 05800000
ests/layout/reftests/svg/filters/feComponentTransfer-2.svg
}

Looks like there's one remaining instance of this in js/src/shell/js.cpp -- I will destroy it.

Comment 13

[Daniel Holbert [:dholbert]]

Hm, looks like that instance (in js/src/shell/js.cpp) prints to a string rather than to the console, as described in the last chunk of bug 492124 comment 0.  I guess some caller is printing out that string...?

Comment 14

[Daniel Holbert [:dholbert]]

Reopening, as this isn't fully fixed yet, and I don't immediately know who's printing out the string returned in comment 13.

Comment 15

[Daniel Holbert [:dholbert]]

Attachment: followup: fix unused variable warnings

Just noticed that my earlier patch is guilty of causing these GCC 4.6 build warnings (from removing the printf that was the only usage of these variables):
{
ipc/testshell/XPCShellEnvironment.cpp:411:12: warning: variable ‘preBytes’ set but not used [-Wunused-but-set-variable]
ipc/testshell/XPCShellEnvironment.cpp:411:22: warning: variable ‘postBytes’ set but not used [-Wunused-but-set-variable]
}

Attached followup fixes this by removing the variables for good.

Comment 16

[Daniel Holbert [:dholbert]]

Followup for first patch landed.
 https://hg.mozilla.org/integration/mozilla-inbound/rev/0b1934705b4e

Note that this still isn't fully fixed, though, as noted in comment 14.

Comment 17

[Daniel Holbert [:dholbert]]

*facepalm* that last followup deleted the last usage of the variable "rt" (unless you have JS_GCMETER defined), so it added 1 new unused variable warning while fixing the other 2.

Pushed another followup to shift "rt" inside the JS_GCMETER #ifdef:
 https://hg.mozilla.org/integration/mozilla-inbound/rev/bb8d9e770b83

Comment 18

[Marco Bonardo [:mak]]

https://hg.mozilla.org/mozilla-central/rev/0b1934705b4e
https://hg.mozilla.org/mozilla-central/rev/bb8d9e770b83

Comment 19

[Daniel Holbert [:dholbert]]

khue

Comment 20

[Daniel Holbert [:dholbert]]

*khuey suspects these test-runners might be running an ancient version of xpcshell, which would explain why this is still happening. (I hit this in a Try log today, interrupting the data URI for a reftest failure)

I filed bug 742597 on checking that we're using a recent xpcshell build.

Comment 21

[Ed Morley [:emorley]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=11560289&tree=Fx-Team#error0

Comment 23

[Kartikaya Gupta (email:[e-mail])]

Bug 742597 is fixed, and looking at the reftest logs on tbpl for m-i, I no longer see this output all over the place. Yay!

Marking bug fixed.