Bug 60328 – NRWT needs a way to log to a file without including backspaces without needing --verbose

• Status: RESOLVED
• Resolution: FIXED
• Component: New Bugs

[Dirk Pranke]

NRWT needs a way to log to a file without including backspaces without needing --verbose

[Dirk Pranke]

Created attachment 92519 [details]
Patch

[Dirk Pranke]

Comment on attachment 92519 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=92519&action=review

> Tools/Scripts/webkitpy/layout_tests/layout_package/manager.py:854
> +                self._printer.print_progress(result_summary, self._retrying, self._test_files_list)

Note that this change is needed so that we still get one-line-progress updates periodically even if no tests have completed.

[Tony Chang]

Comment on attachment 92519 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=92519&action=review

What is the use case for this?

> Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py:46
> +FAST_UPDATES = 0.03
> +SLOW_UPDATES = 10.0

Nit: Can we include the units in these variables?  e.g., FAST_UPDATES_TIME_SECS or FAST_UPDATES_SECS.

> Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py:221
> +            self._update_interval = FAST_UPDATES

Why do we need the fast updates value?  It seems like we didn't have this check before.

[Dirk Pranke]

(In reply to comment #3)
> (From update of attachment 92519 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=92519&action=review
> 
> What is the use case for this?
> 

I assume "this" == "this feature" and not some particular aspect of this patch?

If so, I tried to explain this in the changelog ... " This is useful if you want to capture the log output of NRWT but don't want the full --verbose output. " 

In particular, Adam asked for this on the EWS bots since the --verbose logs were taking up a large amount of space. I have also wanted this because the --verbose logs make it very hard to actually find real errors. Eventually I would like to have the debug output written to a debug log and have the code either do the "overwriting" or "no-overwriting" behavior by default depending on whether it is writing to something that supports overwriting. Unfortunately, I have no idea how to detect that in python. Any ideas?

> > Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py:46
> > +FAST_UPDATES = 0.03
> > +SLOW_UPDATES = 10.0
> 
> Nit: Can we include the units in these variables?  e.g., FAST_UPDATES_TIME_SECS or FAST_UPDATES_SECS.
>

Sure.
 
> > Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py:221
> > +            self._update_interval = FAST_UPDATES
> 
> Why do we need the fast updates value?  It seems like we didn't have this check before.

Correct. Before, we tried to update the progress meter after every test completed (potentially hundreds of times per second).  Adding this reduces the CPU load incurred by the master thread. I suppose it's debatable whether this is really necessary, but given that I've added the SLOW_UPDATES concept (which is necessary), it seems like it is.

[Tony Chang]

(In reply to comment #4)
> In particular, Adam asked for this on the EWS bots since the --verbose logs were taking up a large amount of space. I have also wanted this because the --verbose logs make it very hard to actually find real errors. Eventually I would like to have the debug output written to a debug log

This sounds like a better idea to me.  We could write the debug output to a debug log file (available on the buildbots) and reduce the logging in verbose to just be one line per test without the timestamp/filename prefix.  This also avoids having to add a new command line flag and runtime configuration that we need to support.

[Dirk Pranke]

(In reply to comment #5)
> (In reply to comment #4)
> > In particular, Adam asked for this on the EWS bots since the --verbose logs were taking up a large amount of space. I have also wanted this because the --verbose logs make it very hard to actually find real errors. Eventually I would like to have the debug output written to a debug log
> 
> This sounds like a better idea to me.  We could write the debug output to a debug log file (available on the buildbots) and reduce the logging in verbose to just be one line per test without the timestamp/filename prefix.  This also avoids having to add a new command line flag and runtime configuration that we need to support.

Even one line per test would probably still be several hundred KB of text, and most of it would be noise (since 99%+ of tests pass or we quit early).

The main distinction I'm looking to get is between a mode where nearly everything logged is either a fixed set of configuration messages, warnings, or errors (so there's an upper bound of a page or so of text), and the existing verbose mode (which is mostly useful as a debug log).

Regardless of whether we had that or the method you suggest though, I can still see someone suggesting a way to make the debug log optional (since it is so large) (or redirectable to /dev/null), and I would still want a way to toggle between the one-line update-in-place progress meter and the no-overwriting mode. 

Until/unless I can figure out a way to dynamically detect whether we have real backspaces, we still need some sort of flag. Theoretically we could add different --print options if you were more bothered by it being a top-level flag, but I would prefer not to do that because it's kind of an orthogonal concept (what to log vs. how to log it).

Of course, all this has prompted me to actually poke around and see what needs to be done to detect if I'm talking to a tty and backspace works. It looks like file.isatty() should do the trick, so perhaps I should just do that :)

I'll cancel the r? for now and try that out and maybe that'll work out better.

[Tony Chang]

For reference, the current Chromium Linux bot produces a 4MB stdio for each layout test run.  Trimming it to just the test name and status (also assuming we fix the double output bug) is 815k.

The goal isn't to avoid adding a command line flag, the goal is to avoid having to add additional configurations that we need to support.  It's better to try to come up with ways to satisfy multiple use-cases with fewer configurations.

[Dirk Pranke]

Created attachment 95378 [details]
Patch

[Dirk Pranke]

Okay, it looks like isatty() works like one would hope, so this allows me to simplify the output dramatically.

Once this lands, Adam can get the output he wants by just using '--print everything' (which will print periodic updates without any back spaces as long as the output is going to a file). For now, '--verbose' is the same as it was before, except that it will also include periodic updates.

[Dirk Pranke]

This patch is intended as part of a proper fix for https://bugs.webkit.org/show_bug.cgi?id=60352 .

Adam, does this look useful to you? Given this landing, you could change the EWS bots to just --print everything.

Tony has suggested that we could also include a change to just move the debug output to a file, at which point we could redefine --verbose to --print everything . I haven't coded that part yet (was inclined to make it a separate bug), but I don't think it'll be much additional work.

[Dirk Pranke]

Created attachment 95689 [details]
fix changelog

[Adam Barth]

Comment on attachment 95689 [details]
fix changelog

Cool.  Yeah this would be awesome.

[Tony Chang]

Comment on attachment 95689 [details]
fix changelog

View in context: https://bugs.webkit.org/attachment.cgi?id=95689&action=review

> Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py:47
> +FAST_UPDATES = 0.03
> +SLOW_UPDATES = 10.0

Can we add units to these variables?  FAS_UPDATES_SECONDS, etc

> Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py:221
> +            self._update_interval = FAST_UPDATES

_update_interval -> _update_interval_seconds

[Dirk Pranke]

(In reply to comment #13)
> (From update of attachment 95689 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=95689&action=review
> 
> > Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py:47
> > +FAST_UPDATES = 0.03
> > +SLOW_UPDATES = 10.0
> 
> Can we add units to these variables?  FAS_UPDATES_SECONDS, etc
> 

Will do.

> > Tools/Scripts/webkitpy/layout_tests/layout_package/printing.py:221
> > +            self._update_interval = FAST_UPDATES
> 
> _update_interval -> _update_interval_seconds

Will do.

[Dirk Pranke]

Committed r87967: <http://trac.webkit.org/changeset/87967>