/Misc/tsc_stats.py
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)