Bug 73846 – clean up NRWT logging/metering, be less verbose

• Status: RESOLVED
• Resolution: FIXED
• Component: Tools / Tests

[Ojan Vafai]

Looking at the following snippet of log output, most of it is useful, but the date and the logging level are not useful to me. Can we get rid of those?

2011-12-03 03:09:30,018 58036 printing.py:462 INFO       worker/9:  4696 tests, 1746.63 secs
2011-12-03 03:09:30,018 58036 printing.py:462 INFO       worker/8:  1177 tests, 1693.47 secs
2011-12-03 03:09:30,018 58036 printing.py:462 INFO       worker/3:  1408 tests, 2033.51 secs
2011-12-03 03:09:30,018 58036 printing.py:462 INFO       worker/2:   941 tests, 2119.65 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO       worker/1:  1121 tests, 2041.97 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO       worker/0:  1453 tests, 2515.75 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO       worker/7:  1189 tests, 1731.12 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO       worker/6:  3556 tests, 2114.37 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO       worker/5:   948 tests, 2097.13 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO       worker/4:  1411 tests, 1716.66 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO      worker/15:   795 tests, 2027.16 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO      worker/14:  1123 tests, 1732.72 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO      worker/13:   425 tests, 2021.25 secs
2011-12-03 03:09:30,019 58036 printing.py:462 INFO      worker/12:  1175 tests, 1710.09 secs
2011-12-03 03:09:30,020 58036 printing.py:462 INFO      worker/11:  3462 tests, 2096.30 secs
2011-12-03 03:09:30,020 58036 printing.py:462 INFO      worker/10:  1449 tests, 1722.68 secs
2011-12-03 03:09:30,020 58036 printing.py:462 INFO    31120.45 cumulative, 1945.03 optimal

[Dirk Pranke]

I think it makes sense to get rid of some of the characters, but I'm not sure that I'd pick the same set you did. I'd probably get rid of at least the year, and I'd get rid of the filename and line number (since NRWT essentially funnels all of the logging through the single routine). 

I might compress the log level down (I/E/W/C or something), but I'd like to keep it for now as I find it useful to grep for warnings and errors on occasion. I can't decide if I think the date is useful otherwise. We can certainly get rid of it for now and add it back if we find we miss it.

[Dirk Pranke]

I'm going to hijack this bug to use for landing a large refactoring of the printing and metered_stream modules. Much of this is to make the code cleaner, as the existing implement has several weird subleties, but it also makes the metered stream module reusable for test-webkitpy.

I will at least also make things less verbose, eliminating the date, file:lineno, and level parameters :).

Updating subject accordingly.

[Dirk Pranke]

Created attachment 133592 [details]
Patch

[Ojan Vafai]

Comment on attachment 133592 [details]
Patch

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

Feel free to ignore any of these suggestions.

> Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:50
> +    def _newline(txt):

Nit: i'd call this _ensure_newline

> Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:63
> +        self._progress_delay_in_secs = 0.033 if self._erasing else 10.0

Nit: I think something like 0.1 would be fine here. Noone will notice the difference.

> Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:76
> +        """Restore / clean up any changes to the logging configuration."""

Here and below, these function comments describe the obvious "what" the function does. I don't think they are useful.

> Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:81
> +    def progress(self, txt):

s/progress/write_progress?

> Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:87
> +    def update(self, txt, now=None):

s/update/write_overwritable?

[Dirk Pranke]

(In reply to comment #4)
> (From update of attachment 133592 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=133592&action=review
> 
> Feel free to ignore any of these suggestions.
> 
> > Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:50
> > +    def _newline(txt):
> 
> Nit: i'd call this _ensure_newline
> 

Good. Done; I'd been trying to come up with a better name, but my mind was blanking on ensure_*.

> > Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:63
> > +        self._progress_delay_in_secs = 0.033 if self._erasing else 10.0
> 
> Nit: I think something like 0.1 would be fine here. Noone will notice the difference.
>

10 fps is slow enough to be noticable (at least to me). I changed it to 0.066 (15 fps) which seems like a fair compromise :).
 
> > Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:76
> > +        """Restore / clean up any changes to the logging configuration."""
> 
> Here and below, these function comments describe the obvious "what" the function does. I don't think they are useful.
> 

Ok.

> > Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:81
> > +    def progress(self, txt):
> 
> s/progress/write_progress?
> 

renamed it to write_throttled_update(), because of the change below (and throttled seemed clearer).

> > Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:87
> > +    def update(self, txt, now=None):
> 
> s/update/write_overwritable?

renamed it to write_update(). write_overwritable() seems awkward.

[Dirk Pranke]

Created attachment 133651 [details]
more testing, update w/ review feedback, fix child process issues

[Dirk Pranke]

Committed r112014: <http://trac.webkit.org/changeset/112014>

[Gustavo Noronha (kov)]

I rolled this patch out in r112019; it broke SnowLeopard, Chromium and GTK+ bots. I could not reproduce the problem locally.

[Adam Barth]

Comment on attachment 133651 [details]
more testing, update w/ review feedback, fix child process issues

This patch appears to be hanging the cr-linux EWS bots.

[Dirk Pranke]

(In reply to comment #9)
> (From update of attachment 133651 [details])
> This patch appears to be hanging the cr-linux EWS bots.

Not surprising, given comment #8 :). The patch shouldn't have been r? to begin with.

[Dirk Pranke]

(In reply to comment #8)
> I rolled this patch out in r112019; it broke SnowLeopard, Chromium and GTK+ bots. I could not reproduce the problem locally.

Very odd, given the testing I did locally. Thanks for rolling it out! I'll look into it.

[Dirk Pranke]

(In reply to comment #8)
> I rolled this patch out in r112019; it broke SnowLeopard, Chromium and GTK+ bots. I could not reproduce the problem locally.

Ah, it's a Python 2.6/2.7 issue. Here's a sample failure:

http://build.chromium.org/p/chromium.webkit/builders/Webkit%20Mac10.6/builds/13982/steps/webkit_tests/logs/stdio

should be easy enough to fix ...

[Dirk Pranke]

Created attachment 133867 [details]
Patch w/ fix for python 2.6 compatibility.

[Dirk Pranke]

Comment on attachment 133867 [details]
Patch w/ fix for python 2.6 compatibility.

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

> Tools/Scripts/webkitpy/layout_tests/controllers/worker.py:93
> +            if getattr(h, 'name', '') == metered_stream.LOG_HANDLER_NAME:

Turns out that LogHandlers grow a .name property in 2.7, but don't have it in 2.6.

> Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:122
> +        self.name = LOG_HANDLER_NAME

Fix is to s/self._name/self.name/ and then wrap the name check in getattr(), as above.

[Dirk Pranke]

Comment on attachment 133867 [details]
Patch w/ fix for python 2.6 compatibility.

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

> Tools/Scripts/webkitpy/layout_tests/controllers/worker.py:93
> +            if getattr(h, 'name', '') == metered_stream.LOG_HANDLER_NAME:

Turns out that LogHandlers grow a .name property in 2.7, but don't have it in 2.6.

> Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py:122
> +        self.name = LOG_HANDLER_NAME

Fix is to s/self._name/self.name/ and then wrap the name check in getattr(), as above.

[Dirk Pranke]

Committed r112140: <http://trac.webkit.org/changeset/112140>