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.

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?

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

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.

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.

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.

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

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

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.

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

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?

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

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

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.

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?

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

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

[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

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?

Woohoo, finally in production and working. Thanks aki! The b2g desktop mochitest log size is now around ~100k down from 50mb.

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

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