feat: v-i now reports how long various parts of the process took

Sponsored-by: author

1 files changed, 30 insertions, 0 deletions

diff --git a/v-i b/v-i
index 761323b..c140089 100755
--- a/v-i
+++ b/v-i
@@ -8,6 +8,7 @@ import shutil
 import subprocess
 import sys
 import tempfile
+import time
 import yaml
 
 
@@ -379,6 +380,27 @@ def vmdb_spec(system, ansible_vars):
     return {"steps": steps}
 
 
+class Timings:
+    def __init__(self):
+        self.started = time.time()
+        self.times = {}
+        self.whats = []
+
+    def reached(self, what):
+        assert what not in self.whats
+        assert what not in self.times
+        self.times[what] = time.time()
+        self.whats.append(what)
+
+    def report(self):
+        prev = self.started
+        for what in self.whats:
+            secs = "%.1f" % (self.times[what] - prev)
+            prev = self.times[what]
+            log(f"Duration: {what}: {secs} s")
+            print(f"Duration: {what}: {secs} s")
+
+
 def cache_name(spec):
     return f"{spec.debian_release}.cache.tar.gz"
 
@@ -445,6 +467,8 @@ class SystemSpec:
 
 
 def main():
+    timings = Timings()
+
     p = argparse.ArgumentParser()
     p.add_argument("--verbose", action="store_true")
     p.add_argument("--very-verbose", action="store_true")
@@ -478,8 +502,10 @@ def main():
             vars_dict = yaml.safe_load(f)
         ansible_vars.update(vars_dict)
     log(f"ansible_vars: {ansible_vars!r}")
+    timings.reached("read configuration")
 
     clean_up_disks([system.drive] + system.extra_drives)
+    timings.reached("clean up storage")
 
     vmdb = vmdb_spec(system, ansible_vars)
     tmp = tempfile.mkdtemp()
@@ -505,12 +531,16 @@ def main():
     if verbose:
         argv.append("--verbose")
     run(argv, check=True, capture_output=True)
+    timings.reached("vmdb2")
 
     log("cleanup")
     shutil.rmtree(tmp)
+    timings.reached("clean up")
 
     log("OK, done")
     print("OK, done")
 
+    timings.report()
+
 
 main()