-_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))