Bug 948272 - Report more timings from moz.build; r=glandium

The big change is we now explicitly record time spent in emitter.py. We
also report how much untracked time was measured.

--HG--
extra : rebase_source : f2a867718f0d532748e337abdc6e1c5070646dd7

python/mozbuild/mozbuild/backend/base.py

@@ -66,20 +66,29 @@ class BackendConsumeSummary(object):
         # the read and execute time. It does not cover consume time.
         self.mozbuild_execution_time = 0.0
 
+        # The total wall time spent emitting objects from sandboxes.
+        self.emitter_execution_time = 0.0
+
         # The total wall time spent in the backend. This counts the time the
         # backend writes out files, etc.
         self.backend_execution_time = 0.0
 
         # How much wall time the system spent doing other things. This is
-        # wall_time - mozbuild_execution_time - backend_execution_time.
+        # wall_time - mozbuild_execution_time - emitter_execution_time -
+        # backend_execution_time.
         self.other_time = 0.0
 
     @property
     def reader_summary(self):
-        return 'Finished reading {:d} moz.build files into {:d} descriptors in {:.2f}s'.format(
-            self.mozbuild_count, self.object_count,
+        return 'Finished reading {:d} moz.build files in {:.2f}s'.format(
+            self.mozbuild_count,
             self.mozbuild_execution_time)
 
+    @property
+    def emitter_summary(self):
+        return 'Processed into {:d} build config descriptors in {:.2f}s'.format(
+            self.object_count, self.emitter_execution_time)
+
     @property
     def backend_summary(self):
         return 'Backend executed in {:.2f}s'.format(self.backend_execution_time)
@@ -91,11 +100,14 @@ class BackendConsumeSummary(object):
     @property
     def total_summary(self):
         efficiency_value = self.cpu_time / self.wall_time if self.wall_time else 100
-        return 'Total wall time: {:.2f}s; CPU time: {:.2f}s; Efficiency: {:.0%}'.format(
-            self.wall_time, self.cpu_time, efficiency_value)
+        return 'Total wall time: {:.2f}s; CPU time: {:.2f}s; Efficiency: ' \
+            '{:.0%}; Untracked: {:.2f}s'.format(
+                self.wall_time, self.cpu_time, efficiency_value,
+                self.other_time)
 
     def summaries(self):
         yield self.reader_summary
+        yield self.emitter_summary
         yield self.backend_summary
 
         detailed = self.backend_detailed_summary()
@@ -197,7 +209,8 @@ class BuildBackend(LoggingMixin):
 
             if isinstance(obj, ReaderSummary):
                 self.summary.mozbuild_count = obj.total_file_count
-                self.summary.mozbuild_execution_time = obj.total_execution_time
+                self.summary.mozbuild_execution_time = obj.total_sandbox_execution_time
+                self.summary.emitter_execution_time = obj.total_emitter_execution_time
 
         finished_start = time.time()
         self.consume_finished()
@@ -232,6 +245,7 @@ class BuildBackend(LoggingMixin):
         self.summary.backend_execution_time = backend_time
         self.summary.other_time = self.summary.wall_time - \
             self.summary.mozbuild_execution_time - \
+            self.summary.emitter_execution_time - \
             self.summary.backend_execution_time
 
         return self.summary

python/mozbuild/mozbuild/frontend/data.py

@@ -41,10 +41,12 @@ class TreeMetadata(object):
 class ReaderSummary(TreeMetadata):
     """A summary of what the reader did."""
 
-    def __init__(self, total_file_count, total_execution_time):
+    def __init__(self, total_file_count, total_sandbox_execution_time,
+        total_emitter_execution_time):
         TreeMetadata.__init__(self)
         self.total_file_count = total_file_count
-        self.total_execution_time = total_execution_time
+        self.total_sandbox_execution_time = total_sandbox_execution_time
+        self.total_emitter_execution_time = total_emitter_execution_time
 
 
 class SandboxDerived(TreeMetadata):

python/mozbuild/mozbuild/frontend/emitter.py

@@ -9,6 +9,7 @@ import logging
 import os
 import traceback
 import sys
+import time
 
 from mach.mixin.logging import LoggingMixin
 
@@ -79,26 +80,44 @@ class TreeMetadataEmitter(LoggingMixin):
         typically fed into this function.
         """
         file_count = 0
-        execution_time = 0.0
+        sandbox_execution_time = 0.0
+        emitter_time = 0.0
         sandboxes = {}
 
+        def emit_objs(objs):
+            for o in objs:
+                yield o
+                if not o._ack:
+                    raise Exception('Unhandled object of type %s' % type(o))
+
         for out in output:
             if isinstance(out, MozbuildSandbox):
                 # Keep all sandboxes around, we will need them later.
                 sandboxes[out['OBJDIR']] = out
 
-                for o in self.emit_from_sandbox(out):
-                    yield o
-                    if not o._ack:
-                        raise Exception('Unhandled object of type %s' % type(o))
+                start = time.time()
+                # We need to expand the generator for the timings to work.
+                objs = list(self.emit_from_sandbox(out))
+                emitter_time += time.time() - start
+
+                for o in emit_objs(objs): yield o
 
                 # Update the stats.
                 file_count += len(out.all_paths)
-                execution_time += out.execution_time
+                sandbox_execution_time += out.execution_time
 
             else:
                 raise Exception('Unhandled output type: %s' % out)
 
+        start = time.time()
+        objs = list(self._emit_libs_derived(sandboxes))
+        emitter_time += time.time() - start
+
+        for o in emit_objs(objs): yield o
+
+        yield ReaderSummary(file_count, sandbox_execution_time, emitter_time)
+
+    def _emit_libs_derived(self, sandboxes):
         for objdir, libname, final_lib in self._final_libs:
             if final_lib not in self._libs:
                 raise Exception('FINAL_LIBRARY in %s (%s) does not match any '
@@ -134,8 +153,6 @@ class TreeMetadataEmitter(LoggingMixin):
                         yield passthru
                 yield libdef
 
-        yield ReaderSummary(file_count, execution_time)
-
     def emit_from_sandbox(self, sandbox):
         """Convert a MozbuildSandbox to tree metadata objects.