Open Bug 1448532 Opened 3 years ago Updated 2 years ago

[mozlog] Mach log formatter can cause log output to be really slow

Categories

(Testing :: Mozbase, enhancement, P3)

Version 3
enhancement

Tracking

(Not tracked)

People

(Reporter: bzbarsky, Unassigned)

References

Details

The setup is that I am on Mac, using XQuartz xterms, sshing to a Linux box and running things there.

Some data points:

New format, time mach xpcshell-test caps/tests/unit/test_origin.js:
3.233u 0.886s 0:21.34 19.2%     0+0k 13224+16760io 9pf+0w

Old format, time mach xpcshell-test --log-tbpl=- caps/tests/unit/test_origin.js:
3.002u 0.754s 0:03.94 95.1%     0+0k 0+16760io 0pf+0w

New format, redirected to /dev/null:
2.928u 0.788s 0:03.63 101.9%    0+0k 0+16760io 0pf+0w

There are 470 lines of test output there, so we're spending about 37ms per line.  It's pretty visible to the naked eye: the lines kinda slowly appear.
Hmm.  Though I may be using a build from before bug 1445624, looking at the commit ids.  In which case I'm not quite sure what log format it's using...
OK, so given bug 1448533, it's possible that bug 1421799 did in fact turn on the mach formatter for xpcshell (but not other test suites).

Local bisect shows that for the steps to reproduce from comment 0 (running the caps/tests/unit/test_origin.js test) performance regressed significantly on this revision:

changeset:   397685:cee49b47add0
user:        Andrew Halberstadt <ahalberstadt@mozilla.com>
date:        Thu Nov 30 09:31:36 2017 -0500
summary:     Bug 1421799 - [mozlog] Improve the 'mach' formatter r=gbrown

Note that the output before that revision is _not_ the same as the current-tip output with --log-tbpl=-, by the way.  Specifically, the output from --log-tbpl=- looks something like this:

  TEST-PASS | caps/tests/unit/test_origin.js | checkValues - [checkValues : 64] "" == ""

with no colors, whereas the output from no extra logging args, on revision 0ad440c6f93b, looks identical to the current tip output, just much faster.
Flags: needinfo?(ahalberstadt)
Actually, a slight correction to the setup: the numbers I was seeing are what I get if I ssh to the Linux box, then run xterm there (showing it on the X server on the Mac box), and then run the relevant commands in that xterm.

Anyway, I played around a bit, and the entire regression is due to using term.dim_blue() instead of term.blue() for the timestamp.
(In reply to Boris Zbarsky [:bz] (no decent commit message means r-) from comment #3)
> Anyway, I played around a bit, and the entire regression is due to using
> term.dim_blue() instead of term.blue() for the timestamp.

Wow good find, thanks for debugging!

Fwiw, on my Linux box (no ssh) the 'mach' formatter ever so slightly outperforms the 'tbpl' formatter (I think because the tbpl formatter does some extra buffering the mach one doesn't). Though for all intents and purposes they're about equal. First off I'll get bug 1448533 fixed so you can easily revert back to the old format for |mach xpcshell-test|.

As for this bug, I could try finding another colour scheme to replace 'dim'. I wonder what's happening under the hood for 'dim' to cause such a regression.
Flags: needinfo?(ahalberstadt)
Also to possibly clarify some of the confusion around when the format changed.. XPCShell has long been using the 'mach' format by default, dating back to bug 1033126:
https://hg.mozilla.org/mozilla-central/rev/b2dc4f1dc9b3#l8.317

I don't remember the history around why it was made the default for xpcshell but not the other suites.
Priority: -- → P3
Summary: Mach log formatter can cause log output to be really slow → [mozlog] Mach log formatter can cause log output to be really slow
You need to log in before you can comment on or make changes to this bug.