[StGit PATCH 5/5] Global performance logging

["Karl Hasselström" <kha@treskal.com>]

Measure the time for the whole program, and how much of that was
subprocess calls.

Signed-off-by: Karl Hasselström <kha@treskal.com>

---

 stgit/main.py |   11 +++++++++--
 stgit/run.py  |   32 ++++++++++++++++++++++++++++----
 2 files changed, 37 insertions(+), 6 deletions(-)


diff --git a/stgit/main.py b/stgit/main.py
index aa1f8ef..64cff30 100644
--- a/stgit/main.py
+++ b/stgit/main.py
@@ -23,7 +23,7 @@ from optparse import OptionParser
 
 import stgit.commands
 from stgit.out import *
-from stgit import utils
+from stgit import run, utils
 
 #
 # The commands map
@@ -192,7 +192,7 @@ def print_help():
 #
 # The main function (command dispatcher)
 #
-def main():
+def _main():
     """The main function
     """
     global prog
@@ -293,3 +293,10 @@ def main():
         sys.exit(utils.STGIT_BUG_ERROR)
 
     sys.exit(ret or utils.STGIT_SUCCESS)
+
+def main():
+    run.start_logging()
+    try:
+        _main()
+    finally:
+        run.stop_logging()
diff --git a/stgit/run.py b/stgit/run.py
index befd3c1..e46836b 100644
--- a/stgit/run.py
+++ b/stgit/run.py
@@ -42,7 +42,27 @@ def get_log_mode(spec):
         f = out
     return (log_mode, f)
 
-(_log_mode, _logfile) = get_log_mode(os.environ.get('STGIT_SUBPROCESS_LOG', ''))
+def start_logging():
+    global _log_mode, _logfile, _log_starttime, _log_subproctime
+    (_log_mode, _logfile) = get_log_mode(
+        os.environ.get('STGIT_SUBPROCESS_LOG', ''))
+    _log_starttime = datetime.datetime.now()
+    _log_subproctime = 0.0
+
+def duration(t1, t2):
+    d = t2 - t1
+    return 86400*d.days + d.seconds + 1e-6*d.microseconds
+
+def stop_logging():
+    if _log_mode != 'profile':
+        return
+    ttime = duration(_log_starttime, datetime.datetime.now())
+    rtime = ttime - _log_subproctime
+    _logfile.info('Total time: %1.3f s' % ttime,
+                  'Time spent in subprocess calls: %1.3f s (%1.1f%%)'
+                  % (_log_subproctime, 100*_log_subproctime/ttime),
+                  'Remaining time: %1.3f s (%1.1f%%)'
+                  % (rtime, 100*rtime/ttime))
 
 class Run:
     exc = RunException
@@ -68,12 +88,16 @@ class Run:
             _logfile.start('Running subprocess %s' % self.__cmd)
             self.__starttime = datetime.datetime.now()
     def __log_end(self, retcode):
+        global _log_subproctime, _log_starttime
         if _log_mode == 'debug':
             _logfile.done('return code: %d' % retcode)
         elif _log_mode == 'profile':
-            duration = datetime.datetime.now() - self.__starttime
-            _logfile.done('%1.3f s' % (duration.microseconds/1e6
-                                       + duration.seconds))
+            n = datetime.datetime.now()
+            d = duration(self.__starttime, n)
+            _logfile.done('%1.3f s' % d)
+            _log_subproctime += d
+            _logfile.info('Time since program start: %1.3f s'
+                          % duration(_log_starttime, n))
     def __check_exitcode(self):
         if self.__good_retvals == None:
             return