Browse Source

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>
Simon Glass 2 years ago
parent
commit
03ebc20de3
4 changed files with 88 additions and 0 deletions
  1. 3 0
      tools/binman/control.py
  2. 5 0
      tools/binman/etype/blob.py
  3. 8 0
      tools/binman/ftest.py
  4. 72 0
      tools/binman/state.py

+ 3 - 0
tools/binman/control.py

@@ -646,6 +646,9 @@ def Binman(args):
 
 
             if missing:
             if missing:
                 tout.Warning("\nSome images are invalid")
                 tout.Warning("\nSome images are invalid")
+
+            # Use this to debug the time take to pack the image
+            #state.TimingShow()
         finally:
         finally:
             tools.FinaliseOutputDir()
             tools.FinaliseOutputDir()
     finally:
     finally:

+ 5 - 0
tools/binman/etype/blob.py

@@ -6,6 +6,7 @@
 #
 #
 
 
 from binman.entry import Entry
 from binman.entry import Entry
+from binman import state
 from dtoc import fdt_util
 from dtoc import fdt_util
 from patman import tools
 from patman import tools
 from patman import tout
 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
         the data in chunks and avoid reading it all at once. For now
         this seems like an unnecessary complication.
         this seems like an unnecessary complication.
         """
         """
+        state.TimingStart('read')
         indata = tools.ReadFile(self._pathname)
         indata = tools.ReadFile(self._pathname)
+        state.TimingAccum('read')
+        state.TimingStart('compress')
         data = self.CompressData(indata)
         data = self.CompressData(indata)
+        state.TimingAccum('compress')
         self.SetContents(data)
         self.SetContents(data)
         return True
         return True
 
 

+ 8 - 0
tools/binman/ftest.py

@@ -4568,6 +4568,14 @@ class TestFunctional(unittest.TestCase):
         self.assertIn("Node '/binman/section@0': Timed out obtaining contents",
         self.assertIn("Node '/binman/section@0': Timed out obtaining contents",
                       str(e.exception))
                       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__":
 if __name__ == "__main__":
     unittest.main()
     unittest.main()

+ 72 - 0
tools/binman/state.py

@@ -5,8 +5,10 @@
 # Holds and modifies the state information held by binman
 # Holds and modifies the state information held by binman
 #
 #
 
 
+from collections import defaultdict
 import hashlib
 import hashlib
 import re
 import re
+import time
 import threading
 import threading
 
 
 from dtoc import fdt
 from dtoc import fdt
@@ -59,6 +61,27 @@ allow_entry_contraction = False
 # Number of threads to use for binman (None means machine-dependent)
 # Number of threads to use for binman (None means machine-dependent)
 num_threads = None
 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):
 def GetFdtForEtype(etype):
     """Get the Fdt object for a particular device-tree entry
     """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)
         Number of threads to use (None for default, 0 for single-threaded)
     """
     """
     return num_threads
     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))