Bug 883209 - Part 1: Record system resource usage of builds; r=glandium

build/mach_bootstrap.py

@@ -50,6 +50,7 @@ SEARCH_PATHS = [
     'testing/mozbase/mozprocess',
     'testing/mozbase/mozprofile',
     'testing/mozbase/mozrunner',
+    'testing/mozbase/mozsystemmonitor',
     'testing/mozbase/mozinfo',
     'testing/mozbase/manifestdestiny',
     'xpcom/idl-parser',

python/mozbuild/mozbuild/controller/building.py

@@ -5,6 +5,8 @@
 from __future__ import unicode_literals
 
 import getpass
+import json
+import logging
 import os
 import sys
 import time
@@ -23,6 +25,8 @@ if sys.platform.startswith("freebsd") or sys.platform.startswith("darwin") or sy
 else:
     psutil = None
 
+from mozsystemmonitor.resourcemonitor import SystemResourceMonitor
+
 from ..base import MozbuildObject
 
 from ..compilation.warnings import (
@@ -48,10 +52,12 @@ class TierStatus(object):
     like subtiers.
     """
 
-    def __init__(self):
+    def __init__(self, resources):
+        """Accepts a SystemResourceMonitor to record results against."""
         self.tiers = OrderedDict()
         self.active_tier = None
         self.active_subtiers = set()
+        self.resources = resources
 
     def set_tiers(self, tiers):
         """Record the set of known tiers."""
@@ -69,6 +75,7 @@ class TierStatus(object):
         # We should ideally use a monotonic clock here. Unfortunately, we won't
         # have one until Python 3.
         t['begin_time'] = time.time()
+        self.resources.begin_phase(self._phase(tier))
         for subtier in subtiers:
             t['subtiers'][subtier] = dict(
                 begin_time=None,
@@ -87,10 +94,11 @@ class TierStatus(object):
         """Record that execution of a tier has finished."""
         t = self.tiers[tier]
         t['finish_time'] = time.time()
-        t['duration'] = t['finish_time'] - t['begin_time']
+        t['duration'] = self.resources.finish_phase(self._phase(tier))
 
     def begin_subtier(self, tier, subtier, dirs):
         """Record that execution of a subtier has begun."""
+        self.resources.begin_phase(self._phase(tier, subtier))
         st = self.tiers[tier]['subtiers'][subtier]
         st['begin_time'] = time.time()
 
@@ -122,10 +130,11 @@ class TierStatus(object):
         except KeyError:
             pass
 
-        st['duration'] = st['finish_time'] - st['begin_time']
+        st['duration'] = self.resources.finish_phase(self._phase(tier, subtier))
 
     def begin_dir(self, tier, subtier, d):
         """Record that execution of a directory has begun."""
+        self.resources.begin_phase(self._phase(tier, subtier, d))
         entry = self.tiers[tier]['subtiers'][subtier]['dirs'][d]
         entry['begin_time'] = time.time()
 
@@ -143,11 +152,12 @@ class TierStatus(object):
         entry['finish_time'] = time.time()
 
         self.active_dirs[subtier].remove(d)
-        entry['duration'] = entry['finish_time'] - entry['begin_time']
-
         if self.active_dirs[subtier]:
             entry['concurrent'] = True
 
+        entry['duration'] = self.resources.finish_phase(self._phase(tier,
+            subtier, d))
+
     def tier_status(self):
         for tier, state in self.tiers.items():
             active = self.active_tier == tier
@@ -167,6 +177,93 @@ class TierStatus(object):
             st = self.tiers[self.active_tier]['subtiers'][subtier]
             yield subtier, st['dirs'].keys(), dirs, st['dirs_complete']
 
+    def tiered_resource_usage(self):
+        """Obtains an object containing resource usage for tiers.
+
+        The returned object is suitable for serialization.
+        """
+        o = []
+
+        for tier, state in self.tiers.items():
+            t_entry = dict(
+                name=tier,
+                start=state['begin_time'],
+                end=state['finish_time'],
+                duration=state['duration'],
+                subtiers=[],
+            )
+
+            self.add_resources_to_dict(t_entry, phase=self._phase(tier))
+
+            for subtier, state in state['subtiers'].items():
+                st_entry = dict(
+                    name=subtier,
+                    start=state['begin_time'],
+                    end=state['finish_time'],
+                    duration=state['duration'],
+                    concurrent=state['concurrent'],
+                    dirs=[],
+                )
+
+                self.add_resources_to_dict(st_entry, phase=self._phase(tier,
+                    subtier))
+
+                for d, state in state['dirs'].items():
+                    d_entry = dict(
+                        name=d,
+                        start=state['begin_time'],
+                        end=state['finish_time'],
+                        duration=state['duration'],
+                    )
+
+                    self.add_resources_to_dict(d_entry, phase=self._phase(tier,
+                        subtier, d))
+
+                    st_entry['dirs'].append(d_entry)
+
+                t_entry['subtiers'].append(st_entry)
+
+            o.append(t_entry)
+
+        return o
+
+    def add_resources_to_dict(self, entry, start=None, end=None, phase=None):
+        """Helper function to append resource information to a dict."""
+        cpu_percent = self.resources.aggregate_cpu_percent(start=start,
+            end=end, phase=phase, per_cpu=False)
+        cpu_times = self.resources.aggregate_cpu_times(start=start, end=end,
+            phase=phase, per_cpu=False)
+        io = self.resources.aggregate_io(start=start, end=end, phase=phase)
+
+        if cpu_percent is None:
+            return entry
+
+        entry['cpu_percent'] = cpu_percent
+        entry['cpu_times'] = list(cpu_times)
+        entry['io'] = list(io)
+
+        return entry
+
+    def add_resource_fields_to_dict(self, d):
+        for usage in self.resources.range_usage():
+            cpu_times = self.resources.aggregate_cpu_times(per_cpu=False)
+
+            d['cpu_times_fields'] = list(cpu_times._fields)
+            d['io_fields'] = list(usage.io._fields)
+            d['virt_fields'] = list(usage.virt._fields)
+            d['swap_fields'] = list(usage.swap._fields)
+
+            return d
+
+    def _phase(self, tier, subtier=None, d=None):
+        parts = [tier]
+        if subtier:
+            parts.append(subtier)
+        if d:
+            parts.append(d)
+
+        return '_'.join(parts)
+
 
 class BuildMonitor(MozbuildObject):
     """Monitors the output of the build."""
@@ -177,8 +274,10 @@ class BuildMonitor(MozbuildObject):
         warnings_path is a path of a warnings database to use.
         """
         self._warnings_path = warnings_path
+        self.resources = SystemResourceMonitor(poll_interval=1.0)
+        self._resources_started = False
 
-        self.tiers = TierStatus()
+        self.tiers = TierStatus(self.resources)
 
         self.warnings_database = WarningsDatabase()
         if os.path.exists(warnings_path):
@@ -195,6 +294,11 @@ class BuildMonitor(MozbuildObject):
         self.start_time = time.time()
         self._finder_start_cpu = self._get_finder_cpu_usage()
 
+    def start_resource_recording(self):
+        # This should be merged into start() once bug 892342 lands.
+        self.resources.start()
+        self._resources_started = True
+
     def on_line(self, line):
         """Consume a line of output from the build system.
 
@@ -257,15 +361,29 @@ class BuildMonitor(MozbuildObject):
 
         return BuildOutputResult(warning, False, True)
 
-    def finish(self):
+    def finish(self, record_usage=True):
         """Record the end of the build."""
         self.end_time = time.time()
+
+        if self._resources_started:
+            self.resources.stop()
+
         self._finder_end_cpu = self._get_finder_cpu_usage()
         self.elapsed = self.end_time - self.start_time
 
         self.warnings_database.prune()
         self.warnings_database.save_to_file(self._warnings_path)
 
+        if not record_usage:
+            return
+
+        usage = self.record_resource_usage()
+        if not usage:
+            return
+
+        with open(self._get_state_filename('build_resources.json'), 'w') as fh:
+            json.dump(usage, fh, indent=2)
+
     def _get_finder_cpu_usage(self):
         """Obtain the CPU usage of the Finder app on OS X.
 
@@ -322,3 +440,88 @@ class BuildMonitor(MozbuildObject):
         finder_percent = cpu_seconds / self.elapsed * 100
 
         return finder_percent > 25, finder_percent
+
+    @property
+    def have_resource_usage(self):
+        """Whether resource usage is available."""
+        return self.resources.start_time is not None
+
+    def record_resource_usage(self):
+        """Record the resource usage of this build.
+
+        We write a log message containing a high-level summary. We also produce
+        a data structure containing the low-level resource usage information.
+        This data structure can e.g. be serialized into JSON and saved for
+        subsequent analysis.
+
+        If no resource usage is available, None is returned.
+        """
+        if not self.have_resource_usage:
+            return None
+
+        cpu_percent = self.resources.aggregate_cpu_percent(phase=None,
+            per_cpu=False)
+        cpu_times = self.resources.aggregate_cpu_times(phase=None,
+            per_cpu=False)
+        io = self.resources.aggregate_io(phase=None)
+
+        self._log_resource_usage('Overall system resources', 'resource_usage',
+            self.end_time - self.start_time, cpu_percent, cpu_times, io)
+
+        o = dict(
+            version=1,
+            start=self.start_time,
+            end=self.end_time,
+            duration=self.end_time - self.start_time,
+            resources=[],
+            cpu_percent=cpu_percent,
+            cpu_times=cpu_times,
+            io=io,
+        )
+
+        o['tiers'] = self.tiers.tiered_resource_usage()
+
+        self.tiers.add_resource_fields_to_dict(o)
+
+        for usage in self.resources.range_usage():
+            cpu_percent = self.resources.aggregate_cpu_percent(usage.start,
+                usage.end, per_cpu=False)
+            cpu_times = self.resources.aggregate_cpu_times(usage.start,
+                usage.end, per_cpu=False)
+
+            entry = dict(
+                start=usage.start,
+                end=usage.end,
+                virt=list(usage.virt),
+                swap=list(usage.swap),
+            )
+
+            self.tiers.add_resources_to_dict(entry, start=usage.start,
+                    end=usage.end)
+
+            o['resources'].append(entry)
+
+        return o
+
+    def _log_resource_usage(self, prefix, m_type, duration, cpu_percent,
+        cpu_times, io, extra_params={}):
+
+        params = dict(
+            duration=duration,
+            cpu_percent=cpu_percent,
+            io_reads=io.read_count,
+            io_writes=io.write_count,
+            io_read_bytes=io.read_bytes,
+            io_write_bytes=io.write_bytes,
+            io_read_time=io.read_time,
+            io_write_time=io.write_time,
+        )
+
+        params.update(extra_params)
+
+        message = prefix + ' - Wall time: {duration:.0f}s; ' \
+            'CPU: {cpu_percent:.0f}%; ' \
+            'Read bytes: {io_read_bytes}; Write bytes: {io_write_bytes}; ' \
+            'Read time: {io_read_time}; Write time: {io_write_time}'
+
+        self.log(logging.WARNING, m_type, params, message)

python/mozbuild/mozbuild/mach_commands.py

@@ -223,12 +223,12 @@ class BuildOutputManager(LoggingMixin):
         self.t = terminal
         self.footer = BuildProgressFooter(terminal, monitor)
 
-        self.handler = TerminalLoggingHandler()
-        self.handler.setFormatter(log_manager.terminal_formatter)
-        self.handler.footer = self.footer
+        self._handler = TerminalLoggingHandler()
+        self._handler.setFormatter(log_manager.terminal_formatter)
+        self._handler.footer = self.footer
 
-        old = log_manager.replace_terminal_handler(self.handler)
-        self.handler.level = old.level
+        old = log_manager.replace_terminal_handler(self._handler)
+        self._handler.level = old.level
 
     def __enter__(self):
         return self
@@ -236,6 +236,8 @@ class BuildOutputManager(LoggingMixin):
     def __exit__(self, exc_type, exc_value, traceback):
         if self.footer:
             self.footer.clear()
+            # Prevents the footer from being redrawn if logging occurs.
+            self._handler.footer = None
 
     def write_line(self, line):
         if self.footer:
@@ -290,6 +292,8 @@ class Build(MachCommandBase):
         from mozbuild.controller.building import BuildMonitor
         from mozbuild.util import resolve_target_to_make
 
+        self.log_manager.register_structured_logger(logging.getLogger('mozbuild'))
+
         warnings_path = self._get_state_filename('warnings.json')
         monitor = self._spawn(BuildMonitor)
         monitor.init(warnings_path)
@@ -353,6 +357,7 @@ class Build(MachCommandBase):
                     if status != 0:
                         break
             else:
+                monitor.start_resource_recording()
                 status = self._run_make(srcdir=True, filename='client.mk',
                     line_handler=output.on_line, log=False, print_directory=False,
                     allow_parallel=False, ensure_exit_code=False, num_jobs=jobs,
@@ -362,7 +367,7 @@ class Build(MachCommandBase):
                     {'count': len(monitor.warnings_database)},
                     '{count} compiler warnings present.')
 
-            monitor.finish()
+            monitor.finish(record_usage=status==0)
 
         high_finder, finder_percent = monitor.have_high_finder_usage()
         if high_finder: