Bug 1250624 - Overall system resources is displayed twice; r?chmanchester draft
authorDan Minor <dminor@mozilla.com>
Wed, 24 Feb 2016 09:18:03 -0800
changeset 334591 6a3c50b842e404a2e3819b686a5030312329fad0
parent 334101 d848a5628d801a460a7244cbcdea22d328d8b310
child 514951 af830e5c933a55206442415793479cafbdab3dc5
push id11590
push userdminor@mozilla.com
push dateThu, 25 Feb 2016 17:49:19 +0000
reviewerschmanchester
bugs1250624
milestone47.0a1
Bug 1250624 - Overall system resources is displayed twice; r?chmanchester MozReview-Commit-ID: Hbx8lOlrUuw
python/mozbuild/mozbuild/controller/building.py
python/mozbuild/mozbuild/mach_commands.py
--- a/python/mozbuild/mozbuild/controller/building.py
+++ b/python/mozbuild/mozbuild/controller/building.py
@@ -246,20 +246,21 @@ class BuildMonitor(MozbuildObject):
 
         self.warnings_database.prune()
         self.warnings_database.save_to_file(self._warnings_path)
 
         if not record_usage:
             return
 
         try:
-            usage = self.record_resource_usage()
+            usage = self.get_resource_usage()
             if not usage:
                 return
 
+            self.log_resource_usage(usage)
             with open(self._get_state_filename('build_resources.json'), 'w') as fh:
                 json.dump(usage, fh, indent=2)
         except Exception as e:
             self.log(logging.WARNING, 'build_resources_error',
                 {'msg': str(e)},
                 'Exception when writing resource usage file: {msg}')
 
     def _get_finder_cpu_usage(self):
@@ -341,46 +342,33 @@ class BuildMonitor(MozbuildObject):
         excessive = swap_in > 512 * 1048576 or swap_out > 512 * 1048576
         return excessive, swap_in, swap_out
 
     @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.
+    def get_resource_usage(self):
+        """ Produce a data structure containing the low-level resource usage information.
 
-        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)
-
-        excessive, sin, sout = self.have_excessive_swapping()
-        if excessive is not None and (sin or sout):
-            sin /= 1048576
-            sout /= 1048576
-            self.log(logging.WARNING, 'swap_activity',
-                {'sin': sin, 'sout': sout},
-                'Swap in/out (MB): {sin}/{sout}')
-
         o = dict(
             version=3,
             argv=sys.argv,
             start=self.start_time,
             end=self.end_time,
             duration=self.end_time - self.start_time,
             resources=[],
             cpu_percent=cpu_percent,
@@ -425,38 +413,45 @@ class BuildMonitor(MozbuildObject):
                 logical_cpu_count=psutil.cpu_count(),
                 physical_cpu_count=psutil.cpu_count(logical=False),
                 swap_total=psutil.swap_memory()[0],
                 vmem_total=psutil.virtual_memory()[0],
             ))
 
         return o
 
-    def _log_resource_usage(self, prefix, m_type, duration, cpu_percent,
-        cpu_times, io, extra_params={}):
+    def log_resource_usage(self, usage):
+        """Summarize the resource usage of this build in a log message."""
+
+        if not usage:
+            return
 
         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,
+            duration=self.end_time - self.start_time,
+            cpu_percent=usage['cpu_percent'],
+            io_read_bytes=usage['io'].read_bytes,
+            io_write_bytes=usage['io'].write_bytes,
+            io_read_time=usage['io'].read_time,
+            io_write_time=usage['io'].write_time,
         )
 
-        params.update(extra_params)
-
-        message = prefix + ' - Wall time: {duration:.0f}s; ' \
+        message = 'Overall system resources - 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)
+        self.log(logging.WARNING, 'resource_usage', params, message)
+
+        excessive, sin, sout = self.have_excessive_swapping()
+        if excessive is not None and (sin or sout):
+            sin /= 1048576
+            sout /= 1048576
+            self.log(logging.WARNING, 'swap_activity',
+                {'sin': sin, 'sout': sout},
+                'Swap in/out (MB): {sin}/{sout}')
 
     def ccache_stats(self):
         ccache_stats = None
 
         try:
             ccache = which.which('ccache')
             output = subprocess.check_output([ccache, '-s'])
             ccache_stats = CCacheStats(output)
--- a/python/mozbuild/mozbuild/mach_commands.py
+++ b/python/mozbuild/mozbuild/mach_commands.py
@@ -491,17 +491,17 @@ class Build(MachCommandBase):
             # if excessive:
             #    print(EXCESSIVE_SWAP_MESSAGE)
 
             print('To view resource usage of the build, run |mach '
                 'resource-usage|.')
 
             telemetry_handler = getattr(self._mach_context,
                                         'telemetry_handler', None)
-            telemetry_data = monitor.record_resource_usage()
+            telemetry_data = monitor.get_resource_usage()
 
             # Record build configuration data. For now, we cherry pick
             # items we need rather than grabbing everything, in order
             # to avoid accidentally disclosing PII.
             try:
                 moz_artifact_builds = self.substs.get('MOZ_ARTIFACT_BUILDS',
                                                       False)
                 telemetry_data['substs'] = {