binman: Add basic support for debugging performance

One of binman's attributes is that it is extremely fast, at least for a
Python program. Add some simple timing around operations that might take
a while, such as reading an image and compressing it. This should help
to maintain the performance as new features are added.

This is for debugging purposes only.

Signed-off-by: Simon Glass <sjg@chromium.org>

4 files changed, 88 insertions, 0 deletions

diff --git a/tools/binman/control.py b/tools/binman/control.py
index b2113b6e64..dcba02ff7f 100644
--- a/tools/binman/control.py
+++ b/tools/binman/control.py
@@ -646,6 +646,9 @@ def Binman(args):
 
             if missing:
                 tout.Warning("\nSome images are invalid")
+
+            # Use this to debug the time take to pack the image
+            #state.TimingShow()
         finally:
             tools.FinaliseOutputDir()
     finally:
diff --git a/tools/binman/etype/blob.py b/tools/binman/etype/blob.py
index 018f8c9a31..fae86ca3ec 100644
--- a/tools/binman/etype/blob.py
+++ b/tools/binman/etype/blob.py
@@ -6,6 +6,7 @@
 #
 
 from binman.entry import Entry
+from binman import state
 from dtoc import fdt_util
 from patman import tools
 from patman import tout
@@ -59,8 +60,12 @@ class Entry_blob(Entry):
         the data in chunks and avoid reading it all at once. For now
         this seems like an unnecessary complication.
         """
+        state.TimingStart('read')
         indata = tools.ReadFile(self._pathname)
+        state.TimingAccum('read')
+        state.TimingStart('compress')
         data = self.CompressData(indata)
+        state.TimingAccum('compress')
         self.SetContents(data)
         return True
 
diff --git a/tools/binman/ftest.py b/tools/binman/ftest.py
index 531ea65771..cea3ebf2b9 100644
--- a/tools/binman/ftest.py
+++ b/tools/binman/ftest.py
@@ -4568,6 +4568,14 @@ class TestFunctional(unittest.TestCase):
         self.assertIn("Node '/binman/section@0': Timed out obtaining contents",
                       str(e.exception))
 
+    def testTiming(self):
+        """Test output of timing information"""
+        data = self._DoReadFile('055_sections.dts')
+        with test_util.capture_sys_output() as (stdout, stderr):
+            state.TimingShow()
+        self.assertIn('read:', stdout.getvalue())
+        self.assertIn('compress:', stdout.getvalue())
+
 
 if __name__ == "__main__":
     unittest.main()
diff --git a/tools/binman/state.py b/tools/binman/state.py
index 2f56758738..9e5b8a3931 100644
--- a/tools/binman/state.py
+++ b/tools/binman/state.py
@@ -5,8 +5,10 @@
 # Holds and modifies the state information held by binman
 #
 
+from collections import defaultdict
 import hashlib
 import re
+import time
 import threading
 
 from dtoc import fdt
@@ -59,6 +61,27 @@ allow_entry_contraction = False
 # Number of threads to use for binman (None means machine-dependent)
 num_threads = None
 
+
+class Timing:
+    """Holds information about an operation that is being timed
+
+    Properties:
+        name: Operation name (only one of each name is stored)
+        start: Start time of operation in seconds (None if not start)
+        accum:: Amount of time spent on this operation so far, in seconds
+    """
+    def __init__(self, name):
+        self.name = name
+        self.start = None # cause an error if TimingStart() is not called
+        self.accum = 0.0
+
+
+# Holds timing info for each name:
+#    key: name of Timing info (Timing.name)
+#    value: Timing object
+timing_info = {}
+
+
 def GetFdtForEtype(etype):
     """Get the Fdt object for a particular device-tree entry
 
@@ -443,3 +466,52 @@ def GetThreads():
         Number of threads to use (None for default, 0 for single-threaded)
     """
     return num_threads
+
+def GetTiming(name):
+    """Get the timing info for a particular operation
+
+    The object is created if it does not already exist.
+
+    Args:
+        name: Operation name to get
+
+    Returns:
+        Timing object for the current thread
+    """
+    threaded_name = '%s:%d' % (name, threading.get_ident())
+    timing = timing_info.get(threaded_name)
+    if not timing:
+        timing = Timing(threaded_name)
+        timing_info[threaded_name] = timing
+    return timing
+
+def TimingStart(name):
+    """Start the timer for an operation
+
+    Args:
+        name: Operation name to start
+    """
+    timing = GetTiming(name)
+    timing.start = time.monotonic()
+
+def TimingAccum(name):
+    """Stop and accumlate the time for an operation
+
+    This measures the time since the last TimingStart() and adds that to the
+    accumulated time.
+
+    Args:
+        name: Operation name to start
+    """
+    timing = GetTiming(name)
+    timing.accum += time.monotonic() - timing.start
+
+def TimingShow():
+    """Show all timing information"""
+    duration = defaultdict(float)
+    for threaded_name, timing in timing_info.items():
+        name = threaded_name.split(':')[0]
+        duration[name] += timing.accum
+
+    for name, seconds in duration.items():
+        print('%10s: %10.1fms' % (name, seconds * 1000))