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 ---
tools/binman/control.py | 3 ++ tools/binman/etype/blob.py | 5 +++ tools/binman/ftest.py | 8 +++++ tools/binman/state.py | 72 ++++++++++++++++++++++++++++++++++++++ 4 files changed, 88 insertions(+)
diff --git a/tools/binman/control.py b/tools/binman/control.py index b2113b6e64f..dcba02ff7f8 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 018f8c9a319..fae86ca3ec0 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 ceaa6a8737c..d93361778ec 100644 --- a/tools/binman/ftest.py +++ b/tools/binman/ftest.py @@ -4634,6 +4634,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 809429fbd9d..17d72cadecb 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 @@ -60,6 +62,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
@@ -444,3 +467,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))