Add an option to hide subtest results in Mochitest

RESOLVED FIXED

Status

defect
RESOLVED FIXED
6 years ago
6 years ago

People

(Reporter: ahal, Assigned: ahal)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [leave-open])

Attachments

(4 attachments, 1 obsolete attachment)

Many of the mochitests have hundreds (or thousands) of subtests which make the logs very verbose. In bug 951771 we are reaching the 50Mb log limit for b2g desktop.

I propose we only print the subtest results if a failure or timeout occurs. This should not only reduce the log size, but make the tests run faster as they won't need to print nearly as much.
Joel, flagging you for a fresh perspective (also based on review queues in suggested reviewers ;)

For now, subtests are only hidden if you pass in --hide-subtests, so nothing should change until we enable it in mozharness. Though we may eventually want to make this option default if the perf win is large enough.

There is a risk that this could hide relevant output that comes from outside the test. I'm not sure if there's much we can do about that though.
Attachment #8357371 - Flags: review?(jmaher)
It may be good at some point to consolidate the approaches used here, for xpcshell [1] and imptests [2] :-)

[1] http://mxr.mozilla.org/mozilla-central/source/testing/xpcshell/runxpcshelltests.py#624
[2] http://mxr.mozilla.org/mozilla-central/source/dom/imptests/testharnessreport.js#164
Comment on attachment 8357371 [details] [diff] [review]
Patch 1.0 - add option to hide subtests

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

we have additional log processing for shutdown leaks:
http://dxr.mozilla.org/mozilla-central/source/build/automationutils.py#555

off hand, I don't think it affects things, but more food for thought.

I could be convinced of a r+, this just had too many little things.

::: testing/mochitest/runtests.py
@@ +1151,5 @@
>  
> +    def log_output_buffer(self):
> +        if self.output_buffer:
> +            lines = ['  %s' % line for line in self.output_buffer]
> +            log.info("Buffered test output:\n%s" % '\n'.join(lines))

should we have a \n at the end of the joined lines?

@@ +1189,5 @@
> +    def check_test_failure(self, line):
> +      if 'TEST-END' in line:
> +        self.running_test = False
> +        if any('TEST-UNEXPECTED-FAIL' in l for l in self.output_buffer):
> +          self.log_output_buffer()

don't forget TEST-UNEXPECTED-PASS.  This will always output even if we are not hinding subtests.

@@ +1196,2 @@
>      def log(self, line):
> +      if self.hide_subtests and self.running_test:

why not write it:
if self.hide_subtests:
  if self.running_test:
    self.output_buffer.append(line)
  elif 'TEST-END' in line:
    #hack line alignment

log.info(line)

@@ +1199,5 @@
> +      else:
> +        # hack to make separators align nicely, remove when we use mozlog
> +        if self.hide_subtests and 'TEST-END' in line:
> +            index = line.index('TEST-END') + len('TEST-END')
> +            line = line[:index] + ' ' * (len('TEST-START')-len('TEST-END')) + line[index:]

I really don't understand what this hack is doing.  Will this conflict in any way (double printing, etc.) with the method check_test_failure() above?

@@ +1200,5 @@
> +        # hack to make separators align nicely, remove when we use mozlog
> +        if self.hide_subtests and 'TEST-END' in line:
> +            index = line.index('TEST-END') + len('TEST-END')
> +            line = line[:index] + ' ' * (len('TEST-START')-len('TEST-END')) + line[index:]
> +        log.info(line)

this will always log.info(line).

@@ +1201,5 @@
> +        if self.hide_subtests and 'TEST-END' in line:
> +            index = line.index('TEST-END') + len('TEST-END')
> +            line = line[:index] + ' ' * (len('TEST-START')-len('TEST-END')) + line[index:]
> +        log.info(line)
> +      return line

why are we returning from the log() method now?
Attachment #8357371 - Flags: review?(jmaher) → review-
(In reply to Joel Maher (:jmaher) from comment #3)
> > +    def log_output_buffer(self):
> > +        if self.output_buffer:
> > +            lines = ['  %s' % line for line in self.output_buffer]
> > +            log.info("Buffered test output:\n%s" % '\n'.join(lines))
> 
> should we have a \n at the end of the joined lines?

The log.info() call adds a newline for us.

> @@ +1196,2 @@
> >      def log(self, line):
> > +      if self.hide_subtests and self.running_test:
> 
> why not write it:
> if self.hide_subtests:
>   if self.running_test:
>     self.output_buffer.append(line)
>   elif 'TEST-END' in line:
>     #hack line alignment
> 
> log.info(line)
> 
> @@ +1199,5 @@
> > +      else:
> > +        # hack to make separators align nicely, remove when we use mozlog
> > +        if self.hide_subtests and 'TEST-END' in line:
> > +            index = line.index('TEST-END') + len('TEST-END')
> > +            line = line[:index] + ' ' * (len('TEST-START')-len('TEST-END')) + line[index:]
> 
> I really don't understand what this hack is doing.  Will this conflict in
> any way (double printing, etc.) with the method check_test_failure() above?

I don't think that re-write actually does what I want. This hack is a little silly, but it's basically just to keep the '|' character in alignment. With --hide-subtests passed in we'll basically always have a TEST-START followed by a TEST-END. The result is the log looks like:
  INFO TEST-START | test_foo.py
  INFO TEST-END | test_foo.py
  INFO TEST-START | test_bar.py
  INFO TEST-END | test_bar.py

The hack turns the above into:
  INFO TEST-START | test_foo.py
  INFO TEST-END   | test_foo.py
  INFO TEST-START | test_bar.py
  INFO TEST-END   | test_bar.py

Which I think makes it much quicker to glance at a logfile and find the test name you want. I only do it if --hide-subtests is enabled because normally TEST-START and TEST-END are interspersed with a bunch of TEST-PASS lines which makes it less ugly to read.

> @@ +1200,5 @@
> > +        # hack to make separators align nicely, remove when we use mozlog
> > +        if self.hide_subtests and 'TEST-END' in line:
> > +            index = line.index('TEST-END') + len('TEST-END')
> > +            line = line[:index] + ' ' * (len('TEST-START')-len('TEST-END')) + line[index:]
> > +        log.info(line)
> 
> this will always log.info(line).

Yeah, it's supposed to always print out the TEST-END.

> @@ +1201,5 @@
> > +        if self.hide_subtests and 'TEST-END' in line:
> > +            index = line.index('TEST-END') + len('TEST-END')
> > +            line = line[:index] + ' ' * (len('TEST-START')-len('TEST-END')) + line[index:]
> > +        log.info(line)
> > +      return line
> 
> why are we returning from the log() method now?

I'm not really sure.. this is just how it was implemented before. I guess we can manipulate the line and then return it so it can be passed into the next handler?

Thanks for the quick review. I'll get a new patch up addressing your other comments shortly.
I looked into the leaklog processing and this patch shouldn't affect that since the trackShutdownLeaks handler will forward the line to the ShutdownLeaks class regardless of whether it is buffered or not.

So the only change in this patch is s/TEST-UNEXPECTED-FAIL/TEST-UNEXPECTED. I think I answered your other concerns in the previous comment. Though let me know if something still doesn't make sense.
Attachment #8357371 - Attachment is obsolete: true
Attachment #8357811 - Flags: review?(jmaher)
Comment on attachment 8357811 [details] [diff] [review]
Patch 2.0 - add option to hide subtests

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

thanks for answering all my concerns/nits.
Attachment #8357811 - Flags: review?(jmaher) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/7cbba8097c61

This will at least need to land on aurora and b2g26 too, but I'll wait until it sticks on inbound first. In the meantime I'll get the mozharness patch up and reviewed.
Whiteboard: [leave-open]
This will cause bustage if there exists a branch that doesn't have the --hide-subtests command line option. Afaict this means landing the above patch (or a dummy command line option) to aurora and b2g26.
Attachment #8357968 - Flags: review?(jgriffin)
The previous patch caused bustage because I forgot Android still uses automation.py. Follow up fix:
https://hg.mozilla.org/integration/mozilla-inbound/rev/83ca1eb288a2
Attachment #8357968 - Flags: review?(jgriffin) → review+
Depends on: 958395
The previous patch applied cleanly to aurora, so I'll land it there. But mochitest has been completely re-written since b2g26 and I'd have to re-implement the subtest hiding in a completely different way.

Therefore I'd like to just add the cli option to prevent mozharness bustage and be done with it.
Attachment #8358632 - Flags: review?(jgriffin)
Attachment #8358632 - Flags: review?(jgriffin) → review+
https://hg.mozilla.org/build/mozharness/rev/d8f601297cb7

This should go live next time mozharness is merged. I'll keep an eye on Cypress for mozharness bustage.
Is it just me or is Cypress not picking up mozharness default?
Flags: needinfo?(armenzg)
Hi ahal, I'm looking at it and I only see d8f601297cb7 being used which is part of the default branch.
Where are you seeing something else?

From tbpl:
TinderboxPrint: mozharness_revlink: http: //hg.mozilla.org/build/mozharness/rev/d8f601297cb7

I also see that revision in the log under the "hg id -i" step:
https://tbpl.mozilla.org/php/getParsedLog.php?id=32957010&tree=Cypress&full=1
Flags: needinfo?(armenzg)
(In reply to Armen Zambrano [:armenzg] (Release Engineering) (EDT/UTC-4) from comment #15)
> Hi ahal, I'm looking at it and I only see d8f601297cb7 being used which is
> part of the default branch.
> Where are you seeing something else?

Oh strange.. the b2g desktop mochitests are used a3ca4936ba02 even though I pushed the Cypress merge after I pushed my mozharness change (d8f601297cb7). I guess it doesn't pick up new mozharness changes immediately? Or maybe it's some timezone bug because I'm in Taipei. Anyway, I should just be able to re-trigger now. Thanks for looking!
Oh I think I know what is going on. We probably set the mozharness_branch variable (or whatever it's called) in config.py but not b2g_config.py or something. Armen, can you confirm?
Flags: needinfo?(armenzg)
I managed to test this on Cedar. It works, the log is much smaller, but the summary isn't getting printed for some reason so I backed out the mozharness patch before it got merged:
https://hg.mozilla.org/build/mozharness/rev/75f255efbf93

I'll figure out what's going on and re-land asap.
Ah the problem is the last line:

TEST-START | Shutdown

This causes my algorithm to think that a test is currently running and causes it to suppress all further output which unfortunately includes the summary. I'll get a patch up shortly.
something is in production
Tested this locally, it fixes the problem.
Attachment #8360878 - Flags: review?(jmaher)
Comment on attachment 8360878 [details] [diff] [review]
Patch 2.1 - fix for TEST-START | Shutdown bug

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

::: testing/mochitest/runtests.py
@@ +1206,5 @@
>  
>      def record_last_test(self, line):
>        """record last test on harness"""
>        if "TEST-START" in line and "|" in line:
> +        if not line.endswith('Shutdown'):

wow, I feel as though we are just adding more hacks to the system.  Are there other places where we would need to modify this?  b2g/remote runners?
Attachment #8360878 - Flags: review?(jmaher) → review+
(In reply to Andrew Halberstadt [:ahal] from comment #17)
> Oh I think I know what is going on. We probably set the mozharness_branch
> variable (or whatever it's called) in config.py but not b2g_config.py or
> something. Armen, can you confirm?

jgriffin fixed it on bug 960323. I missed that.
Flags: needinfo?(armenzg)
(In reply to Joel Maher (:jmaher) from comment #22)
> wow, I feel as though we are just adding more hacks to the system.  Are
> there other places where we would need to modify this?  b2g/remote runners?

Yeah. I wanted to wait for structured logging to land, then this patch would have been dead simple. But the mochitest log size kind of forced my hand. And no, we don't need to land this anywhere else (it's just an amendment to the last patch).

https://hg.mozilla.org/integration/mozilla-inbound/rev/6f94c2f5b72b
https://hg.mozilla.org/releases/mozilla-aurora/rev/a328472a909c

Also landed the mozharness change, will test again on Cedar:
https://hg.mozilla.org/build/mozharness/rev/3f764317c8db
something is in production
Comment on attachment 8357968 [details] [diff] [review]
Patch 1.0 (mozharness) - pass in --hide-subtests to b2g desktop mochitests

Backed out for suspected bustage:
https://tbpl.mozilla.org/php/getParsedLog.php?id=33186070&tree=Fx-Team

12:15:56     INFO -  Traceback (most recent call last):
12:15:56     INFO -    File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
12:15:56     INFO -    File "/usr/lib/python2.7/threading.py", line 504, in run
12:15:56     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozprocess/processhandler.py", line 728, in _processOutput
12:15:56     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozprocess/processhandler.py", line 680, in readWithTimeout
12:15:56     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozprocess/processhandler.py", line 819, in _readWithTimeout
12:15:56     INFO -  <type 'exceptions.AttributeError'>: 'NoneType' object has no attribute 'read'
12:15:56     INFO - Return code: 0
12:15:56     INFO - TinderboxPrint: mochitest<br/><em class="testfail">T-FAIL</em>
12:15:56  WARNING - # TBPL WARNING #
12:15:56  WARNING - The mochitest suite: mochitest-1 ran with return status: WARNING
Confirmed that tests went green post-backout.
What happened here? Seems like the M(1)'s are green on Cedar (and much smaller!) with all these patches applied. I believe the problem was just that https://hg.mozilla.org/mozilla-central/rev/6f94c2f5b72b didn't propagate to fx-team yet. Or did this happen on other branches (e.g inbound/central) as well?
I confirmed that the last patch had not yet been merged to fx-team, so the error there was expected. I re-landed the mozharness patch once more (third time's the charm!):
https://hg.mozilla.org/build/mozharness/rev/12fc4ec719cc
mozharness merged to production
Hmm, this still isn't active.. looks like something went wrong in the merge?
Yeah, this should have merged it:
http://hg.mozilla.org/build/mozharness/rev/e49a766f7e5b

But the diff for desktop_automation_config.py is empty. I confirmed on my local clone too, the changes exist on default but not when I hg update production.

Should I just land it directly on production?
Flags: needinfo?(jhopkins)
[19:36]	<aki>	jhopkins|afk: that can happen if the branches get out of sync
[19:36]	<aki>	jhopkins|afk: the fix is probably occasional merges from prod -> default, but then releng-ci goes crazy
[19:37]	<aki>	or maybe production becomes a bookmark that we move to a specific revision


Ahal: can you transplant it rather than land it directly?  I think that'll help with future merges.

hg up -r production
hg transplant SHA1
hg out
hg push
hg up -r default  # to avoid landing on production directly in the future

IIRC
(In reply to Aki Sasaki [:aki] from comment #34)
> [19:36]	<aki>	jhopkins|afk: that can happen if the branches get out of sync
> [19:36]	<aki>	jhopkins|afk: the fix is probably occasional merges from prod
> -> default, but then releng-ci goes crazy
> [19:37]	<aki>	or maybe production becomes a bookmark that we move to a
> specific revision

The main problem with a bookmark is sometimes multiple things land in default, and we want to cherrypick a later revision for immediate transplant to production.
aki: hg transplant won't apply the change

$ hg up -r production
$ hg transplant 12fc4ec719cc
skipping already applied revision 2290:12fc4ec719cc
Flags: needinfo?(jhopkins) → needinfo?(aki)
I:

# get a copy of the patch
hg export -r d8f601297cb7 >../patch
# back it out of default
patch -p1 -R <../patch
hg commit
# reland on default
hg import ../patch
# re-transplant to production
hg ident
hg up -r production
hg transplant 697adf40550e
# verify and push
hg out --patch | more
hg push

Andrew: if you only backed this out on production earlier, could you back out of both branches if you have to back out a merged patch in the future?
Flags: needinfo?(aki)
Woohoo, finally in production and working. Thanks aki!

The b2g desktop mochitest log size is now around ~100k down from 50mb.
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
aki: are we likely to hit this problem again when merging mozharness?
Flags: needinfo?(aki)
(In reply to John Hopkins (:jhopkins) from comment #39)
> aki: are we likely to hit this problem again when merging mozharness?

Shouldn't, but we shouldn't have hit it in the first place either, imo.
Flags: needinfo?(aki)
Blocks: 969446
You need to log in before you can comment on or make changes to this bug.