Merge branch 'proposed' of git://github.com/gustavh/stgit

[stgit] / stgit / run.py

diff --git a/stgit/run.py b/stgit/run.py
index 77f2e6595c1639c5d2cbdabf62c46a44008a6f04..2d8ed348b67883f19f050ce89aa8347b417e2e2a 100644 (file)
--- a/stgit/run.py
+++ b/stgit/run.py
@@ -27,12 +27,40 @@ class RunException(StgException):
     subprocess."""
     pass
 
-_all_log_modes = ['debug', 'profile']
-_log_mode = os.environ.get('STGIT_SUBPROCESS_LOG', '')
-if _log_mode and not _log_mode in _all_log_modes:
-    out.warn(('Unknown log mode "%s" specified in $STGIT_SUBPROCESS_LOG.'
-              % _log_mode),
-             'Valid values are: %s' % ', '.join(_all_log_modes))
+def get_log_mode(spec):
+    if not ':' in spec:
+        spec += ':'
+    (log_mode, outfile) = spec.split(':', 1)
+    all_log_modes = ['debug', 'profile']
+    if log_mode and not log_mode in all_log_modes:
+        out.warn(('Unknown log mode "%s" specified in $STGIT_SUBPROCESS_LOG.'
+                  % log_mode),
+                 'Valid values are: %s' % ', '.join(all_log_modes))
+    if outfile:
+        f = MessagePrinter(open(outfile, 'a'))
+    else:
+        f = out
+    return (log_mode, f)
+
+(_log_mode, _logfile) = get_log_mode(os.environ.get('STGIT_SUBPROCESS_LOG', ''))
+if _log_mode == 'profile':
+    _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 finish_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
@@ -47,16 +75,27 @@ class Run:
         self.__discard_stderr = False
     def __log_start(self):
         if _log_mode == 'debug':
-            out.start('Running subprocess %s' % self.__cmd)
+            _logfile.start('Running subprocess %s' % self.__cmd)
+            if self.__cwd != None:
+                _logfile.info('cwd: %s' % self.__cwd)
+            if self.__env != None:
+                for k in sorted(self.__env.iterkeys()):
+                    if k not in os.environ or os.environ[k] != self.__env[k]:
+                        _logfile.info('%s: %s' % (k, self.__env[k]))
         elif _log_mode == 'profile':
-            out.start('Running subprocess %s' % self.__cmd[0])
+            _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':
-            out.done('return code: %d' % retcode)
+            _logfile.done('return code: %d' % retcode)
         elif _log_mode == 'profile':
-            duration = datetime.datetime.now() - self.__starttime
-            out.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
@@ -71,7 +110,11 @@ class Run:
                                  stdin = subprocess.PIPE,
                                  stdout = subprocess.PIPE,
                                  stderr = subprocess.PIPE)
-            outdata, errdata = p.communicate(self.__indata)
+            # TODO: only use communicate() once support for Python 2.4 is
+            # dropped (write() needed because of performance reasons)
+            if self.__indata:
+                p.stdin.write(self.__indata)
+            outdata, errdata = p.communicate()
             self.exitcode = p.returncode
         except OSError, e:
             raise self.exc('%s failed: %s' % (self.__cmd[0], e))