957768 - Add an option to hide subtest results in Mochitest

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Andrew Halberstadt [:ahal]]

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.

Comment 1

[Andrew Halberstadt [:ahal]]

Attachment: Patch 1.0 - add option to hide subtests

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.

Comment 2

[Ed Morley [:emorley]]

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 3

[Joel Maher ( :jmaher ) (UTC -8)]

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?

Comment 4

[Andrew Halberstadt [:ahal]]

(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.

Comment 5

[Andrew Halberstadt [:ahal]]

Attachment: Patch 2.0 - add option to hide subtests

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.

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

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.

Comment 7

[Andrew Halberstadt [:ahal]]

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.

Comment 8

[Andrew Halberstadt [:ahal]]

Attachment: Patch 1.0 (mozharness) - pass in --hide-subtests to b2g desktop mochitests

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.

Comment 9

[Andrew Halberstadt [:ahal]]

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

Comment 10

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/7cbba8097c61
https://hg.mozilla.org/mozilla-central/rev/83ca1eb288a2

Comment 11

[Andrew Halberstadt [:ahal]]

Attachment: Dummy option for b2g26

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.

Comment 12

[Andrew Halberstadt [:ahal]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/2f7db1f0276a
https://hg.mozilla.org/releases/mozilla-b2g26_v1_2/rev/42a1c35fc831

Comment 13

[Andrew Halberstadt [:ahal]]

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.

Comment 14

[Andrew Halberstadt [:ahal]]

Is it just me or is Cypress not picking up mozharness default?

Comment 15

[Armen [: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

Comment 16

[Andrew Halberstadt [:ahal]]

(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!

Comment 17

[Andrew Halberstadt [:ahal]]

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?

Comment 18

[Andrew Halberstadt [:ahal]]

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.

Comment 19

[Andrew Halberstadt [:ahal]]

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.

Comment 20

[[e-mail] (:bhearsum)]

something is in production

Comment 21

[Andrew Halberstadt [:ahal]]

Attachment: Patch 2.1 - fix for TEST-START | Shutdown bug

Tested this locally, it fixes the problem.

Comment 22

[Joel Maher ( :jmaher ) (UTC -8)]

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?

Comment 23

[Armen [:armenzg]]

(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.

Comment 24

[Andrew Halberstadt [:ahal]]

(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

Comment 25

[Carsten Book [:Tomcat]]

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

Comment 26

[[e-mail] (:bhearsum)]

something is in production

Comment 27

[[e-mail] (:bhearsum)]

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

Comment 28

[Ryan VanderMeulen [:RyanVM]]

Confirmed that tests went green post-backout.

Comment 29

[Andrew Halberstadt [:ahal]]

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?

Comment 30

[Andrew Halberstadt [:ahal]]

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

Comment 31

[John Hopkins (:jhopkins)]

mozharness merged to production

Comment 32

[Andrew Halberstadt [:ahal]]

Hmm, this still isn't active.. looks like something went wrong in the merge?

Comment 33

[Andrew Halberstadt [:ahal]]

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?

Comment 34

[Aki Sasaki (not active)]

[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

Comment 35

[Aki Sasaki (not active)]

(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.

Comment 36

[John Hopkins (:jhopkins)]

aki: hg transplant won't apply the change

$ hg up -r production
$ hg transplant 12fc4ec719cc
skipping already applied revision 2290:12fc4ec719cc

Comment 37

[Aki Sasaki (not active)]

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?

Comment 38

[Andrew Halberstadt [:ahal]]

Woohoo, finally in production and working. Thanks aki!

The b2g desktop mochitest log size is now around ~100k down from 50mb.

Comment 39

[John Hopkins (:jhopkins)]

aki: are we likely to hit this problem again when merging mozharness?

Comment 40

[Aki Sasaki (not active)]

(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.