Measure the time for the whole program, and how much of that was
subprocess calls.
Signed-off-by: Karl Hasselström <kha@xxxxxxxxxxx>
---
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
--
To unsubscribe from this list: send the line "unsubscribe git" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
