PageRenderTime 62ms CodeModel.GetById 29ms app.highlight 25ms RepoModel.GetById 2ms app.codeStats 0ms

/Misc/tsc_stats.py

http://unladen-swallow.googlecode.com/
Python | 282 lines | 171 code | 39 blank | 72 comment | 33 complexity | da3f43cd611153a89a37a7d0dcc37695 MD5 | raw file
  1#!/usr/bin/env python
  2
  3"""Compute timing statistics based on the output of Python with TSC enabled.
  4
  5To use this script, pass --with-tsc to ./configure and call sys.settscdump(True)
  6in the script that you want to use to record timings.  When the script and
  7interpreter exit, the timings will be printed to stderr as a CSV file separated
  8by tabs.  You should redirect that to this script, either through a file or
  9pipe:
 10
 11    ./python myscript.py 2>&1 >&3 3>&- | Misc/tsc_stats.py
 12    ./python myscript.py 2> stats ; Misc/tsc_stats.py stats
 13
 14This script outputs statistics about function call overhead, exception handling
 15overhead, bytecode to LLVM IR compilation overhead, native code generation
 16overhead, and various other things.
 17
 18In order to not use too much memory, the event timer in Python periodically
 19flushes the event buffer.  This messes up a lot of the timings, so it also
 20prints out events that let us figure out how long the flush took.  We take that
 21time and go back and adjust the times to erase that overhead.  Otherwise our
 22max, mean, and stddev statistics would be meaningless.
 23
 24In order to get more meaningful results for function call overhead, any time
 25spent doing compilation in the eval loop is not counted against the function
 26call overhead.  Otherwise the mean and max function call overhead times would be
 27way off.
 28
 29"""
 30
 31from __future__ import division
 32
 33import itertools
 34import math
 35import sys
 36
 37
 38def median(xs):
 39    """Return the median of some numeric values.
 40
 41    Assumes that the input list is sorted.
 42    """
 43    mid = len(xs) // 2
 44    if len(xs) % 2 == 0:
 45        return (xs[mid] + xs[mid - 1]) / 2
 46    else:
 47        return xs[mid]
 48
 49
 50def decile_decorator(func):
 51    def decile_func(xs):
 52        """Return the func applied to the inter-decile 80% of the input.
 53
 54        Assumes that the input list is sorted.
 55        """
 56        decile = len(xs) // 10
 57        if decile == 0:
 58            # Special case this because -0 == 0, so the list slice below doesn't
 59            # work.
 60            return func(xs)
 61        return func(xs[decile:-decile])
 62    return decile_func
 63
 64
 65def mean(xs):
 66    """Return the mean of some numeric values."""
 67    return float(sum(xs)) / len(xs)
 68
 69
 70decile_mean = decile_decorator(mean)
 71
 72
 73def stddev(xs):
 74    """Return the standard deviation of some numeric values."""
 75    if len(xs) == 1:
 76        return 0  # Avoid doing a ZeroDivisionError.
 77    mn = mean(xs)
 78    deviations = (x - mn for x in xs)
 79    square_sum = sum(d * d for d in deviations)
 80    variance = square_sum / float(len(xs) - 1)
 81    return math.sqrt(variance)
 82
 83
 84decile_stddev = decile_decorator(stddev)
 85
 86
 87class DeltaStatistic(object):
 88
 89    """This class matches and stores delta timings for a class of events."""
 90
 91    def __init__(self, start_prefix, end_prefix, missed_events):
 92        """Constructor.
 93
 94        Args:
 95            start_prefix: the prefix matching the start event
 96            end_prefix: the prefix matching the end event
 97            missed_events: the list that we should missed events to
 98        """
 99        self.start_prefix = start_prefix
100        self.end_prefix = end_prefix
101        self.missed_events = missed_events
102        self.delta_dict = {}
103        self.aggregate_deltas = []
104        self.started = False
105        self.start_event = None
106        self.start_time = 0
107
108    def try_match(self, thread, event, time):
109        """If this event matches the statistic, record it and return True.
110
111        Args:
112            thread: the thread id for this event
113            event: the name of the event
114            time: the timestamp counter when the event occurred
115        """
116        # TODO(rnk): Keep things thread local.
117        if event.startswith(self.start_prefix):
118            # If we already started, we missed an end event.  Record the old
119            # start event that didn't get an end, and use this start event
120            # instead.
121            if self.started:
122                self.missed_events.append((self.start_event, self.start_time))
123
124            self.started = True
125            self.start_event = event
126            self.start_time = time
127            return True
128
129        elif event.startswith(self.end_prefix):
130            # If we have not started, we missed a start event.  Record this
131            # end event, and ignore it.
132            if not self.started:
133                self.missed_events.append((event, time))
134                return True
135
136            delta = time - self.start_time
137            key = (self.start_event, event)
138            self.delta_dict.setdefault(key, []).append(delta)
139            self.aggregate_deltas.append(delta)
140
141            # Reset us looking for a start event.
142            self.started = False
143            self.start_event = None
144            self.start_time = 0
145            return True
146
147        return False
148
149
150class TimeAnalyzer(object):
151
152    def __init__(self, input):
153        self.input = input
154        self.missed_events = []
155        m_e = self.missed_events  # Shorthand
156        self.call_stats = DeltaStatistic("CALL_START_", "CALL_ENTER_", m_e)
157        self.exception_stats = DeltaStatistic("EXCEPT_RAISE_", "EXCEPT_CATCH_",
158                                              m_e)
159        self.global_stats = DeltaStatistic("LOAD_GLOBAL_ENTER_",
160                                           "LOAD_GLOBAL_EXIT_", m_e)
161        self.native_stats = DeltaStatistic("JIT_START", "JIT_END", m_e)
162        self.llvm_stats = DeltaStatistic("LLVM_COMPILE_START",
163                                         "LLVM_COMPILE_END", m_e)
164        self.eval_compile_stats = DeltaStatistic("EVAL_COMPILE_START",
165                                                 "EVAL_COMPILE_END", m_e)
166        self.flush_stats = DeltaStatistic("FLUSH_START", "FLUSH_END", m_e)
167        self.statistics = [
168                self.call_stats,
169                self.exception_stats,
170                self.global_stats,
171                self.native_stats,
172                self.llvm_stats,
173                self.eval_compile_stats,
174                self.flush_stats,
175                ]
176
177    def flush_fudge(self, flush_delta):
178        """Fudge the start time of open stats to eliminate flush overhead."""
179        for stat in self.statistics:
180            if stat.started:
181                stat.start_time += flush_delta
182
183    def analyze(self):
184        """Process the input into categorized timings."""
185        for line in self.input:
186            (thread, event, time) = line.strip().split("\t")
187            time = int(time)
188            for stat in self.statistics:
189                if stat.try_match(thread, event, time):
190                    if not stat.started and stat.aggregate_deltas:
191                        delta = stat.aggregate_deltas[-1]
192                        if (stat is self.eval_compile_stats and
193                            self.call_stats.started):
194                            # Fudge the call_stats start time to erase
195                            # compilation overhead in the eval loop.
196                            self.call_stats.start_time += delta
197                        if stat is self.flush_stats:
198                            # Fudge every stat that has an open timing to
199                            # eliminate the flush overhead.
200                            self.flush_fudge(delta)
201                    break
202            else:
203                # If no statistic matched the event, log it as missed.
204                self.missed_events.append((event, time))
205
206    def print_deltas(self, deltas):
207        """Print out statistics about this sequence of timings."""
208        print "occurrences:", len(deltas)
209        if deltas:
210            deltas = sorted(deltas)
211            print "median:", median(deltas)
212            print "inter-decile mean:", decile_mean(deltas)
213            print "min delta:", deltas[0]
214            print "max delta:", deltas[-1]
215            print "inter-decile stddev:", decile_stddev(deltas)
216
217    def print_stat_deltas(self, stat):
218        """Print out the deltas for this statistic broken down by pairing."""
219        for ((start, end), deltas) in stat.delta_dict.iteritems():
220            print "for transitions from %s to %s:" % (start, end)
221            self.print_deltas(deltas)
222            print
223
224    def print_stat_aggregate(self, stat):
225        """Print out the aggregate deltas for this statistic."""
226        print ("In aggregate, for transitions from %s* to %s*:" %
227               (stat.start_prefix, stat.end_prefix))
228        self.print_deltas(stat.aggregate_deltas)
229
230    def print_analysis(self):
231        print ("All times are in time stamp counter units, which are related "
232               "to your CPU frequency.")
233        print
234        print "Call overhead:"
235        print "----------------------------------------"
236        self.print_stat_deltas(self.call_stats)
237        self.print_stat_aggregate(self.call_stats)
238        print
239        print "Exception handling overhead:"
240        print "----------------------------------------"
241        self.print_stat_deltas(self.exception_stats)
242        self.print_stat_aggregate(self.exception_stats)
243        print
244        print "LOAD_GLOBAL overhead:"
245        print "----------------------------------------"
246        self.print_stat_deltas(self.global_stats)
247        self.print_stat_aggregate(self.global_stats)
248        print
249        print "LLVM IR compilation:"
250        print "----------------------------------------"
251        self.print_stat_aggregate(self.llvm_stats)
252        print
253        print "Native code generation:"
254        print "----------------------------------------"
255        self.print_stat_aggregate(self.native_stats)
256        print
257        print "Total time doing compilation in the eval loop:"
258        print "----------------------------------------"
259        self.print_stat_aggregate(self.eval_compile_stats)
260        print
261
262        grouped = {}
263        for (event, time) in self.missed_events:
264            grouped[event] = grouped.get(event, 0) + 1
265        print "missed events:",
266        print ", ".join("%s %d" % (event, count)
267                        for (event, count) in grouped.iteritems())
268
269
270def main(argv):
271    if argv:
272        assert len(argv) == 2, "tsc_stats.py expects one file as input."
273        input = open(argv[1])
274    else:
275        input = sys.stdin
276    analyzer = TimeAnalyzer(input)
277    analyzer.analyze()
278    analyzer.print_analysis()
279
280
281if __name__ == "__main__":
282    main(sys.argv)