Mercurial > hg
view mercurial/statprof.py @ 30779:38aa1ca97b6a
repair: migrate revlogs during upgrade
Our next step for in-place upgrade is to migrate store data. Revlogs
are the biggest source of data within the store and a store is useless
without them, so we implement their migration first.
Our strategy for migrating revlogs is to walk the store and call
`revlog.clone()` on each revlog. There are some minor complications.
Because revlogs have different storage options (e.g. changelog has
generaldelta and delta chains disabled), we need to obtain the
correct class of revlog so inserted data is encoded properly for its
type.
Various attempts at implementing progress indicators that didn't lead
to frustration from false "it's almost done" indicators were made.
I initially used a single progress bar based on number of revlogs.
However, this quickly churned through all filelogs, got to 99% then
effectively froze at 99.99% when it got to the manifest.
So I converted the progress bar to total revision count. This was a
little bit better. But the manifest was still significantly slower
than filelogs and it took forever to process the last few percent.
I then tried both revision/chunk bytes and raw bytes as the
denominator. This had the opposite effect: because so much data is in
manifests, it would churn through filelogs without showing much
progress. When it got to manifests, it would fill in 90+% of the
progress bar.
I finally gave up having a unified progress bar and instead implemented
3 progress bars: 1 for filelog revisions, 1 for manifest revisions, and
1 for changelog revisions. I added extra messages indicating the total
number of revisions of each so users know there are more progress bars
coming.
I also added extra messages before and after each stage to give extra
details about what is happening. Strictly speaking, this isn't
necessary. But the numbers are impressive. For example, when converting
a non-generaldelta mozilla-central repository, the messages you see are:
migrating 2475593 total revisions (1833043 in filelogs, 321156 in manifests, 321394 in changelog)
migrating 1.67 GB in store; 2508 GB tracked data
migrating 267868 filelogs containing 1833043 revisions (1.09 GB in store; 57.3 GB tracked data)
finished migrating 1833043 filelog revisions across 267868 filelogs; change in size: -415776 bytes
migrating 1 manifests containing 321156 revisions (518 MB in store; 2451 GB tracked data)
That "2508 GB" figure really blew me away. I had no clue that the raw
tracked data in mozilla-central was that large. Granted, 2451 GB is in
the manifest and "only" 57.3 GB is in filelogs. But still.
It's worth noting that gratuitous loading of source revlogs in order
to display numbers and progress bars does serve a purpose: it ensures
we can open all source revlogs. We don't want to spend several minutes
copying revlogs only to encounter a permissions error or similar later.
As part of this commit, we also add swapping of the store directory
to the upgrade function. After revlogs are converted, we move the
old store into the backup directory then move the temporary repo's
store into the old store's location. On well-behaved systems, this
should be 2 atomic operations and the window of inconsistency show be
very narrow.
There are still a few improvements to be made to store copying and
upgrading. But this commit gets the bulk of the work out of the way.
author | Gregory Szorc <gregory.szorc@gmail.com> |
---|---|
date | Sun, 18 Dec 2016 17:00:15 -0800 |
parents | 344e68882cd3 |
children | 262c2be8ea5a |
line wrap: on
line source
#!/usr/bin/env python ## statprof.py ## Copyright (C) 2012 Bryan O'Sullivan <bos@serpentine.com> ## Copyright (C) 2011 Alex Fraser <alex at phatcore dot com> ## Copyright (C) 2004,2005 Andy Wingo <wingo at pobox dot com> ## Copyright (C) 2001 Rob Browning <rlb at defaultvalue dot org> ## This library is free software; you can redistribute it and/or ## modify it under the terms of the GNU Lesser General Public ## License as published by the Free Software Foundation; either ## version 2.1 of the License, or (at your option) any later version. ## ## This library is distributed in the hope that it will be useful, ## but WITHOUT ANY WARRANTY; without even the implied warranty of ## MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU ## Lesser General Public License for more details. ## ## You should have received a copy of the GNU Lesser General Public ## License along with this program; if not, contact: ## ## Free Software Foundation Voice: +1-617-542-5942 ## 59 Temple Place - Suite 330 Fax: +1-617-542-2652 ## Boston, MA 02111-1307, USA gnu@gnu.org """ statprof is intended to be a fairly simple statistical profiler for python. It was ported directly from a statistical profiler for guile, also named statprof, available from guile-lib [0]. [0] http://wingolog.org/software/guile-lib/statprof/ To start profiling, call statprof.start(): >>> start() Then run whatever it is that you want to profile, for example: >>> import test.pystone; test.pystone.pystones() Then stop the profiling and print out the results: >>> stop() >>> display() % cumulative self time seconds seconds name 26.72 1.40 0.37 pystone.py:79:Proc0 13.79 0.56 0.19 pystone.py:133:Proc1 13.79 0.19 0.19 pystone.py:208:Proc8 10.34 0.16 0.14 pystone.py:229:Func2 6.90 0.10 0.10 pystone.py:45:__init__ 4.31 0.16 0.06 pystone.py:53:copy ... All of the numerical data is statistically approximate. In the following column descriptions, and in all of statprof, "time" refers to execution time (both user and system), not wall clock time. % time The percent of the time spent inside the procedure itself (not counting children). cumulative seconds The total number of seconds spent in the procedure, including children. self seconds The total number of seconds spent in the procedure itself (not counting children). name The name of the procedure. By default statprof keeps the data collected from previous runs. If you want to clear the collected data, call reset(): >>> reset() reset() can also be used to change the sampling frequency from the default of 1000 Hz. For example, to tell statprof to sample 50 times a second: >>> reset(50) This means that statprof will sample the call stack after every 1/50 of a second of user + system time spent running on behalf of the python process. When your process is idle (for example, blocking in a read(), as is the case at the listener), the clock does not advance. For this reason statprof is not currently not suitable for profiling io-bound operations. The profiler uses the hash of the code object itself to identify the procedures, so it won't confuse different procedures with the same name. They will show up as two different rows in the output. Right now the profiler is quite simplistic. I cannot provide call-graphs or other higher level information. What you see in the table is pretty much all there is. Patches are welcome :-) Threading --------- Because signals only get delivered to the main thread in Python, statprof only profiles the main thread. However because the time reporting function uses per-process timers, the results can be significantly off if other threads' work patterns are not similar to the main thread's work patterns. """ # no-check-code from __future__ import absolute_import, division, print_function import collections import contextlib import getopt import inspect import json import os import signal import sys import tempfile import threading import time from . import ( encoding, pycompat, ) defaultdict = collections.defaultdict contextmanager = contextlib.contextmanager __all__ = ['start', 'stop', 'reset', 'display', 'profile'] skips = set(["util.py:check", "extensions.py:closure", "color.py:colorcmd", "dispatch.py:checkargs", "dispatch.py:<lambda>", "dispatch.py:_runcatch", "dispatch.py:_dispatch", "dispatch.py:_runcommand", "pager.py:pagecmd", "dispatch.py:run", "dispatch.py:dispatch", "dispatch.py:runcommand", "hg.py:<module>", "evolve.py:warnobserrors", ]) ########################################################################### ## Utils def clock(): times = os.times() return times[0] + times[1] ########################################################################### ## Collection data structures class ProfileState(object): def __init__(self, frequency=None): self.reset(frequency) def reset(self, frequency=None): # total so far self.accumulated_time = 0.0 # start_time when timer is active self.last_start_time = None # a float if frequency: self.sample_interval = 1.0 / frequency elif not hasattr(self, 'sample_interval'): # default to 1000 Hz self.sample_interval = 1.0 / 1000.0 else: # leave the frequency as it was pass self.remaining_prof_time = None # for user start/stop nesting self.profile_level = 0 self.samples = [] def accumulate_time(self, stop_time): self.accumulated_time += stop_time - self.last_start_time def seconds_per_sample(self): return self.accumulated_time / len(self.samples) state = ProfileState() class CodeSite(object): cache = {} __slots__ = (u'path', u'lineno', u'function', u'source') def __init__(self, path, lineno, function): self.path = path self.lineno = lineno self.function = function self.source = None def __eq__(self, other): try: return (self.lineno == other.lineno and self.path == other.path) except: return False def __hash__(self): return hash((self.lineno, self.path)) @classmethod def get(cls, path, lineno, function): k = (path, lineno) try: return cls.cache[k] except KeyError: v = cls(path, lineno, function) cls.cache[k] = v return v def getsource(self, length): if self.source is None: lineno = self.lineno - 1 fp = None try: fp = open(self.path) for i, line in enumerate(fp): if i == lineno: self.source = line.strip() break except: pass finally: if fp: fp.close() if self.source is None: self.source = '' source = self.source if len(source) > length: source = source[:(length - 3)] + "..." return source def filename(self): return os.path.basename(self.path) class Sample(object): __slots__ = (u'stack', u'time') def __init__(self, stack, time): self.stack = stack self.time = time @classmethod def from_frame(cls, frame, time): stack = [] while frame: stack.append(CodeSite.get(frame.f_code.co_filename, frame.f_lineno, frame.f_code.co_name)) frame = frame.f_back return Sample(stack, time) ########################################################################### ## SIGPROF handler def profile_signal_handler(signum, frame): if state.profile_level > 0: now = clock() state.accumulate_time(now) state.samples.append(Sample.from_frame(frame, state.accumulated_time)) signal.setitimer(signal.ITIMER_PROF, state.sample_interval, 0.0) state.last_start_time = now stopthread = threading.Event() def samplerthread(tid): while not stopthread.is_set(): now = clock() state.accumulate_time(now) frame = sys._current_frames()[tid] state.samples.append(Sample.from_frame(frame, state.accumulated_time)) state.last_start_time = now time.sleep(state.sample_interval) stopthread.clear() ########################################################################### ## Profiling API def is_active(): return state.profile_level > 0 lastmechanism = None def start(mechanism='thread'): '''Install the profiling signal handler, and start profiling.''' state.profile_level += 1 if state.profile_level == 1: state.last_start_time = clock() rpt = state.remaining_prof_time state.remaining_prof_time = None global lastmechanism lastmechanism = mechanism if mechanism == 'signal': signal.signal(signal.SIGPROF, profile_signal_handler) signal.setitimer(signal.ITIMER_PROF, rpt or state.sample_interval, 0.0) elif mechanism == 'thread': frame = inspect.currentframe() tid = [k for k, f in sys._current_frames().items() if f == frame][0] state.thread = threading.Thread(target=samplerthread, args=(tid,), name="samplerthread") state.thread.start() def stop(): '''Stop profiling, and uninstall the profiling signal handler.''' state.profile_level -= 1 if state.profile_level == 0: if lastmechanism == 'signal': rpt = signal.setitimer(signal.ITIMER_PROF, 0.0, 0.0) signal.signal(signal.SIGPROF, signal.SIG_IGN) state.remaining_prof_time = rpt[0] elif lastmechanism == 'thread': stopthread.set() state.thread.join() state.accumulate_time(clock()) state.last_start_time = None statprofpath = encoding.environ.get('STATPROF_DEST') if statprofpath: save_data(statprofpath) return state def save_data(path): with open(path, 'w+') as file: file.write(str(state.accumulated_time) + '\n') for sample in state.samples: time = str(sample.time) stack = sample.stack sites = ['\1'.join([s.path, str(s.lineno), s.function]) for s in stack] file.write(time + '\0' + '\0'.join(sites) + '\n') def load_data(path): lines = open(path, 'r').read().splitlines() state.accumulated_time = float(lines[0]) state.samples = [] for line in lines[1:]: parts = line.split('\0') time = float(parts[0]) rawsites = parts[1:] sites = [] for rawsite in rawsites: siteparts = rawsite.split('\1') sites.append(CodeSite.get(siteparts[0], int(siteparts[1]), siteparts[2])) state.samples.append(Sample(sites, time)) def reset(frequency=None): '''Clear out the state of the profiler. Do not call while the profiler is running. The optional frequency argument specifies the number of samples to collect per second.''' assert state.profile_level == 0, "Can't reset() while statprof is running" CodeSite.cache.clear() state.reset(frequency) @contextmanager def profile(): start() try: yield finally: stop() display() ########################################################################### ## Reporting API class SiteStats(object): def __init__(self, site): self.site = site self.selfcount = 0 self.totalcount = 0 def addself(self): self.selfcount += 1 def addtotal(self): self.totalcount += 1 def selfpercent(self): return self.selfcount / len(state.samples) * 100 def totalpercent(self): return self.totalcount / len(state.samples) * 100 def selfseconds(self): return self.selfcount * state.seconds_per_sample() def totalseconds(self): return self.totalcount * state.seconds_per_sample() @classmethod def buildstats(cls, samples): stats = {} for sample in samples: for i, site in enumerate(sample.stack): sitestat = stats.get(site) if not sitestat: sitestat = SiteStats(site) stats[site] = sitestat sitestat.addtotal() if i == 0: sitestat.addself() return [s for s in stats.itervalues()] class DisplayFormats: ByLine = 0 ByMethod = 1 AboutMethod = 2 Hotpath = 3 FlameGraph = 4 Json = 5 def display(fp=None, format=3, data=None, **kwargs): '''Print statistics, either to stdout or the given file object.''' data = data or state if fp is None: import sys fp = sys.stdout if len(data.samples) == 0: print('No samples recorded.', file=fp) return if format == DisplayFormats.ByLine: display_by_line(data, fp) elif format == DisplayFormats.ByMethod: display_by_method(data, fp) elif format == DisplayFormats.AboutMethod: display_about_method(data, fp, **kwargs) elif format == DisplayFormats.Hotpath: display_hotpath(data, fp, **kwargs) elif format == DisplayFormats.FlameGraph: write_to_flame(data, fp, **kwargs) elif format == DisplayFormats.Json: write_to_json(data, fp) else: raise Exception("Invalid display format") if format != DisplayFormats.Json: print('---', file=fp) print('Sample count: %d' % len(data.samples), file=fp) print('Total time: %f seconds' % data.accumulated_time, file=fp) def display_by_line(data, fp): '''Print the profiler data with each sample line represented as one row in a table. Sorted by self-time per line.''' stats = SiteStats.buildstats(data.samples) stats.sort(reverse=True, key=lambda x: x.selfseconds()) print('%5.5s %10.10s %7.7s %-8.8s' % ('% ', 'cumulative', 'self', ''), file=fp) print('%5.5s %9.9s %8.8s %-8.8s' % ("time", "seconds", "seconds", "name"), file=fp) for stat in stats: site = stat.site sitelabel = '%s:%d:%s' % (site.filename(), site.lineno, site.function) print('%6.2f %9.2f %9.2f %s' % (stat.selfpercent(), stat.totalseconds(), stat.selfseconds(), sitelabel), file=fp) def display_by_method(data, fp): '''Print the profiler data with each sample function represented as one row in a table. Important lines within that function are output as nested rows. Sorted by self-time per line.''' print('%5.5s %10.10s %7.7s %-8.8s' % ('% ', 'cumulative', 'self', ''), file=fp) print('%5.5s %9.9s %8.8s %-8.8s' % ("time", "seconds", "seconds", "name"), file=fp) stats = SiteStats.buildstats(data.samples) grouped = defaultdict(list) for stat in stats: grouped[stat.site.filename() + ":" + stat.site.function].append(stat) # compute sums for each function functiondata = [] for fname, sitestats in grouped.iteritems(): total_cum_sec = 0 total_self_sec = 0 total_percent = 0 for stat in sitestats: total_cum_sec += stat.totalseconds() total_self_sec += stat.selfseconds() total_percent += stat.selfpercent() functiondata.append((fname, total_cum_sec, total_self_sec, total_percent, sitestats)) # sort by total self sec functiondata.sort(reverse=True, key=lambda x: x[2]) for function in functiondata: if function[3] < 0.05: continue print('%6.2f %9.2f %9.2f %s' % (function[3], # total percent function[1], # total cum sec function[2], # total self sec function[0]), # file:function file=fp) function[4].sort(reverse=True, key=lambda i: i.selfseconds()) for stat in function[4]: # only show line numbers for significant locations (>1% time spent) if stat.selfpercent() > 1: source = stat.site.getsource(25) stattuple = (stat.selfpercent(), stat.selfseconds(), stat.site.lineno, source) print('%33.0f%% %6.2f line %s: %s' % (stattuple), file=fp) def display_about_method(data, fp, function=None, **kwargs): if function is None: raise Exception("Invalid function") filename = None if ':' in function: filename, function = function.split(':') relevant_samples = 0 parents = {} children = {} for sample in data.samples: for i, site in enumerate(sample.stack): if site.function == function and (not filename or site.filename() == filename): relevant_samples += 1 if i != len(sample.stack) - 1: parent = sample.stack[i + 1] if parent in parents: parents[parent] = parents[parent] + 1 else: parents[parent] = 1 if site in children: children[site] = children[site] + 1 else: children[site] = 1 parents = [(parent, count) for parent, count in parents.iteritems()] parents.sort(reverse=True, key=lambda x: x[1]) for parent, count in parents: print('%6.2f%% %s:%s line %s: %s' % (count / relevant_samples * 100, parent.filename(), parent.function, parent.lineno, parent.getsource(50)), file=fp) stats = SiteStats.buildstats(data.samples) stats = [s for s in stats if s.site.function == function and (not filename or s.site.filename() == filename)] total_cum_sec = 0 total_self_sec = 0 total_self_percent = 0 total_cum_percent = 0 for stat in stats: total_cum_sec += stat.totalseconds() total_self_sec += stat.selfseconds() total_self_percent += stat.selfpercent() total_cum_percent += stat.totalpercent() print( '\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n' % ( filename or '___', function, total_cum_sec, total_cum_percent, total_self_sec, total_self_percent ), file=fp) children = [(child, count) for child, count in children.iteritems()] children.sort(reverse=True, key=lambda x: x[1]) for child, count in children: print(' %6.2f%% line %s: %s' % (count / relevant_samples * 100, child.lineno, child.getsource(50)), file=fp) def display_hotpath(data, fp, limit=0.05, **kwargs): class HotNode(object): def __init__(self, site): self.site = site self.count = 0 self.children = {} def add(self, stack, time): self.count += time site = stack[0] child = self.children.get(site) if not child: child = HotNode(site) self.children[site] = child if len(stack) > 1: i = 1 # Skip boiler plate parts of the stack while i < len(stack) and '%s:%s' % (stack[i].filename(), stack[i].function) in skips: i += 1 if i < len(stack): child.add(stack[i:], time) root = HotNode(None) lasttime = data.samples[0].time for sample in data.samples: root.add(sample.stack[::-1], sample.time - lasttime) lasttime = sample.time def _write(node, depth, multiple_siblings): site = node.site visiblechildren = [c for c in node.children.itervalues() if c.count >= (limit * root.count)] if site: indent = depth * 2 - 1 filename = '' function = '' if len(node.children) > 0: childsite = list(node.children.itervalues())[0].site filename = (childsite.filename() + ':').ljust(15) function = childsite.function # lots of string formatting listpattern = ''.ljust(indent) +\ ('\\' if multiple_siblings else '|') +\ ' %4.1f%% %s %s' liststring = listpattern % (node.count / root.count * 100, filename, function) codepattern = '%' + str(55 - len(liststring)) + 's %s: %s' codestring = codepattern % ('line', site.lineno, site.getsource(30)) finalstring = liststring + codestring childrensamples = sum([c.count for c in node.children.itervalues()]) # Make frames that performed more than 10% of the operation red if node.count - childrensamples > (0.1 * root.count): finalstring = '\033[91m' + finalstring + '\033[0m' # Make frames that didn't actually perform work dark grey elif node.count - childrensamples == 0: finalstring = '\033[90m' + finalstring + '\033[0m' print(finalstring, file=fp) newdepth = depth if len(visiblechildren) > 1 or multiple_siblings: newdepth += 1 visiblechildren.sort(reverse=True, key=lambda x: x.count) for child in visiblechildren: _write(child, newdepth, len(visiblechildren) > 1) if root.count > 0: _write(root, 0, False) def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs): if scriptpath is None: scriptpath = encoding.environ['HOME'] + '/flamegraph.pl' if not os.path.exists(scriptpath): print("error: missing %s" % scriptpath, file=fp) print("get it here: https://github.com/brendangregg/FlameGraph", file=fp) return fd, path = tempfile.mkstemp() file = open(path, "w+") lines = {} for sample in data.samples: sites = [s.function for s in sample.stack] sites.reverse() line = ';'.join(sites) if line in lines: lines[line] = lines[line] + 1 else: lines[line] = 1 for line, count in lines.iteritems(): file.write("%s %s\n" % (line, count)) file.close() if outputfile is None: outputfile = '~/flamegraph.svg' os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile)) print("Written to %s" % outputfile, file=fp) def write_to_json(data, fp): samples = [] for sample in data.samples: stack = [] for frame in sample.stack: stack.append((frame.path, frame.lineno, frame.function)) samples.append((sample.time, stack)) print(json.dumps(samples), file=fp) def printusage(): print(""" The statprof command line allows you to inspect the last profile's results in the following forms: usage: hotpath [-l --limit percent] Shows a graph of calls with the percent of time each takes. Red calls take over 10%% of the total time themselves. lines Shows the actual sampled lines. functions Shows the samples grouped by function. function [filename:]functionname Shows the callers and callees of a particular function. flame [-s --script-path] [-o --output-file path] Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg) Requires that ~/flamegraph.pl exist. (Specify alternate script path with --script-path.)""") def main(argv=None): if argv is None: argv = sys.argv if len(argv) == 1: printusage() return 0 displayargs = {} optstart = 2 displayargs['function'] = None if argv[1] == 'hotpath': displayargs['format'] = DisplayFormats.Hotpath elif argv[1] == 'lines': displayargs['format'] = DisplayFormats.ByLine elif argv[1] == 'functions': displayargs['format'] = DisplayFormats.ByMethod elif argv[1] == 'function': displayargs['format'] = DisplayFormats.AboutMethod displayargs['function'] = argv[2] optstart = 3 elif argv[1] == 'flame': displayargs['format'] = DisplayFormats.FlameGraph else: printusage() return 0 # process options try: opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:", ["help", "limit=", "file=", "output-file=", "script-path="]) except getopt.error as msg: print(msg) printusage() return 2 displayargs['limit'] = 0.05 path = None for o, value in opts: if o in ("-l", "--limit"): displayargs['limit'] = float(value) elif o in ("-f", "--file"): path = value elif o in ("-o", "--output-file"): displayargs['outputfile'] = value elif o in ("-p", "--script-path"): displayargs['scriptpath'] = value elif o in ("-h", "help"): printusage() return 0 else: assert False, "unhandled option %s" % o load_data(path=path) display(**displayargs) return 0 if __name__ == "__main__": sys.exit(main())