{"thread":{"id":"14511","subject":"[StGit PATCH 1/5] Add some performance testing scripts","startedAt":"2008-07-17T20:42:20Z","lastAt":"2008-07-18T21:47:46Z","messageCount":8,"participants":["Karl Hasselström","Catalin Marinas"],"isPatch":true,"patchVersion":1,"patchTotal":5},"messages":[{"id":"83751","messageId":"20080717204133.23407.34264.stgit@yoghurt","threadId":"14511","inReplyTo":null,"subject":"[StGit PATCH 0/5] Performance testing tools","fromName":"Karl Hasselström","fromEmail":"kha@treskal.com","sentAt":"2008-07-17T20:42:20Z","receivedAt":"2008-07-17T20:42:20Z","isPatch":true,"sender":{"key":"kha@treskal.com","avatar":"https://gravatar.com/avatar/f0120c734b5279b345075a28521e1ac66acb20c9913ffe9bf6ae97e53f7f3f13?d=mp&s=160"},"body":"Here's the same scripts I posted earlier, but polished and extended.\n\n---\n\nKarl Hasselström (5):\n      Global performance logging\n      Log subprocess calls during performance testing\n      Show full command in subprocess profiling\n      Log subproces activity to a file\n      Add some performance testing scripts\n\n\n perf/.gitignore               |    2 +\n perf/create_synthetic_repo.py |   61 ++++++++++++++++++++++++++\n perf/find_patchbomb.py        |   31 +++++++++++++\n perf/perftest.py              |   96 +++++++++++++++++++++++++++++++++++++++++\n perf/setup.sh                 |   52 ++++++++++++++++++++++\n stgit/main.py                 |   11 ++++-\n stgit/out.py                  |   11 +++--\n stgit/run.py                  |   61 +++++++++++++++++++++-----\n 8 files changed, 306 insertions(+), 19 deletions(-)\n create mode 100644 perf/.gitignore\n create mode 100644 perf/create_synthetic_repo.py\n create mode 100644 perf/find_patchbomb.py\n create mode 100644 perf/perftest.py\n create mode 100644 perf/setup.sh\n\n-- \nKarl Hasselström, kha@treskal.com\n      www.treskal.com/kalle\n"},{"id":"83750","messageId":"20080717204227.23407.1854.stgit@yoghurt","threadId":"14511","inReplyTo":"20080717204133.23407.34264.stgit@yoghurt","subject":"[StGit PATCH 1/5] Add some performance testing scripts","fromName":"Karl Hasselström","fromEmail":"kha@treskal.com","sentAt":"2008-07-17T20:42:27Z","receivedAt":"2008-07-17T20:42:27Z","isPatch":true,"sender":{"key":"kha@treskal.com","avatar":"https://gravatar.com/avatar/f0120c734b5279b345075a28521e1ac66acb20c9913ffe9bf6ae97e53f7f3f13?d=mp&s=160"},"body":"find_patchbomb.py: Given a git repo, finds the longest linear sequence\n  of commits. Useful for testing StGit on a real repository.\n\nsetup.sh: Creates two test repositories, one synthetic and one based\n  on the Linux kernel repo, with strategically placed tags.\n\ncreate_synthetic_repo.py: Helper script for setup.sh; it produces\n  output that is to be fed to git fast-import.\n\nperftest.py: Runs one of a (small) number of hard-coded performance\n  tests against a copy of one of the repos created by setup.sh. The\n  initial testcases all involve uncommitting a large number of patches\n  and then rebasing them.\n\nSigned-off-by: Karl Hasselström <kha@treskal.com>\n\n---\n\n perf/.gitignore               |    2 +\n perf/create_synthetic_repo.py |   61 ++++++++++++++++++++++++++++\n perf/find_patchbomb.py        |   31 ++++++++++++++\n perf/perftest.py              |   88 +++++++++++++++++++++++++++++++++++++++++\n perf/setup.sh                 |   52 ++++++++++++++++++++++++\n 5 files changed, 234 insertions(+), 0 deletions(-)\n create mode 100644 perf/.gitignore\n create mode 100644 perf/create_synthetic_repo.py\n create mode 100644 perf/find_patchbomb.py\n create mode 100644 perf/perftest.py\n create mode 100644 perf/setup.sh\n\n\ndiff --git a/perf/.gitignore b/perf/.gitignore\nnew file mode 100644\nindex 0000000..dfae110\n--- /dev/null\n+++ b/perf/.gitignore\n@@ -0,0 +1,2 @@\n+/*.orig\n+/*.trash\ndiff --git a/perf/create_synthetic_repo.py b/perf/create_synthetic_repo.py\nnew file mode 100644\nindex 0000000..4d6ef6b\n--- /dev/null\n+++ b/perf/create_synthetic_repo.py\n@@ -0,0 +1,61 @@\n+next_mark = 1\n+def get_mark():\n+    global next_mark\n+    next_mark += 1\n+    return (next_mark - 1)\n+\n+def write_data(s):\n+    print 'data %d' % len(s)\n+    print s\n+\n+def write_blob(s):\n+    print 'blob'\n+    m = get_mark()\n+    print 'mark :%d' % m\n+    write_data(s)\n+    return m\n+\n+def write_commit(branch, files, msg, parent = None):\n+    print 'commit %s' % branch\n+    m = get_mark()\n+    print 'mark :%d' % m\n+    auth = 'X Ample <xa@example.com> %d +0000' % (1000000000 + m)\n+    print 'author %s' % auth\n+    print 'committer %s' % auth\n+    write_data(msg)\n+    if parent != None:\n+        print 'from :%d' % parent\n+    for fn, fm in sorted(files.iteritems()):\n+        print 'M 100644 :%d %s' % (fm, fn)\n+    return m\n+\n+def set_ref(ref, mark):\n+    print 'reset %s' % ref\n+    print 'from :%d' % mark\n+\n+def stdblob(fn):\n+    return ''.join('%d %s\\n' % (x, fn) for x in xrange(10))\n+\n+def iter_paths():\n+    for i in xrange(32):\n+        for j in xrange(32):\n+            for k in xrange(32):\n+                yield '%02d/%02d/%02d' % (i, j, k)\n+\n+def setup():\n+    def t(name): return 'refs/tags/%s' % name\n+    files = dict((fn, write_blob(stdblob(fn))) for fn in iter_paths())\n+    initial = write_commit(t('bomb-base'), files, 'Initial commit')\n+    set_ref(t('bomb-top'), initial)\n+    for fn in iter_paths():\n+        write_commit(t('bomb-top'),\n+                     { fn: write_blob(stdblob(fn) + 'Last line\\n') },\n+                     'Add last line to %s' % fn)\n+    write_commit(t('add-file'), { 'woo-hoo.txt': write_blob('woo-hoo\\n') },\n+                 'Add a new file', parent = initial)\n+    files = dict((fn, write_blob('First line\\n' + stdblob(fn)))\n+                 for fn in iter_paths())\n+    write_commit(t('modify-all'), files, 'Add first line to all files',\n+                 parent = initial)\n+\n+setup()\ndiff --git a/perf/find_patchbomb.py b/perf/find_patchbomb.py\nnew file mode 100644\nindex 0000000..69a78c7\n--- /dev/null\n+++ b/perf/find_patchbomb.py\n@@ -0,0 +1,31 @@\n+# Feed this with git rev-list HEAD --parents\n+\n+import sys\n+\n+parents = {}\n+for line in sys.stdin.readlines():\n+    commits = line.split()\n+    parents[commits[0]] = commits[1:]\n+\n+sequence_num = {}\n+stack = []\n+for commit in parents.keys():\n+    stack.append(commit)\n+    while stack:\n+        c = stack.pop()\n+        if c in sequence_num:\n+            continue\n+        ps = parents[c]\n+        if len(ps) == 1:\n+            p = ps[0]\n+            if p in sequence_num:\n+                sequence_num[c] = 1 + sequence_num[p]\n+            else:\n+                stack.append(c)\n+                stack.append(p)\n+        else:\n+            sequence_num[c] = 0\n+\n+(num, commit) = max((num, commit) for (commit, num)\n+                    in sequence_num.iteritems())\n+print '%s is a sequence of %d patches' % (commit, num)\ndiff --git a/perf/perftest.py b/perf/perftest.py\nnew file mode 100644\nindex 0000000..7072772\n--- /dev/null\n+++ b/perf/perftest.py\n@@ -0,0 +1,88 @@\n+import datetime, subprocess, sys\n+\n+def duration(t1, t2):\n+    d = t2 - t1\n+    return 86400*d.days + d.seconds + 1e-6*d.microseconds\n+\n+class Run(object):\n+    def __init__(self):\n+        self.__cwd = None\n+        self.__log = []\n+    def __call__(self, *cmd, **args):\n+        kwargs = { 'cwd': self.__cwd }\n+        if args.get('capture_stdout', False):\n+            kwargs['stdout'] = subprocess.PIPE\n+        start = datetime.datetime.now()\n+        p = subprocess.Popen(cmd, **kwargs)\n+        (out, err) = p.communicate()\n+        stop = datetime.datetime.now()\n+        self.__log.append((cmd, duration(start, stop)))\n+        return out\n+    def cd(self, dir):\n+        self.__cwd = dir\n+    def summary(self):\n+        def pcmd(c): return ' '.join(c)\n+        def ptime(t): return '%.3f' % t\n+        (cs, times) = zip(*self.__log)\n+        ttime = sum(times)\n+        cl = max(len(pcmd(c)) for c in cs)\n+        tl = max(len(ptime(t)) for t in list(times) + [ttime])\n+        for (c, t) in self.__log:\n+            print '%*s  %*s' % (tl, ptime(t), -cl, pcmd(c))\n+        print '%*s' % (tl, ptime(ttime))\n+\n+perftests = {}\n+perftestdesc = {}\n+def perftest(desc, name = None):\n+    def decorator(f):\n+        def g():\n+            r = Run()\n+            f(r)\n+            r.summary()\n+        perftests[name or f.__name__] = g\n+        perftestdesc[name or f.__name__] = desc\n+        return g\n+    return decorator\n+\n+def copy_testdir(dir):\n+    tmp = dir + '.trash'\n+    r = Run()\n+    r('rsync', '-a', '--delete', dir + '.orig/', tmp)\n+    return tmp\n+\n+def new_rebase(r, ref):\n+    top = r('stg', 'top', capture_stdout = True)\n+    r('stg', 'pop', '-a')\n+    r('git', 'reset', '--hard', ref)\n+    r('stg', 'goto', top.strip())\n+\n+def old_rebase(r, ref):\n+    r('stg', 'rebase', ref)\n+\n+def def_rebasetest(rebase, dir, tag):\n+    @perftest('%s rebase onto %s in %s' % (rebase, tag, dir),\n+              'rebase-%srebase-%s-%s' % (rebase, tag, dir))\n+    def rebasetest(r):\n+        r.cd(copy_testdir(dir))\n+        r('stg', 'init')\n+        if dir == 'synt':\n+            r('stg', 'uncommit', '-n', '500')\n+        else:\n+            r('stg', 'uncommit', '-x', '-t', 'bomb-base')\n+        if rebase == 'new':\n+            new_rebase(r, tag)\n+        else:\n+            old_rebase(r, tag)\n+for rebase in ['old', 'new']:\n+    for (dir, tag) in [('synt', 'add-file'),\n+                       ('synt', 'modify-all'),\n+                       ('linux', 'add-file')]:\n+        def_rebasetest(rebase, dir, tag)\n+\n+args = sys.argv[1:]\n+if len(args) == 0:\n+    for (fun, desc) in sorted(perftestdesc.iteritems()):\n+        print '%s: %s' % (fun, desc)\n+else:\n+    for test in args:\n+        perftests[test]()\ndiff --git a/perf/setup.sh b/perf/setup.sh\nnew file mode 100644\nindex 0000000..b92ddfc\n--- /dev/null\n+++ b/perf/setup.sh\n@@ -0,0 +1,52 @@\n+krepo='git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git'\n+\n+get_linux() {\n+    rm -rf linux.orig\n+    git clone \"$krepo\" linux.orig\n+}\n+\n+mod_linux() {\n+    # Tag the top and base of a very long linear sequence of commits.\n+    git tag bomb-top 85040bcb4643cba578839e953f25e2d1965d83d0\n+    git tag bomb-base bomb-top~1470\n+\n+    # Add a file at the base of the linear sequence.\n+    git checkout bomb-base\n+    echo \"woo-hoo\" > woo-hoo.txt\n+    git add woo-hoo.txt\n+    git commit -m \"Add a file\"\n+    git tag add-file\n+\n+    # Clean up and go to start position.\n+    git gc\n+    git update-ref refs/heads/master bomb-top\n+    git checkout master\n+}\n+\n+setup_linux () {\n+    get_linux\n+    ( cd linux.orig && mod_linux )\n+}\n+\n+create_empty () {\n+    dir=\"$1\"\n+    rm -rf $dir\n+    mkdir $dir\n+    ( cd $dir && git init )\n+}\n+\n+fill_synthetic () {\n+    python ../create_synthetic_repo.py | git fast-import\n+    git gc --aggressive\n+    git update-ref refs/heads/master bomb-top\n+    git checkout master\n+}\n+\n+setup_synthetic()\n+{\n+    create_empty synt.orig\n+    ( cd synt.orig && fill_synthetic )\n+}\n+\n+setup_linux\n+setup_synthetic\n"},{"id":"83752","messageId":"20080717204233.23407.59842.stgit@yoghurt","threadId":"14511","inReplyTo":"20080717204133.23407.34264.stgit@yoghurt","subject":"[StGit PATCH 2/5] Log subproces activity to a file","fromName":"Karl Hasselström","fromEmail":"kha@treskal.com","sentAt":"2008-07-17T20:42:33Z","receivedAt":"2008-07-17T20:42:33Z","isPatch":true,"sender":{"key":"kha@treskal.com","avatar":"https://gravatar.com/avatar/f0120c734b5279b345075a28521e1ac66acb20c9913ffe9bf6ae97e53f7f3f13?d=mp&s=160"},"body":"If the user sets $STGIT_SUBPROCESS_LOG to a log mode followed by a\ncolon and a file name, append the log to that file instead of writing\nit to stdout.\n\nSigned-off-by: Karl Hasselström <kha@treskal.com>\n\n---\n\n stgit/out.py |   11 +++++++----\n stgit/run.py |   35 +++++++++++++++++++++++------------\n 2 files changed, 30 insertions(+), 16 deletions(-)\n\n\ndiff --git a/stgit/out.py b/stgit/out.py\nindex 485b830..753c176 100644\n--- a/stgit/out.py\n+++ b/stgit/out.py\n@@ -20,7 +20,7 @@ Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA\n import sys, textwrap\n \n class MessagePrinter(object):\n-    def __init__(self):\n+    def __init__(self, file = None):\n         class Output(object):\n             def __init__(self, write, flush):\n                 self.write = write\n@@ -68,9 +68,12 @@ class MessagePrinter(object):\n                 self.new_line()\n                 self.write(string)\n                 self.at_start_of_line = string.endswith('\\n')\n-        self.__stderr = Output(sys.stderr.write, sys.stderr.flush)\n-        self.__stdout = Output(sys.stdout.write, sys.stdout.flush)\n-        if sys.stdout.isatty():\n+        if file:\n+            self.__stdout = self.__stderr = Output(file.write, file.flush)\n+        else:\n+            self.__stdout = Output(sys.stdout.write, sys.stdout.flush)\n+            self.__stderr = Output(sys.stdout.write, sys.stdout.flush)\n+        if file or sys.stdout.isatty():\n             self.__out = self.__stdout\n             self.__err = self.__stdout\n         else:\ndiff --git a/stgit/run.py b/stgit/run.py\nindex 0b79729..9d50e43 100644\n--- a/stgit/run.py\n+++ b/stgit/run.py\n@@ -27,12 +27,22 @@ class RunException(StgException):\n     subprocess.\"\"\"\n     pass\n \n-_all_log_modes = ['debug', 'profile']\n-_log_mode = os.environ.get('STGIT_SUBPROCESS_LOG', '')\n-if _log_mode and not _log_mode in _all_log_modes:\n-    out.warn(('Unknown log mode \"%s\" specified in $STGIT_SUBPROCESS_LOG.'\n-              % _log_mode),\n-             'Valid values are: %s' % ', '.join(_all_log_modes))\n+def get_log_mode(spec):\n+    if not ':' in spec:\n+        spec += ':'\n+    (log_mode, outfile) = spec.split(':', 1)\n+    all_log_modes = ['debug', 'profile']\n+    if log_mode and not log_mode in all_log_modes:\n+        out.warn(('Unknown log mode \"%s\" specified in $STGIT_SUBPROCESS_LOG.'\n+                  % log_mode),\n+                 'Valid values are: %s' % ', '.join(all_log_modes))\n+    if outfile:\n+        f = MessagePrinter(open(outfile, 'a'))\n+    else:\n+        f = out\n+    return (log_mode, f)\n+\n+(_log_mode, _logfile) = get_log_mode(os.environ.get('STGIT_SUBPROCESS_LOG', ''))\n \n class Run:\n     exc = RunException\n@@ -47,22 +57,23 @@ class Run:\n         self.__discard_stderr = False\n     def __log_start(self):\n         if _log_mode == 'debug':\n-            out.start('Running subprocess %s' % self.__cmd)\n+            _logfile.start('Running subprocess %s' % self.__cmd)\n             if self.__cwd != None:\n-                out.info('cwd: %s' % self.__cwd)\n+                _logfile.info('cwd: %s' % self.__cwd)\n             if self.__env != None:\n                 for k in sorted(self.__env.iterkeys()):\n                     if k not in os.environ or os.environ[k] != self.__env[k]:\n-                        out.info('%s: %s' % (k, self.__env[k]))\n+                        _logfile.info('%s: %s' % (k, self.__env[k]))\n         elif _log_mode == 'profile':\n-            out.start('Running subprocess %s' % self.__cmd[0])\n+            _logfile.start('Running subprocess %s' % self.__cmd[0])\n             self.__starttime = datetime.datetime.now()\n     def __log_end(self, retcode):\n         if _log_mode == 'debug':\n-            out.done('return code: %d' % retcode)\n+            _logfile.done('return code: %d' % retcode)\n         elif _log_mode == 'profile':\n             duration = datetime.datetime.now() - self.__starttime\n-            out.done('%1.3f s' % (duration.microseconds/1e6 + duration.seconds))\n+            _logfile.done('%1.3f s' % (duration.microseconds/1e6\n+                                       + duration.seconds))\n     def __check_exitcode(self):\n         if self.__good_retvals == None:\n             return\n"},{"id":"83753","messageId":"20080717204238.23407.47439.stgit@yoghurt","threadId":"14511","inReplyTo":"20080717204133.23407.34264.stgit@yoghurt","subject":"[StGit PATCH 3/5] Show full command in subprocess profiling","fromName":"Karl Hasselström","fromEmail":"kha@treskal.com","sentAt":"2008-07-17T20:42:38Z","receivedAt":"2008-07-17T20:42:38Z","isPatch":true,"sender":{"key":"kha@treskal.com","avatar":"https://gravatar.com/avatar/f0120c734b5279b345075a28521e1ac66acb20c9913ffe9bf6ae97e53f7f3f13?d=mp&s=160"},"body":"Showing just the executable name isn't so useful now that it's always\n\"git\".\n\nSigned-off-by: Karl Hasselström <kha@treskal.com>\n\n---\n\n stgit/run.py |    2 +-\n 1 files changed, 1 insertions(+), 1 deletions(-)\n\n\ndiff --git a/stgit/run.py b/stgit/run.py\nindex 9d50e43..befd3c1 100644\n--- a/stgit/run.py\n+++ b/stgit/run.py\n@@ -65,7 +65,7 @@ class Run:\n                     if k not in os.environ or os.environ[k] != self.__env[k]:\n                         _logfile.info('%s: %s' % (k, self.__env[k]))\n         elif _log_mode == 'profile':\n-            _logfile.start('Running subprocess %s' % self.__cmd[0])\n+            _logfile.start('Running subprocess %s' % self.__cmd)\n             self.__starttime = datetime.datetime.now()\n     def __log_end(self, retcode):\n         if _log_mode == 'debug':\n"},{"id":"83755","messageId":"20080717204244.23407.16332.stgit@yoghurt","threadId":"14511","inReplyTo":"20080717204133.23407.34264.stgit@yoghurt","subject":"[StGit PATCH 4/5] Log subprocess calls during performance testing","fromName":"Karl Hasselström","fromEmail":"kha@treskal.com","sentAt":"2008-07-17T20:42:44Z","receivedAt":"2008-07-17T20:42:44Z","isPatch":true,"sender":{"key":"kha@treskal.com","avatar":"https://gravatar.com/avatar/f0120c734b5279b345075a28521e1ac66acb20c9913ffe9bf6ae97e53f7f3f13?d=mp&s=160"},"body":"Log each command's subprocess calls to a separate file.\n\nSigned-off-by: Karl Hasselström <kha@treskal.com>\n\n---\n\n perf/perftest.py |   12 ++++++++++--\n 1 files changed, 10 insertions(+), 2 deletions(-)\n\n\ndiff --git a/perf/perftest.py b/perf/perftest.py\nindex 7072772..e5ed04b 100644\n--- a/perf/perftest.py\n+++ b/perf/perftest.py\n@@ -1,4 +1,4 @@\n-import datetime, subprocess, sys\n+import datetime, os, os.path, subprocess, sys\n \n def duration(t1, t2):\n     d = t2 - t1\n@@ -8,8 +8,16 @@ class Run(object):\n     def __init__(self):\n         self.__cwd = None\n         self.__log = []\n+    def __logfile(self, cmd):\n+        fn = os.path.join(os.getcwd(), '%04d.log' % len(self.__log))\n+        f = open(fn, 'w')\n+        f.write(' '.join(cmd) + '\\n' + '-'*70 + '\\n\\n')\n+        f.close()\n+        return fn\n     def __call__(self, *cmd, **args):\n-        kwargs = { 'cwd': self.__cwd }\n+        env = dict(os.environ)\n+        env['STGIT_SUBPROCESS_LOG'] = 'profile:' + self.__logfile(cmd)\n+        kwargs = { 'cwd': self.__cwd, 'env': env }\n         if args.get('capture_stdout', False):\n             kwargs['stdout'] = subprocess.PIPE\n         start = datetime.datetime.now()\n"},{"id":"83754","messageId":"20080717204250.23407.39304.stgit@yoghurt","threadId":"14511","inReplyTo":"20080717204133.23407.34264.stgit@yoghurt","subject":"[StGit PATCH 5/5] Global performance logging","fromName":"Karl Hasselström","fromEmail":"kha@treskal.com","sentAt":"2008-07-17T20:42:50Z","receivedAt":"2008-07-17T20:42:50Z","isPatch":true,"sender":{"key":"kha@treskal.com","avatar":"https://gravatar.com/avatar/f0120c734b5279b345075a28521e1ac66acb20c9913ffe9bf6ae97e53f7f3f13?d=mp&s=160"},"body":"Measure the time for the whole program, and how much of that was\nsubprocess calls.\n\nSigned-off-by: Karl Hasselström <kha@treskal.com>\n\n---\n\n stgit/main.py |   11 +++++++++--\n stgit/run.py  |   32 ++++++++++++++++++++++++++++----\n 2 files changed, 37 insertions(+), 6 deletions(-)\n\n\ndiff --git a/stgit/main.py b/stgit/main.py\nindex aa1f8ef..64cff30 100644\n--- a/stgit/main.py\n+++ b/stgit/main.py\n@@ -23,7 +23,7 @@ from optparse import OptionParser\n \n import stgit.commands\n from stgit.out import *\n-from stgit import utils\n+from stgit import run, utils\n \n #\n # The commands map\n@@ -192,7 +192,7 @@ def print_help():\n #\n # The main function (command dispatcher)\n #\n-def main():\n+def _main():\n     \"\"\"The main function\n     \"\"\"\n     global prog\n@@ -293,3 +293,10 @@ def main():\n         sys.exit(utils.STGIT_BUG_ERROR)\n \n     sys.exit(ret or utils.STGIT_SUCCESS)\n+\n+def main():\n+    run.start_logging()\n+    try:\n+        _main()\n+    finally:\n+        run.stop_logging()\ndiff --git a/stgit/run.py b/stgit/run.py\nindex befd3c1..e46836b 100644\n--- a/stgit/run.py\n+++ b/stgit/run.py\n@@ -42,7 +42,27 @@ def get_log_mode(spec):\n         f = out\n     return (log_mode, f)\n \n-(_log_mode, _logfile) = get_log_mode(os.environ.get('STGIT_SUBPROCESS_LOG', ''))\n+def start_logging():\n+    global _log_mode, _logfile, _log_starttime, _log_subproctime\n+    (_log_mode, _logfile) = get_log_mode(\n+        os.environ.get('STGIT_SUBPROCESS_LOG', ''))\n+    _log_starttime = datetime.datetime.now()\n+    _log_subproctime = 0.0\n+\n+def duration(t1, t2):\n+    d = t2 - t1\n+    return 86400*d.days + d.seconds + 1e-6*d.microseconds\n+\n+def stop_logging():\n+    if _log_mode != 'profile':\n+        return\n+    ttime = duration(_log_starttime, datetime.datetime.now())\n+    rtime = ttime - _log_subproctime\n+    _logfile.info('Total time: %1.3f s' % ttime,\n+                  'Time spent in subprocess calls: %1.3f s (%1.1f%%)'\n+                  % (_log_subproctime, 100*_log_subproctime/ttime),\n+                  'Remaining time: %1.3f s (%1.1f%%)'\n+                  % (rtime, 100*rtime/ttime))\n \n class Run:\n     exc = RunException\n@@ -68,12 +88,16 @@ class Run:\n             _logfile.start('Running subprocess %s' % self.__cmd)\n             self.__starttime = datetime.datetime.now()\n     def __log_end(self, retcode):\n+        global _log_subproctime, _log_starttime\n         if _log_mode == 'debug':\n             _logfile.done('return code: %d' % retcode)\n         elif _log_mode == 'profile':\n-            duration = datetime.datetime.now() - self.__starttime\n-            _logfile.done('%1.3f s' % (duration.microseconds/1e6\n-                                       + duration.seconds))\n+            n = datetime.datetime.now()\n+            d = duration(self.__starttime, n)\n+            _logfile.done('%1.3f s' % d)\n+            _log_subproctime += d\n+            _logfile.info('Time since program start: %1.3f s'\n+                          % duration(_log_starttime, n))\n     def __check_exitcode(self):\n         if self.__good_retvals == None:\n             return\n"},{"id":"83916","messageId":"b0943d9e0807181445l146bd90akb8f8c14d602d401e@mail.gmail.com","threadId":"14511","inReplyTo":"20080717204233.23407.59842.stgit@yoghurt","subject":"Re: [StGit PATCH 2/5] Log subproces activity to a file","fromName":"Catalin Marinas","fromEmail":"catalin.marinas@gmail.com","sentAt":"2008-07-18T21:45:53Z","receivedAt":"2008-07-18T21:45:53Z","isPatch":true,"sender":{"key":"catalin.marinas@gmail.com","avatar":null},"body":"2008/7/17 Karl Hasselström <kha@treskal.com>:\n> If the user sets $STGIT_SUBPROCESS_LOG to a log mode followed by a\n> colon and a file name, append the log to that file instead of writing\n> it to stdout.\n\nOK.\n\n-- \nCatalin\n"},{"id":"83918","messageId":"b0943d9e0807181447v44103e05i1cc0243cb6458bef@mail.gmail.com","threadId":"14511","inReplyTo":"20080717204238.23407.47439.stgit@yoghurt","subject":"Re: [StGit PATCH 3/5] Show full command in subprocess profiling","fromName":"Catalin Marinas","fromEmail":"catalin.marinas@gmail.com","sentAt":"2008-07-18T21:47:46Z","receivedAt":"2008-07-18T21:47:46Z","isPatch":true,"sender":{"key":"catalin.marinas@gmail.com","avatar":null},"body":"2008/7/17 Karl Hasselström <kha@treskal.com>:\n> Showing just the executable name isn't so useful now that it's always\n> \"git\".\n\nYes, indeed.\n\n-- \nCatalin\n"}]}