Bug 60328 - NRWT needs a way to log to a file without including backspaces without needing --verbose
Summary: NRWT needs a way to log to a file without including backspaces without needin...
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: New Bugs (show other bugs)
Version: 528+ (Nightly build)
Hardware: PC All
: P2 Normal
Assignee: Dirk Pranke
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-05-05 18:16 PDT by Dirk Pranke
Modified: 2011-06-02 17:21 PDT (History)
4 users (show)

See Also:


Attachments
Patch (11.89 KB, patch)
2011-05-05 18:22 PDT, Dirk Pranke
no flags Details | Formatted Diff | Diff
Patch (12.85 KB, patch)
2011-05-30 16:11 PDT, Dirk Pranke
no flags Details | Formatted Diff | Diff
fix changelog (12.75 KB, patch)
2011-06-01 17:01 PDT, Dirk Pranke
tony: review+
Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Dirk Pranke 2011-05-05 18:16:12 PDT
NRWT needs a way to log to a file without including backspaces without needing --verbose
Comment 1 Dirk Pranke 2011-05-05 18:22:20 PDT
Created attachment 92519 [details]
Patch
Comment 2 Dirk Pranke 2011-05-05 18:23:06 PDT
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.
Comment 3 Tony Chang 2011-05-12 10:18:36 PDT
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.
Comment 4 Dirk Pranke 2011-05-23 21:14:26 PDT
(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.
Comment 5 Tony Chang 2011-05-24 11:06:54 PDT
(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.
Comment 6 Dirk Pranke 2011-05-24 23:34:19 PDT
(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.
Comment 7 Tony Chang 2011-05-25 10:26:31 PDT
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.
Comment 8 Dirk Pranke 2011-05-30 16:11:41 PDT
Created attachment 95378 [details]
Patch
Comment 9 Dirk Pranke 2011-05-30 16:14:05 PDT
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.
Comment 10 Dirk Pranke 2011-06-01 16:51:44 PDT
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.
Comment 11 Dirk Pranke 2011-06-01 17:01:59 PDT
Created attachment 95689 [details]
fix changelog
Comment 12 Adam Barth 2011-06-01 17:47:14 PDT
Comment on attachment 95689 [details]
fix changelog

Cool.  Yeah this would be awesome.
Comment 13 Tony Chang 2011-06-02 10:09:44 PDT
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
Comment 14 Dirk Pranke 2011-06-02 17:12:49 PDT
(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.
Comment 15 Dirk Pranke 2011-06-02 17:21:16 PDT
Committed r87967: <http://trac.webkit.org/changeset/87967>