* [StGit PATCH 1/5] Add some performance testing scripts
2008-07-17 20:42 [StGit PATCH 0/5] Performance testing tools Karl Hasselström
@ 2008-07-17 20:42 ` Karl Hasselström
2008-07-17 20:42 ` [StGit PATCH 2/5] Log subproces activity to a file Karl Hasselström
` (3 subsequent siblings)
4 siblings, 0 replies; 8+ messages in thread
From: Karl Hasselström @ 2008-07-17 20:42 UTC (permalink / raw)
To: Catalin Marinas; +Cc: git
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
^ permalink raw reply related [flat|nested] 8+ messages in thread* [StGit PATCH 2/5] Log subproces activity to a file
2008-07-17 20:42 [StGit PATCH 0/5] Performance testing tools Karl Hasselström
2008-07-17 20:42 ` [StGit PATCH 1/5] Add some performance testing scripts Karl Hasselström
@ 2008-07-17 20:42 ` Karl Hasselström
2008-07-18 21:45 ` Catalin Marinas
2008-07-17 20:42 ` [StGit PATCH 3/5] Show full command in subprocess profiling Karl Hasselström
` (2 subsequent siblings)
4 siblings, 1 reply; 8+ messages in thread
From: Karl Hasselström @ 2008-07-17 20:42 UTC (permalink / raw)
To: Catalin Marinas; +Cc: git
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
^ permalink raw reply related [flat|nested] 8+ messages in thread* [StGit PATCH 5/5] Global performance logging
2008-07-17 20:42 [StGit PATCH 0/5] Performance testing tools Karl Hasselström
` (3 preceding siblings ...)
2008-07-17 20:42 ` [StGit PATCH 4/5] Log subprocess calls during performance testing Karl Hasselström
@ 2008-07-17 20:42 ` Karl Hasselström
4 siblings, 0 replies; 8+ messages in thread
From: Karl Hasselström @ 2008-07-17 20:42 UTC (permalink / raw)
To: Catalin Marinas; +Cc: git
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
^ permalink raw reply related [flat|nested] 8+ messages in thread