[StGit PATCH 0/5] Performance testing tools

[StGit PATCH 0/5] Performance testing tools

[Karl Hasselström]

Here's the same scripts I posted earlier, but polished and extended.

---

Karl Hasselström (5):
      Global performance logging
      Log subprocess calls during performance testing
      Show full command in subprocess profiling
      Log subproces activity to a file
      Add some performance testing scripts


 perf/.gitignore               |    2 +
 perf/create_synthetic_repo.py |   61 ++++++++++++++++++++++++++
 perf/find_patchbomb.py        |   31 +++++++++++++
 perf/perftest.py              |   96 +++++++++++++++++++++++++++++++++++++++++
 perf/setup.sh                 |   52 ++++++++++++++++++++++
 stgit/main.py                 |   11 ++++-
 stgit/out.py                  |   11 +++--
 stgit/run.py                  |   61 +++++++++++++++++++++-----
 8 files changed, 306 insertions(+), 19 deletions(-)
 create mode 100644 perf/.gitignore
 create mode 100644 perf/create_synthetic_repo.py
 create mode 100644 perf/find_patchbomb.py
 create mode 100644 perf/perftest.py
 create mode 100644 perf/setup.sh

-- 
Karl Hasselström, kha@treskal.com
      www.treskal.com/kalle

[StGit PATCH 1/5] Add some performance testing scripts

[Karl Hasselström]

find_patchbomb.py: Given a git repo, finds the longest linear sequence
  of commits. Useful for testing StGit on a real repository.

setup.sh: Creates two test repositories, one synthetic and one based
  on the Linux kernel repo, with strategically placed tags.

create_synthetic_repo.py: Helper script for setup.sh; it produces
  output that is to be fed to git fast-import.

perftest.py: Runs one of a (small) number of hard-coded performance
  tests against a copy of one of the repos created by setup.sh. The
  initial testcases all involve uncommitting a large number of patches
  and then rebasing them.

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

---

 perf/.gitignore               |    2 +
 perf/create_synthetic_repo.py |   61 ++++++++++++++++++++++++++++
 perf/find_patchbomb.py        |   31 ++++++++++++++
 perf/perftest.py              |   88 +++++++++++++++++++++++++++++++++++++++++
 perf/setup.sh                 |   52 ++++++++++++++++++++++++
 5 files changed, 234 insertions(+), 0 deletions(-)
 create mode 100644 perf/.gitignore
 create mode 100644 perf/create_synthetic_repo.py
 create mode 100644 perf/find_patchbomb.py
 create mode 100644 perf/perftest.py
 create mode 100644 perf/setup.sh


diff --git a/perf/.gitignore b/perf/.gitignore
new file mode 100644
index 0000000..dfae110
--- /dev/null
+++ b/perf/.gitignore
@@ -0,0 +1,2 @@
+/*.orig
+/*.trash
diff --git a/perf/create_synthetic_repo.py b/perf/create_synthetic_repo.py
new file mode 100644
index 0000000..4d6ef6b
--- /dev/null
+++ b/perf/create_synthetic_repo.py
@@ -0,0 +1,61 @@
+next_mark = 1
+def get_mark():
+    global next_mark
+    next_mark += 1
+    return (next_mark - 1)
+
+def write_data(s):
+    print 'data %d' % len(s)
+    print s
+
+def write_blob(s):
+    print 'blob'
+    m = get_mark()
+    print 'mark :%d' % m
+    write_data(s)
+    return m
+
+def write_commit(branch, files, msg, parent = None):
+    print 'commit %s' % branch
+    m = get_mark()
+    print 'mark :%d' % m
+    auth = 'X Ample <xa@example.com> %d +0000' % (1000000000 + m)
+    print 'author %s' % auth
+    print 'committer %s' % auth
+    write_data(msg)
+    if parent != None:
+        print 'from :%d' % parent
+    for fn, fm in sorted(files.iteritems()):
+        print 'M 100644 :%d %s' % (fm, fn)
+    return m
+
+def set_ref(ref, mark):
+    print 'reset %s' % ref
+    print 'from :%d' % mark
+
+def stdblob(fn):
+    return ''.join('%d %s\n' % (x, fn) for x in xrange(10))
+
+def iter_paths():
+    for i in xrange(32):
+        for j in xrange(32):
+            for k in xrange(32):
+                yield '%02d/%02d/%02d' % (i, j, k)
+
+def setup():
+    def t(name): return 'refs/tags/%s' % name
+    files = dict((fn, write_blob(stdblob(fn))) for fn in iter_paths())
+    initial = write_commit(t('bomb-base'), files, 'Initial commit')
+    set_ref(t('bomb-top'), initial)
+    for fn in iter_paths():
+        write_commit(t('bomb-top'),
+                     { fn: write_blob(stdblob(fn) + 'Last line\n') },
+                     'Add last line to %s' % fn)
+    write_commit(t('add-file'), { 'woo-hoo.txt': write_blob('woo-hoo\n') },
+                 'Add a new file', parent = initial)
+    files = dict((fn, write_blob('First line\n' + stdblob(fn)))
+                 for fn in iter_paths())
+    write_commit(t('modify-all'), files, 'Add first line to all files',
+                 parent = initial)
+
+setup()
diff --git a/perf/find_patchbomb.py b/perf/find_patchbomb.py
new file mode 100644
index 0000000..69a78c7
--- /dev/null
+++ b/perf/find_patchbomb.py
@@ -0,0 +1,31 @@
+# Feed this with git rev-list HEAD --parents
+
+import sys
+
+parents = {}
+for line in sys.stdin.readlines():
+    commits = line.split()
+    parents[commits[0]] = commits[1:]
+
+sequence_num = {}
+stack = []
+for commit in parents.keys():
+    stack.append(commit)
+    while stack:
+        c = stack.pop()
+        if c in sequence_num:
+            continue
+        ps = parents[c]
+        if len(ps) == 1:
+            p = ps[0]
+            if p in sequence_num:
+                sequence_num[c] = 1 + sequence_num[p]
+            else:
+                stack.append(c)
+                stack.append(p)
+        else:
+            sequence_num[c] = 0
+
+(num, commit) = max((num, commit) for (commit, num)
+                    in sequence_num.iteritems())
+print '%s is a sequence of %d patches' % (commit, num)
diff --git a/perf/perftest.py b/perf/perftest.py
new file mode 100644
index 0000000..7072772
--- /dev/null
+++ b/perf/perftest.py
@@ -0,0 +1,88 @@
+import datetime, subprocess, sys
+
+def duration(t1, t2):
+    d = t2 - t1
+    return 86400*d.days + d.seconds + 1e-6*d.microseconds
+
+class Run(object):
+    def __init__(self):
+        self.__cwd = None
+        self.__log = []
+    def __call__(self, *cmd, **args):
+        kwargs = { 'cwd': self.__cwd }
+        if args.get('capture_stdout', False):
+            kwargs['stdout'] = subprocess.PIPE
+        start = datetime.datetime.now()
+        p = subprocess.Popen(cmd, **kwargs)
+        (out, err) = p.communicate()
+        stop = datetime.datetime.now()
+        self.__log.append((cmd, duration(start, stop)))
+        return out
+    def cd(self, dir):
+        self.__cwd = dir
+    def summary(self):
+        def pcmd(c): return ' '.join(c)
+        def ptime(t): return '%.3f' % t
+        (cs, times) = zip(*self.__log)
+        ttime = sum(times)
+        cl = max(len(pcmd(c)) for c in cs)
+        tl = max(len(ptime(t)) for t in list(times) + [ttime])
+        for (c, t) in self.__log:
+            print '%*s  %*s' % (tl, ptime(t), -cl, pcmd(c))
+        print '%*s' % (tl, ptime(ttime))
+
+perftests = {}
+perftestdesc = {}
+def perftest(desc, name = None):
+    def decorator(f):
+        def g():
+            r = Run()
+            f(r)
+            r.summary()
+        perftests[name or f.__name__] = g
+        perftestdesc[name or f.__name__] = desc
+        return g
+    return decorator
+
+def copy_testdir(dir):
+    tmp = dir + '.trash'
+    r = Run()
+    r('rsync', '-a', '--delete', dir + '.orig/', tmp)
+    return tmp
+
+def new_rebase(r, ref):
+    top = r('stg', 'top', capture_stdout = True)
+    r('stg', 'pop', '-a')
+    r('git', 'reset', '--hard', ref)
+    r('stg', 'goto', top.strip())
+
+def old_rebase(r, ref):
+    r('stg', 'rebase', ref)
+
+def def_rebasetest(rebase, dir, tag):
+    @perftest('%s rebase onto %s in %s' % (rebase, tag, dir),
+              'rebase-%srebase-%s-%s' % (rebase, tag, dir))
+    def rebasetest(r):
+        r.cd(copy_testdir(dir))
+        r('stg', 'init')
+        if dir == 'synt':
+            r('stg', 'uncommit', '-n', '500')
+        else:
+            r('stg', 'uncommit', '-x', '-t', 'bomb-base')
+        if rebase == 'new':
+            new_rebase(r, tag)
+        else:
+            old_rebase(r, tag)
+for rebase in ['old', 'new']:
+    for (dir, tag) in [('synt', 'add-file'),
+                       ('synt', 'modify-all'),
+                       ('linux', 'add-file')]:
+        def_rebasetest(rebase, dir, tag)
+
+args = sys.argv[1:]
+if len(args) == 0:
+    for (fun, desc) in sorted(perftestdesc.iteritems()):
+        print '%s: %s' % (fun, desc)
+else:
+    for test in args:
+        perftests[test]()
diff --git a/perf/setup.sh b/perf/setup.sh
new file mode 100644
index 0000000..b92ddfc
--- /dev/null
+++ b/perf/setup.sh
@@ -0,0 +1,52 @@
+krepo='git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git'
+
+get_linux() {
+    rm -rf linux.orig
+    git clone "$krepo" linux.orig
+}
+
+mod_linux() {
+    # Tag the top and base of a very long linear sequence of commits.
+    git tag bomb-top 85040bcb4643cba578839e953f25e2d1965d83d0
+    git tag bomb-base bomb-top~1470
+
+    # Add a file at the base of the linear sequence.
+    git checkout bomb-base
+    echo "woo-hoo" > woo-hoo.txt
+    git add woo-hoo.txt
+    git commit -m "Add a file"
+    git tag add-file
+
+    # Clean up and go to start position.
+    git gc
+    git update-ref refs/heads/master bomb-top
+    git checkout master
+}
+
+setup_linux () {
+    get_linux
+    ( cd linux.orig && mod_linux )
+}
+
+create_empty () {
+    dir="$1"
+    rm -rf $dir
+    mkdir $dir
+    ( cd $dir && git init )
+}
+
+fill_synthetic () {
+    python ../create_synthetic_repo.py | git fast-import
+    git gc --aggressive
+    git update-ref refs/heads/master bomb-top
+    git checkout master
+}
+
+setup_synthetic()
+{
+    create_empty synt.orig
+    ( cd synt.orig && fill_synthetic )
+}
+
+setup_linux
+setup_synthetic

[StGit PATCH 2/5] Log subproces activity to a file

[Karl Hasselström]

If the user sets $STGIT_SUBPROCESS_LOG to a log mode followed by a
colon and a file name, append the log to that file instead of writing
it to stdout.

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

---

 stgit/out.py |   11 +++++++----
 stgit/run.py |   35 +++++++++++++++++++++++------------
 2 files changed, 30 insertions(+), 16 deletions(-)


diff --git a/stgit/out.py b/stgit/out.py
index 485b830..753c176 100644
--- a/stgit/out.py
+++ b/stgit/out.py
@@ -20,7 +20,7 @@ Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
 import sys, textwrap
 
 class MessagePrinter(object):
-    def __init__(self):
+    def __init__(self, file = None):
         class Output(object):
             def __init__(self, write, flush):
                 self.write = write
@@ -68,9 +68,12 @@ class MessagePrinter(object):
                 self.new_line()
                 self.write(string)
                 self.at_start_of_line = string.endswith('\n')
-        self.__stderr = Output(sys.stderr.write, sys.stderr.flush)
-        self.__stdout = Output(sys.stdout.write, sys.stdout.flush)
-        if sys.stdout.isatty():
+        if file:
+            self.__stdout = self.__stderr = Output(file.write, file.flush)
+        else:
+            self.__stdout = Output(sys.stdout.write, sys.stdout.flush)
+            self.__stderr = Output(sys.stdout.write, sys.stdout.flush)
+        if file or sys.stdout.isatty():
             self.__out = self.__stdout
             self.__err = self.__stdout
         else:
diff --git a/stgit/run.py b/stgit/run.py
index 0b79729..9d50e43 100644
--- a/stgit/run.py
+++ b/stgit/run.py
@@ -27,12 +27,22 @@ 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', ''))
 
 class Run:
     exc = RunException
@@ -47,22 +57,23 @@ 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:
-                out.info('cwd: %s' % self.__cwd)
+                _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]:
-                        out.info('%s: %s' % (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[0])
             self.__starttime = datetime.datetime.now()
     def __log_end(self, retcode):
         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))
+            _logfile.done('%1.3f s' % (duration.microseconds/1e6
+                                       + duration.seconds))
     def __check_exitcode(self):
         if self.__good_retvals == None:
             return

[StGit PATCH 3/5] Show full command in subprocess profiling

[Karl Hasselström]

Showing just the executable name isn't so useful now that it's always
"git".

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

---

 stgit/run.py |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)


diff --git a/stgit/run.py b/stgit/run.py
index 9d50e43..befd3c1 100644
--- a/stgit/run.py
+++ b/stgit/run.py
@@ -65,7 +65,7 @@ class Run:
                     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':
-            _logfile.start('Running subprocess %s' % self.__cmd[0])
+            _logfile.start('Running subprocess %s' % self.__cmd)
             self.__starttime = datetime.datetime.now()
     def __log_end(self, retcode):
         if _log_mode == 'debug':

[StGit PATCH 4/5] Log subprocess calls during performance testing

[Karl Hasselström]

Log each command's subprocess calls to a separate file.

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

---

 perf/perftest.py |   12 ++++++++++--
 1 files changed, 10 insertions(+), 2 deletions(-)


diff --git a/perf/perftest.py b/perf/perftest.py
index 7072772..e5ed04b 100644
--- a/perf/perftest.py
+++ b/perf/perftest.py
@@ -1,4 +1,4 @@
-import datetime, subprocess, sys
+import datetime, os, os.path, subprocess, sys
 
 def duration(t1, t2):
     d = t2 - t1
@@ -8,8 +8,16 @@ class Run(object):
     def __init__(self):
         self.__cwd = None
         self.__log = []
+    def __logfile(self, cmd):
+        fn = os.path.join(os.getcwd(), '%04d.log' % len(self.__log))
+        f = open(fn, 'w')
+        f.write(' '.join(cmd) + '\n' + '-'*70 + '\n\n')
+        f.close()
+        return fn
     def __call__(self, *cmd, **args):
-        kwargs = { 'cwd': self.__cwd }
+        env = dict(os.environ)
+        env['STGIT_SUBPROCESS_LOG'] = 'profile:' + self.__logfile(cmd)
+        kwargs = { 'cwd': self.__cwd, 'env': env }
         if args.get('capture_stdout', False):
             kwargs['stdout'] = subprocess.PIPE
         start = datetime.datetime.now()

[StGit PATCH 5/5] Global performance logging

[Karl Hasselström]

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

Re: [StGit PATCH 2/5] Log subproces activity to a file

[Catalin Marinas]

2008/7/17 Karl Hasselström <kha@treskal.com>:
> If the user sets $STGIT_SUBPROCESS_LOG to a log mode followed by a
> colon and a file name, append the log to that file instead of writing
> it to stdout.

OK.

-- 
Catalin

Re: [StGit PATCH 3/5] Show full command in subprocess profiling

[Catalin Marinas]

2008/7/17 Karl Hasselström <kha@treskal.com>:
> Showing just the executable name isn't so useful now that it's always
> "git".

Yes, indeed.

-- 
Catalin