⚠ Archived content — this site is no longer maintained.   Current WebKit documentation is at docs.webkit.org.

Changeset 112014 in webkit


Ignore:
Timestamp:
Mar 24, 2012, 2:22:41 PM (15 years ago)
Author:
dpranke@chromium.org
Message:

clean up NRWT logging/metering, be less verbose
​https://bugs.webkit.org/show_bug.cgi?id=73846

Reviewed by Ojan Vafai.

This patch totally rewrites the metered_stream module and
changes the way it and the printing module now interact with the
logging subsystem.

The printing module becomes a dumb layout_tests-specific wrapper around
the metered stream. All of the intelligence of how and when to
actually write (or erase) lines and how things interact with
logging moves into the metered stream.

As of now, anything written to the metered stream *bypasses the
logging system*. If a logger is passed to the meter constructor,
the metered stream will also attach a log handler so that all
messages fed to the logger will also be written to the metered
stream. This detangles the logic that used to exist where
sometimes the meter would write to the logger and sometimes the
logger would write to the meter.

All of this makes the logic generic and reusable for
test-webkitpy (coming in another patch). It also helps clarify
what the mysterious "configure_logging" parameter to the printer
constructor used to do (that parameter itself is gone now, and
by default the printer and metered_stream will not ever touch
the logging system; this makes a bunch of tests less fragile).

All of the above should produce no user-visible changes.

However, to also fix the bug in question, we change the message
format in --verbose mode to %H:%M:%S.%frac %pid %message,
eliminating the date, file:lineno, and level parameters. I am
making this change at the same time because it would be
difficult to write things consistently between the logs and the
metered stream if we were still logging the file:lineno.

  • Scripts/webkitpy/layout_tests/controllers/manager_unittest.py: Remove the configure_logging parameter
  • Scripts/webkitpy/layout_tests/controllers/worker.py: Use metered stream to configure the logging (we don't need a printer) and be careful about when and how we manipulate the log level and handlers on the root logger.
  • Scripts/webkitpy/layout_tests/run_webkit_tests.py: Pass in the root logger so that log messages are formatted properly, and set the log level outside of any routines called by unit tests so as to not interfere.
  • Scripts/webkitpy/layout_tests/views/manager_worker_broker.py: remove a duplicate log message.
  • Scripts/webkitpy/layout_tests/views/metered_stream.py: complete rewrite :).
  • Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py: complete rewrite :).
  • Scripts/webkitpy/layout_tests/views/printing.py: move the logging configuration into metered_stream, and also move the "when should I log progress messages" into metered stream.
  • Scripts/webkitpy/layout_tests/views/printing_unittest.py: remove tests that are no longer necessary.
  • Scripts/webkitpy/performance_tests/perftestsrunner.py: remove the configure_logging parameter.
  • Scripts/webkitpy/performance_tests/perftestsrunner_unittest.py: update the test; since the printer no longer writes to the log, we need to check what is written to the regular_output instead. (test_run_test_pause_before_testing):
Location:
trunk/Tools
Files:
12 edited

Legend:

Unmodified
Added
Removed

  • trunk/Tools/ChangeLog

    r111995 r112014  
     12012-03-24  Dirk Pranke  <dpranke@chromium.org>
     2
     3        clean up NRWT logging/metering, be less verbose
     4        https://bugs.webkit.org/show_bug.cgi?id=73846
     5
     6        Reviewed by Ojan Vafai.
     7
     8        This patch totally rewrites the metered_stream module and
     9        changes the way it and the printing module now interact with the
     10        logging subsystem.
     11
     12        The printing module becomes a dumb layout_tests-specific wrapper around
     13        the metered stream. All of the intelligence of how and when to
     14        actually write (or erase) lines and how things interact with
     15        logging moves into the metered stream.
     16
     17        As of now, anything written to the metered stream *bypasses the
     18        logging system*. If a logger is passed to the meter constructor,
     19        the metered stream will also attach a log handler so that all
     20        messages fed to the logger will also be written to the metered
     21        stream. This detangles the logic that used to exist where
     22        sometimes the meter would write to the logger and sometimes the
     23        logger would write to the meter.
     24
     25        All of this makes the logic generic and reusable for
     26        test-webkitpy (coming in another patch). It also helps clarify
     27        what the mysterious "configure_logging" parameter to the printer
     28        constructor used to do (that parameter itself is gone now, and
     29        by default the printer and metered_stream will not ever touch
     30        the logging system; this makes a bunch of tests less fragile).
     31
     32        All of the above should produce no user-visible changes.
     33
     34        However, to also fix the bug in question, we change the message
     35        format in --verbose mode to %H:%M:%S.%frac %pid %message,
     36        eliminating the date, file:lineno, and level parameters. I am
     37        making this change at the same time because it would be
     38        difficult to write things consistently between the logs and the
     39        metered stream if we were still logging the file:lineno.
     40
     41        * Scripts/webkitpy/layout_tests/controllers/manager_unittest.py:
     42          Remove the configure_logging parameter
     43        * Scripts/webkitpy/layout_tests/controllers/worker.py:
     44          Use metered stream to configure the logging (we don't need a printer)
     45          and be careful about when and how we manipulate the log level
     46          and handlers on the root logger.
     47        * Scripts/webkitpy/layout_tests/run_webkit_tests.py:
     48          Pass in the root logger so that log messages are formatted
     49          properly, and set the log level outside of any routines called
     50          by unit tests so as to not interfere.
     51        * Scripts/webkitpy/layout_tests/views/manager_worker_broker.py:
     52          remove a duplicate log message.
     53        * Scripts/webkitpy/layout_tests/views/metered_stream.py:
     54          complete rewrite :).
     55        * Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py:
     56          complete rewrite :).
     57        * Scripts/webkitpy/layout_tests/views/printing.py:
     58          move the logging configuration into metered_stream, and also
     59          move the "when should I log progress messages" into metered stream.
     60        * Scripts/webkitpy/layout_tests/views/printing_unittest.py:
     61          remove tests that are no longer necessary.
     62        * Scripts/webkitpy/performance_tests/perftestsrunner.py:
     63          remove the configure_logging parameter.
     64        * Scripts/webkitpy/performance_tests/perftestsrunner_unittest.py:
     65          update the test; since the printer no longer writes to the log,
     66          we need to check what is written to the regular_output instead.
     67          (test_run_test_pause_before_testing):
     68
    1692012-03-24  Gustavo Noronha Silva  <gns@gnome.org>
    270

  • trunk/Tools/Scripts/webkitpy/layout_tests/controllers/manager_unittest.py

    r111902 r112014  
    215215        port = host.port_factory.get(port_name=options.platform, options=options)
    216216        run_webkit_tests._set_up_derived_options(port, options)
    217         printer = printing.Printer(port, options, StringIO.StringIO(), StringIO.StringIO(), configure_logging=False)
     217        printer = printing.Printer(port, options, StringIO.StringIO(), StringIO.StringIO())
    218218        manager = LockCheckingManager(port, options, printer)
    219219        manager.collect_tests(args)

  • trunk/Tools/Scripts/webkitpy/layout_tests/controllers/manager_worker_broker.py

    r108379 r112014  
    275275        remaining initialization and then calls broker_connection.run_message_loop()."""
    276276        exception_msg = ""
    277         _log.debug("%s starting" % self._name)
    278277
    279278        try:

  • trunk/Tools/Scripts/webkitpy/layout_tests/controllers/worker.py

    r108005 r112014  
    3939from webkitpy.layout_tests.models import test_expectations
    4040from webkitpy.layout_tests.models import test_results
    41 from webkitpy.layout_tests.views import printing
     41from webkitpy.layout_tests.views import metered_stream
    4242
    4343
    … …  
    6666        self._tests_run_file = None
    6767        self._tests_run_filename = None
    68         self._printer = None
     68        self._meter = None
    6969
    7070    def __del__(self):
    … …  
    8383        self._tests_run_file = self._filesystem.open_text_file_for_writing(tests_run_filename)
    8484
     85    def _set_up_logging(self):
     86        # The unix multiprocessing implementation clones the MeteredStream log handler
     87        # into the child process, so we need to remove it before we can
     88        # add a new one to get the correct pid logged.
     89        root_logger = logging.getLogger()
     90        handler_to_remove = None
     91        for h in root_logger.handlers:
     92            if h.name == metered_stream.LOG_HANDLER_NAME:
     93                handler_to_remove = h
     94                break
     95        if handler_to_remove:
     96            root_logger.removeHandler(handler_to_remove)
     97
     98        # FIXME: This won't work if the calling process is logging
     99        # somewhere other than sys.stderr, but I'm not sure
     100        # if this will be an issue in practice. Also, it would be
     101        # nice if we trapped all of the messages for a given test
     102        # and sent them back in finished_test() rather than logging
     103        # them to stderr.
     104        if not root_logger.handlers:
     105            options = self._options
     106            root_logger.setLevel(logging.DEBUG if options.verbose else logging.INFO)
     107            self._meter = metered_stream.MeteredStream(sys.stderr, options.verbose, logger=root_logger)
     108
     109    def _set_up_host_and_port(self):
     110        options = self._options
     111        if options.platform and 'test' in options.platform:
     112            # It is lame to import mocks into real code, but this allows us to use the test port in multi-process tests as well.
     113            from webkitpy.common.host_mock import MockHost
     114            host = MockHost()
     115        else:
     116            host = Host()
     117        self._port = host.port_factory.get(options.platform, options)
     118
    85119    def set_inline_arguments(self, port):
    86120        self._port = port
    … …  
    88122    def run(self):
    89123        if not self._port:
    90             # We are running in a child process and need to create a new Host.
    91             if self._options.platform and 'test' in self._options.platform:
    92                 # It is lame to import mocks into real code, but this allows us to use the test port in multi-process tests as well.
    93                 from webkitpy.common.host_mock import MockHost
    94                 host = MockHost()
    95             else:
    96                 host = Host()
    97 
    98             options = self._options
    99             self._port = host.port_factory.get(options.platform, options)
    100 
    101             # The unix multiprocessing implementation clones the
    102             # log handler configuration into the child processes,
    103             # but the win implementation doesn't.
    104             configure_logging = (sys.platform == 'win32')
    105 
    106             # FIXME: This won't work if the calling process is logging
    107             # somewhere other than sys.stderr and sys.stdout, but I'm not sure
    108             # if this will be an issue in practice.
    109             self._printer = printing.Printer(self._port, options, sys.stderr, sys.stdout, configure_logging)
     124            # We are running in a child process and need to initialize things.
     125            self._set_up_logging()
     126            self._set_up_host_and_port()
    110127
    111128        self.safe_init()
    112 
    113129        try:
    114130            _log.debug("%s starting" % self._name)
    115131            super(Worker, self).run()
    116132        finally:
     133            self.kill_driver()
    117134            self._worker_connection.post_message('done')
     135            _log.debug("%s exiting" % self._name)
    118136            self.cleanup()
    119             _log.debug("%s exiting" % self._name)
    120137
    121138    def handle_test_list(self, src, list_name, test_list):
    … …  
    154171            self._tests_run_file.close()
    155172            self._tests_run_file = None
    156         if self._printer:
    157             self._printer.cleanup()
    158             self._printer = None
     173        if self._meter:
     174            self._meter.cleanup()
     175            self._meter = None
    159176
    160177    def timeout(self, test_input):

  • trunk/Tools/Scripts/webkitpy/layout_tests/controllers/worker_unittest.py

    r107867 r112014  
    4747        worker_connection = FakeConnection()
    4848        worker = Worker(worker_connection, WorkerArguments(1, '/tmp', MockOptions(platform=None, print_options=None, verbose=False, batch_size=0)))
    49         worker._done = True
    50         worker.run()
     49        worker._set_up_host_and_port()
    5150        self.assertNotEquals(worker._port, None)
    5251

  • trunk/Tools/Scripts/webkitpy/layout_tests/run_webkit_tests.py

    r111902 r112014  
    8686    warnings = _set_up_derived_options(port, options)
    8787
    88     printer = printing.Printer(port, options, regular_output, buildbot_output, configure_logging=True)
     88    printer = printing.Printer(port, options, regular_output, buildbot_output, logger=logging.getLogger())
    8989
    9090    for warning in warnings:
    … …  
    480480    host._initialize_scm()
    481481    port = host.port_factory.get(options.platform, options)
     482    logging.getLogger().setLevel(logging.DEBUG if options.verbose else logging.INFO)
    482483    return run(port, options, args)
    483484

  • trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py

    r108175 r112014  
    11#!/usr/bin/env python
    2 # Copyright (C) 2010 Google Inc. All rights reserved.
     2# Copyright (C) 2010, 2012 Google Inc. All rights reserved.
    33#
    44# Redistribution and use in source and binary forms, with or without
    … …  
    2828# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
    2929
    30 """
    31 Package that implements a stream wrapper that has 'meters' as well as
    32 regular output. A 'meter' is a single line of text that can be erased
    33 and rewritten repeatedly, without producing multiple lines of output. It
    34 can be used to produce effects like progress bars.
    35 
    36 This package should only be called by the printing module in the layout_tests
    37 package.
    38 """
     30import logging
     31import os
     32import sys
     33import time
    3934
    4035
    41 class MeteredStream:
    42     """This class is a wrapper around a stream that allows you to implement
    43     meters (progress bars, etc.).
     36LOG_HANDLER_NAME = 'MeteredStreamLogHandler'
    4437
    45     It can be used directly as a stream, by calling write(), but also provides
    46     a method called update() that will overwite prior updates().
    47    """
    4838
    49     def __init__(self, stream):
    50         """
    51         Args:
    52           stream: output stream to write to
    53         """
    54         self._stream = stream
    55         self._dirty = False
    56         self._last_update = ""
     39class MeteredStream(object):
     40    """
     41    This class implements a stream wrapper that has 'meters' as well as
     42    regular output. A 'meter' is a single line of text that can be erased
     43    and rewritten repeatedly, without producing multiple lines of output. It
     44    can be used to produce effects like progress bars.
     45    """
    5746
    58     def write(self, txt):
    59         """Write to the stream, overwriting and resetting the meter."""
     47    @staticmethod
     48    def _erasure(txt):
     49        num_chars = len(txt)
     50        return '\b' * num_chars + ' ' * num_chars + '\b' * num_chars
    6051
    61         # This routine is called by the logging infrastructure, and
    62         # must not call back into logging. It is not a public function.
    63         self._overwrite(txt)
    64         self._reset()
     52    @staticmethod
     53    def _ensure_newline(txt):
     54        return txt if txt.endswith('\n') else txt + '\n'
    6555
    66     def update(self, txt):
    67         """Write a message that will be overwritten by subsequent update() or write() calls."""
    68         self._overwrite(txt)
     56    def __init__(self, stream=None, verbose=False, logger=None, time_fn=None, pid=None):
     57        self._stream = stream or sys.stderr
     58        self._verbose = verbose
     59        self._time_fn = time_fn or time.time
     60        self._pid = pid or os.getpid()
    6961
    70     def _overwrite(self, txt):
    71         # Print the necessary number of backspaces to erase the previous
    72         # message.
    73         if len(self._last_update):
    74             self._stream.write("\b" * len(self._last_update) +
    75                                " " * len(self._last_update) +
    76                                "\b" * len(self._last_update))
    77         self._stream.write(txt)
    78         last_newline = txt.rfind("\n")
    79         self._last_update = txt[(last_newline + 1):]
    80         self._dirty = True
     62        self._isatty = self._stream.isatty()
     63        self._erasing = self._isatty and not verbose
     64        self._last_partial_line = ''
     65        self._last_write_time = 0.0
     66        self._throttle_delay_in_secs = 0.066 if self._erasing else 10.0
    8167
    82     def _reset(self):
    83         self._dirty = False
    84         self._last_update = ''
     68        self._logger = logger
     69        self._log_handler = None
     70        if self._logger:
     71            log_level = logging.DEBUG if verbose else logging.INFO
     72            self._log_handler = _LogHandler(self)
     73            self._log_handler.setLevel(log_level)
     74            self._logger.addHandler(self._log_handler)
     75
     76    def __del__(self):
     77        self.cleanup()
     78
     79    def cleanup(self):
     80        if self._logger:
     81            self._logger.removeHandler(self._log_handler)
     82            self._log_handler = None
     83
     84    def write_throttled_update(self, txt):
     85        now = self._time_fn()
     86        if now - self._last_write_time >= self._throttle_delay_in_secs:
     87            self.write_update(txt, now)
     88
     89    def write_update(self, txt, now=None):
     90        self.write(txt, now)
     91        if self._erasing:
     92            self._last_partial_line = txt[txt.rfind('\n') + 1:]
     93
     94    def write(self, txt, now=None):
     95        now = now or self._time_fn()
     96        self._last_write_time = now
     97        if self._last_partial_line:
     98            self._erase_last_partial_line()
     99        if self._verbose:
     100            now_tuple = time.localtime(now)
     101            msg = '%02d:%02d:%02d.%03d %d %s' % (now_tuple.tm_hour, now_tuple.tm_min, now_tuple.tm_sec, int((now * 1000) % 1000), self._pid, self._ensure_newline(txt))
     102        elif self._isatty:
     103            msg = txt
     104        else:
     105            msg = self._ensure_newline(txt)
     106
     107        self._stream.write(msg)
     108
     109    def writeln(self, txt, now=None):
     110        self.write(self._ensure_newline(txt), now)
     111
     112    def _erase_last_partial_line(self):
     113        num_chars = len(self._last_partial_line)
     114        self._stream.write(self._erasure(self._last_partial_line))
     115        self._last_partial_line = ''
     116
     117
     118class _LogHandler(logging.Handler):
     119    def __init__(self, meter):
     120        logging.Handler.__init__(self)
     121        self._meter = meter
     122        self._name = LOG_HANDLER_NAME
     123
     124    def emit(self, record):
     125        self._meter.writeln(record.msg, record.created)

  • trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py

    r108175 r112014  
    11#!/usr/bin/python
    2 # Copyright (C) 2010 Google Inc. All rights reserved.
     2# Copyright (C) 2010, 2012 Google Inc. All rights reserved.
    33#
    44# Redistribution and use in source and binary forms, with or without
    … …  
    2828# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
    2929
     30import logging
     31import re
    3032import StringIO
    3133import unittest
    … …  
    3436
    3537
    36 class TestMeteredStream(unittest.TestCase):
    37     def test_regular(self):
    38         a = StringIO.StringIO()
    39         m = MeteredStream(a)
    40         self.assertFalse(a.getvalue())
     38class RegularTest(unittest.TestCase):
     39    verbose = False
     40    isatty = False
    4141
    42         # basic test
    43         m.write("foo")
    44         exp = ['foo']
    45         self.assertEquals(a.buflist, exp)
     42    def setUp(self):
     43        self.stream = StringIO.StringIO()
     44        self.buflist = self.stream.buflist
     45        self.stream.isatty = lambda: self.isatty
    4646
    47         # now check that a second write() does not overwrite the first.
    48         m.write("bar")
    49         exp.append('bar')
    50         self.assertEquals(a.buflist, exp)
     47        # configure a logger to test that log calls do normally get included.
     48        self.logger = logging.getLogger(__name__)
     49        self.logger.setLevel(logging.DEBUG)
     50        self.logger.propagate = False
    5151
    52         m.update("batter")
    53         exp.append('batter')
    54         self.assertEquals(a.buflist, exp)
     52        # add a dummy time counter for a default behavior.
     53        self.times = range(10)
    5554
    56         # The next update() should overwrite the laste update() but not the
    57         # other text. Note that the cursor is effectively positioned at the
    58         # end of 'foo', even though we had to erase three more characters.
    59         m.update("foo")
    60         exp.append('\b\b\b\b\b\b      \b\b\b\b\b\b')
    61         exp.append('foo')
    62         self.assertEquals(a.buflist, exp)
     55        self.meter = MeteredStream(self.stream, self.verbose, self.logger, self.time_fn, 8675)
    6356
    64         # now check that a write() does overwrite the update
    65         m.write("foo")
    66         exp.append('\b\b\b   \b\b\b')
    67         exp.append('foo')
    68         self.assertEquals(a.buflist, exp)
     57    def tearDown(self):
     58        if self.meter:
     59            self.meter.cleanup()
     60            self.meter = None
    6961
    70         # Now test that we only back up to the most recent newline.
     62    def time_fn(self):
     63        return self.times.pop(0)
    7164
    72         # Note also that we do not back up to erase the most recent write(),
    73         # i.e., write()s do not get erased.
    74         a = StringIO.StringIO()
    75         m = MeteredStream(a)
    76         m.update("foo\nbar")
    77         m.update("baz")
    78         self.assertEquals(a.buflist, ['foo\nbar', '\b\b\b   \b\b\b', 'baz'])
     65    def test_logging_not_included(self):
     66        # This tests that if we don't hand a logger to the MeteredStream,
     67        # nothing is logged.
     68        logging_stream = StringIO.StringIO()
     69        handler = logging.StreamHandler(logging_stream)
     70        root_logger = logging.getLogger()
     71        orig_level = root_logger.level
     72        root_logger.addHandler(handler)
     73        root_logger.setLevel(logging.DEBUG)
     74        try:
     75            self.meter = MeteredStream(self.stream, self.verbose, None, self.time_fn, 8675)
     76            self.meter.write_throttled_update('foo')
     77            self.meter.write_update('bar')
     78            self.meter.write('baz')
     79            self.assertEquals(logging_stream.buflist, [])
     80        finally:
     81            root_logger.removeHandler(handler)
     82            root_logger.setLevel(orig_level)
     83
     84    def _basic(self, times):
     85        self.times = times
     86        self.meter.write_update('foo')
     87        self.meter.write_update('bar')
     88        self.meter.write_throttled_update('baz')
     89        self.meter.write_throttled_update('baz 2')
     90        self.meter.writeln('done')
     91        self.assertEquals(self.times, [])
     92        return self.buflist
     93
     94    def test_basic(self):
     95        buflist = self._basic([0, 1, 2, 13, 14])
     96        self.assertEquals(buflist, ['foo\n', 'bar\n', 'baz 2\n', 'done\n'])
     97
     98    def _log_after_update(self):
     99        self.meter.write_update('foo')
     100        self.logger.info('bar')
     101        return self.buflist
     102
     103    def test_log_after_update(self):
     104        buflist = self._log_after_update()
     105        self.assertEquals(buflist, ['foo\n', 'bar\n'])
     106
     107
     108class TtyTest(RegularTest):
     109    verbose = False
     110    isatty = True
     111
     112    def test_basic(self):
     113        buflist = self._basic([0, 1, 1.05, 1.1, 2])
     114        self.assertEquals(buflist, ['foo',
     115                                     MeteredStream._erasure('foo'), 'bar',
     116                                     MeteredStream._erasure('bar'), 'baz 2',
     117                                     MeteredStream._erasure('baz 2'), 'done\n'])
     118
     119    def test_log_after_update(self):
     120        buflist = self._log_after_update()
     121        self.assertEquals(buflist, ['foo',
     122                                     MeteredStream._erasure('foo'), 'bar\n'])
     123
     124
     125class VerboseTest(RegularTest):
     126    isatty = False
     127    verbose = True
     128
     129    def test_basic(self):
     130        buflist = self._basic([0, 1, 2.1, 13, 14.1234])
     131        self.assertEquals(buflist, ['16:00:00.000 8675 foo\n', '16:00:01.000 8675 bar\n', '16:00:13.000 8675 baz 2\n', '16:00:14.123 8675 done\n'])
     132
     133    def test_log_after_update(self):
     134        buflist = self._log_after_update()
     135        self.assertEquals(buflist[0], '16:00:00.000 8675 foo\n')
     136
     137        # The second argument should have a real timestamp and pid, so we just check the format.
     138        self.assertEquals(len(buflist), 2)
     139        self.assertTrue(re.match('\d\d:\d\d:\d\d.\d\d\d \d+ bar\n', buflist[1]))
    79140
    80141

  • trunk/Tools/Scripts/webkitpy/layout_tests/views/printing.py

    r109282 r112014  
    11#!/usr/bin/env python
    2 # Copyright (C) 2010 Google Inc. All rights reserved.
     2# Copyright (C) 2010, 2012 Google Inc. All rights reserved.
    33#
    44# Redistribution and use in source and binary forms, with or without
    … …  
    3030"""Package that handles non-debug, non-file output for run-webkit-tests."""
    3131
    32 import logging
    3332import optparse
    34 import time
    3533
    3634from webkitpy.common.net import resultsjsonparser
     35from webkitpy.layout_tests.models.test_expectations import TestExpectations
    3736from webkitpy.layout_tests.views.metered_stream import MeteredStream
    38 from webkitpy.layout_tests.models.test_expectations import TestExpectations
    39 
    40 
    41 _log = logging.getLogger(__name__)
    42 
    4337
    4438NUM_SLOW_TESTS_TO_LOG = 10
    45 FAST_UPDATES_SECONDS = 0.03
    46 SLOW_UPDATES_SECONDS = 10.0
    4739
    4840PRINT_DEFAULT = "misc,one-line-progress,one-line-summary,unexpected,unexpected-results,updates"
    … …  
    155147
    156148
    157 def _configure_logging(stream, verbose):
    158     log_fmt = '%(message)s'
    159     log_datefmt = '%y%m%d %H:%M:%S'
    160     log_level = logging.INFO
    161     if verbose:
    162         log_fmt = '%(asctime)s %(process)d %(filename)s:%(lineno)d %(levelname)s %(message)s'
    163         log_level = logging.DEBUG
    164 
    165     root = logging.getLogger()
    166     handler = logging.StreamHandler(stream)
    167     handler.setFormatter(logging.Formatter(log_fmt, None))
    168     root.addHandler(handler)
    169     root.setLevel(log_level)
    170     return handler
    171 
    172 
    173 def _restore_logging(handler_to_remove):
    174     root = logging.getLogger()
    175     root.handlers.remove(handler_to_remove)
    176 
    177 
    178149class Printer(object):
    179150    """Class handling all non-debug-logging printing done by run-webkit-tests.
    … …  
    188159    By default the buildbot-parsed code gets logged to stdout, and regular
    189160    output gets logged to stderr."""
    190     def __init__(self, port, options, regular_output, buildbot_output, configure_logging):
     161    def __init__(self, port, options, regular_output, buildbot_output, logger=None):
    191162        """
    192163        Args
    … …  
    197168          buildbot_output    stream to which output intended to be read by
    198169                             the buildbots (and humans) should be written
    199           configure_loggign  Whether a logging handler should be registered
    200 
     170          logger             optional logger to integrate into the stream.
    201171        """
    202172        self._port = port
    203173        self._options = options
    204         self._stream = regular_output
    205174        self._buildbot_stream = buildbot_output
    206         self._meter = None
    207 
    208         # These are used for --print one-line-progress
    209         self._last_remaining = None
    210         self._last_update_time = None
    211 
     175        self._meter = MeteredStream(regular_output, options.verbose, logger=logger)
    212176        self.switches = parse_print_options(options.print_options, options.verbose)
    213177
    214         self._logging_handler = None
    215         if self._stream.isatty() and not options.verbose:
    216             self._update_interval_seconds = FAST_UPDATES_SECONDS
    217             self._meter = MeteredStream(self._stream)
    218             if configure_logging:
    219                 self._logging_handler = _configure_logging(self._meter, options.verbose)
    220         else:
    221             self._update_interval_seconds = SLOW_UPDATES_SECONDS
    222             if configure_logging:
    223                 self._logging_handler = _configure_logging(self._stream, options.verbose)
    224 
    225178    def cleanup(self):
    226         """Restore logging configuration to its initial settings."""
    227         if self._logging_handler:
    228             _restore_logging(self._logging_handler)
    229             self._logging_handler = None
     179        self._meter.cleanup()
    230180
    231181    def __del__(self):
    … …  
    351301            return
    352302
    353         now = time.time()
    354         if self._last_update_time is None:
    355             self._last_update_time = now
    356 
    357         time_since_last_update = now - self._last_update_time
    358         if time_since_last_update <= self._update_interval_seconds:
    359             return
    360 
    361         self._last_update_time = now
     303        if result_summary.remaining == 0:
     304            self._meter.write_update('')
     305            return
    362306
    363307        percent_complete = 100 * (result_summary.expected +
    … …  
    366310        if retrying:
    367311            action = "Retrying"
    368         self._update("%s (%d%%): %d ran as expected, %d didn't, %d left" %
    369                      (action, percent_complete, result_summary.expected,
    370                       result_summary.unexpected, result_summary.remaining))
    371 
    372         if result_summary.remaining == 0:
    373             self._update('')
     312
     313        self._meter.write_throttled_update("%s (%d%%): %d ran as expected, %d didn't, %d left" %
     314            (action, percent_complete, result_summary.expected,
     315             result_summary.unexpected, result_summary.remaining))
    374316
    375317    def print_unexpected_results(self, unexpected_results):
    … …  
    459401        if self.disabled('updates'):
    460402            return
    461         self._update(msg)
     403        self._meter.write_update(msg)
    462404
    463405    def write(self, msg, option="misc"):
    … …  
    467409
    468410    def _write(self, msg):
    469         _log.info(msg)
    470 
    471     def _update(self, msg):
    472         if self._meter:
    473             self._meter.update(msg)
    474         else:
    475             self._write(msg)
     411        self._meter.writeln(msg)

  • trunk/Tools/Scripts/webkitpy/layout_tests/views/printing_unittest.py

    r108175 r112014  
    11#!/usr/bin/python
    2 # Copyright (C) 2010 Google Inc. All rights reserved.
     2# Copyright (C) 2010, 2012 Google Inc. All rights reserved.
    33#
    44# Redistribution and use in source and binary forms, with or without
    … …  
    3030"""Unit tests for printing.py."""
    3131
    32 import logging
    3332import optparse
    3433import StringIO
    … …  
    5554
    5655class TestUtilityFunctions(unittest.TestCase):
    57     def assertEmpty(self, stream):
    58         self.assertFalse(stream.getvalue())
    59 
    60     def assertNotEmpty(self, stream):
    61         self.assertTrue(stream.getvalue())
    62 
    63     def assertWritten(self, stream, contents):
    64         self.assertEquals(stream.buflist, contents)
    65 
    66     def test_configure_logging(self):
    67         options, args = get_options([])
    68         stream = StringIO.StringIO()
    69         handler = printing._configure_logging(stream, options.verbose)
    70         logging.info("this should be logged")
    71         self.assertNotEmpty(stream)
    72 
    73         stream = StringIO.StringIO()
    74         logging.debug("this should not be logged")
    75         self.assertEmpty(stream)
    76 
    77         printing._restore_logging(handler)
    78 
    79         stream = StringIO.StringIO()
    80         options, args = get_options(['--verbose'])
    81         handler = printing._configure_logging(stream, options.verbose)
    82         logging.debug("this should be logged")
    83         self.assertNotEmpty(stream)
    84         printing._restore_logging(handler)
    85 
    8656    def test_print_options(self):
    8757        options, args = get_options([])
    … …  
    145115        regular_output.isatty = lambda: tty
    146116        buildbot_output = StringIO.StringIO()
    147         printer = printing.Printer(self._port, options, regular_output,
    148                                    buildbot_output, configure_logging=True)
     117        printer = printing.Printer(self._port, options, regular_output, buildbot_output)
    149118        return printer, regular_output, buildbot_output
    150119
    … …  
    351320        paths, rs, exp = self.get_result_summary(tests, expectations)
    352321
    353         # First, test that we print nothing.
     322        # First, test that we print nothing when we shouldn't print anything.
    354323        printer.print_progress(rs, False, paths)
    355324        self.assertEmpty(out)
    … …  
    360329        self.assertEmpty(err)
    361330
    362         self.times = [1, 2, 12, 13, 14, 23, 33]
    363 
    364         def mock_time():
    365             return self.times.pop(0)
    366 
    367         orig_time = time.time
    368         try:
    369             time.time = mock_time
    370 
    371             # Test printing progress updates to a file.
    372             printer, err, out = self.get_printer(['--print', 'one-line-progress'])
    373             printer.print_progress(rs, False, paths)
    374             printer.print_progress(rs, False, paths)
    375             self.assertEmpty(out)
    376             self.assertEmpty(err)
    377 
    378             printer.print_progress(rs, False, paths)
    379             self.assertEmpty(out)
    380             self.assertNotEmpty(err)
    381 
    382             self.reset(err)
    383             self.reset(out)
    384             printer.print_progress(rs, True, paths)
    385             self.assertEmpty(out)
    386             self.assertEmpty(err)
    387 
    388             printer.print_progress(rs, True, paths)
    389             self.assertEmpty(out)
    390             self.assertNotEmpty(err)
    391 
    392             # Now reconfigure the printer to test printing to a TTY instead of a file.
    393             self.times = [1, 1.01, 2, 3]
    394             printer, err, out = self.get_printer(['--print', 'one-line-progress'], tty=True)
    395             printer.print_progress(rs, False, paths)
    396             printer.print_progress(rs, False, paths)
    397             self.assertEmpty(out)
    398             self.assertEmpty(err)
    399 
    400             printer.print_progress(rs, False, paths)
    401             self.assertEmpty(out)
    402             self.assertNotEmpty(err)
    403 
    404             self.reset(err)
    405             self.reset(out)
    406             printer.print_progress(rs, True, paths)
    407             self.assertEmpty(out)
    408             self.assertNotEmpty(err)
    409         finally:
    410             time.time = orig_time
     331        # Now test that we do print things.
     332        printer, err, out = self.get_printer(['--print', 'one-line-progress'])
     333        printer.print_progress(rs, False, paths)
     334        self.assertEmpty(out)
     335        self.assertNotEmpty(err)
     336
     337        printer, err, out = self.get_printer(['--print', 'one-line-progress'])
     338        printer.print_progress(rs, True, paths)
     339        self.assertEmpty(out)
     340        self.assertNotEmpty(err)
     341
     342        printer, err, out = self.get_printer(['--print', 'one-line-progress'])
     343        rs.remaining = 0
     344        printer.print_progress(rs, False, paths)
     345        self.assertEmpty(out)
     346        self.assertNotEmpty(err)
     347
     348        printer.print_progress(rs, True, paths)
     349        self.assertEmpty(out)
     350        self.assertNotEmpty(err)
     351
     352
    411353
    412354    def test_write_nothing(self):

  • trunk/Tools/Scripts/webkitpy/performance_tests/perftestsrunner.py

    r110933 r112014  
    6363            self._port = self._host.port_factory.get(self._options.platform, self._options)
    6464        self._host._initialize_scm()
    65         self._printer = printing.Printer(self._port, self._options, regular_output, buildbot_output, configure_logging=False)
     65        self._printer = printing.Printer(self._port, self._options, regular_output, buildbot_output)
    6666        self._webkit_base_dir_len = len(self._port.webkit_base())
    6767        self._base_path = self._port.perf_tests_dir()

  • trunk/Tools/Scripts/webkitpy/performance_tests/perftestsrunner_unittest.py

    r109491 r112014  
    183183
    184184        buildbot_output = StringIO.StringIO()
    185         runner = self.create_runner(buildbot_output, args=["--pause-before-testing"], driver_class=TestDriverWithStartCount)
     185        regular_output = StringIO.StringIO()
     186        runner = self.create_runner(buildbot_output, args=["--pause-before-testing"], regular_output=regular_output, driver_class=TestDriverWithStartCount)
    186187
    187188        dirname = runner._base_path + '/inspector/'
    … …  
    194195            self.assertEqual(TestDriverWithStartCount.start_count, 1)
    195196        finally:
    196             _, stderr, logs = output.restore_output()
     197            _, stderr, _ = output.restore_output()
    197198            self.assertEqual(stderr, "Ready to run test?\n")
    198             self.assertTrue("Running inspector/pass.html (1 of 1)" in logs)
     199            self.assertTrue("Running inspector/pass.html (1 of 1)" in regular_output.getvalue())
    199200
    200201    def test_run_test_set_for_parser_tests(self):
Note: See TracChangeset for help on using the changeset viewer.