Bug 73846

Summary: clean up NRWT logging/metering, be less verbose
Product: WebKit Reporter: Ojan Vafai <ojan>
Component: Tools / TestsAssignee: Dirk Pranke <dpranke>
Status: RESOLVED FIXED    
Severity: Normal CC: abarth, aroben, dpranke, eric, gustavo, tony, webkit.review.bot
Priority: P2    
Version: 528+ (Nightly build)   
Hardware: Unspecified   
OS: Unspecified   
Bug Depends on: 82138    
Bug Blocks:    
Attachments:
Description Flags
Patch
none
more testing, update w/ review feedback, fix child process issues
none
Patch w/ fix for python 2.6 compatibility. none

Description Ojan Vafai 2011-12-05 11:10:23 PST
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
Comment 1 Dirk Pranke 2011-12-05 12:25:21 PST
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.
Comment 2 Dirk Pranke 2012-03-23 17:19:15 PDT
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.
Comment 3 Dirk Pranke 2012-03-23 17:19:59 PDT
Created attachment 133592 [details]
Patch
Comment 4 Ojan Vafai 2012-03-23 19:27:22 PDT
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?
Comment 5 Dirk Pranke 2012-03-24 12:35:09 PDT
(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.
Comment 6 Dirk Pranke 2012-03-24 14:18:10 PDT
Created attachment 133651 [details]
more testing, update w/ review feedback, fix child process issues
Comment 7 Dirk Pranke 2012-03-24 14:22:51 PDT
Committed r112014: <http://trac.webkit.org/changeset/112014>
Comment 8 Gustavo Noronha (kov) 2012-03-24 20:53:06 PDT
I rolled this patch out in r112019; it broke SnowLeopard, Chromium and GTK+ bots. I could not reproduce the problem locally.
Comment 9 Adam Barth 2012-03-25 11:52:42 PDT
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.
Comment 10 Dirk Pranke 2012-03-25 13:58:07 PDT
(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.
Comment 11 Dirk Pranke 2012-03-25 13:58:29 PDT
(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.
Comment 12 Dirk Pranke 2012-03-26 11:56:56 PDT
(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 ...
Comment 13 Dirk Pranke 2012-03-26 12:33:22 PDT
Created attachment 133867 [details]
Patch w/ fix for python 2.6 compatibility.
Comment 14 Dirk Pranke 2012-03-26 12:35:23 PDT
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.
Comment 15 Dirk Pranke 2012-03-26 12:35:23 PDT
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.
Comment 16 Dirk Pranke 2012-03-26 12:41:09 PDT
Committed r112140: <http://trac.webkit.org/changeset/112140>