1# -*- coding: utf-8 -*- 2"""Timing related functionality for the xonsh shell. 3 4The following time_it alias and Timer was forked from the IPython project: 5* Copyright (c) 2008-2014, IPython Development Team 6* Copyright (C) 2001-2007 Fernando Perez <fperez@colorado.edu> 7* Copyright (c) 2001, Janko Hauser <jhauser@zscout.de> 8* Copyright (c) 2001, Nathaniel Gray <n8gray@caltech.edu> 9""" 10import os 11import gc 12import sys 13import math 14import time 15import timeit 16import builtins 17import itertools 18 19from xonsh.lazyasd import lazyobject, lazybool 20from xonsh.events import events 21from xonsh.platform import ON_WINDOWS 22 23 24@lazybool 25def _HAVE_RESOURCE(): 26 try: 27 import resource as r 28 29 have = True 30 except ImportError: 31 # There is no distinction of user/system time under windows, so we 32 # just use time.perf_counter() for everything... 33 have = False 34 return have 35 36 37@lazyobject 38def resource(): 39 import resource as r 40 41 return r 42 43 44@lazyobject 45def clocku(): 46 if _HAVE_RESOURCE: 47 48 def clocku(): 49 """clocku() -> floating point number 50 Return the *USER* CPU time in seconds since the start of the 51 process.""" 52 return resource.getrusage(resource.RUSAGE_SELF)[0] 53 54 else: 55 clocku = time.perf_counter 56 return clocku 57 58 59@lazyobject 60def clocks(): 61 if _HAVE_RESOURCE: 62 63 def clocks(): 64 """clocks() -> floating point number 65 Return the *SYSTEM* CPU time in seconds since the start of the 66 process.""" 67 return resource.getrusage(resource.RUSAGE_SELF)[1] 68 69 else: 70 clocks = time.perf_counter 71 return clocks 72 73 74@lazyobject 75def clock(): 76 if _HAVE_RESOURCE: 77 78 def clock(): 79 """clock() -> floating point number 80 Return the *TOTAL USER+SYSTEM* CPU time in seconds since the 81 start of the process.""" 82 u, s = resource.getrusage(resource.RUSAGE_SELF)[:2] 83 return u + s 84 85 else: 86 clock = time.perf_counter 87 return clock 88 89 90@lazyobject 91def clock2(): 92 if _HAVE_RESOURCE: 93 94 def clock2(): 95 """clock2() -> (t_user,t_system) 96 Similar to clock(), but return a tuple of user/system times.""" 97 return resource.getrusage(resource.RUSAGE_SELF)[:2] 98 99 else: 100 101 def clock2(): 102 """Under windows, system CPU time can't be measured. 103 This just returns perf_counter() and zero.""" 104 return time.perf_counter(), 0.0 105 106 return clock2 107 108 109def format_time(timespan, precision=3): 110 """Formats the timespan in a human readable form""" 111 if timespan >= 60.0: 112 # we have more than a minute, format that in a human readable form 113 parts = [("d", 60 * 60 * 24), ("h", 60 * 60), ("min", 60), ("s", 1)] 114 time = [] 115 leftover = timespan 116 for suffix, length in parts: 117 value = int(leftover / length) 118 if value > 0: 119 leftover = leftover % length 120 time.append("{0}{1}".format(str(value), suffix)) 121 if leftover < 1: 122 break 123 return " ".join(time) 124 # Unfortunately the unicode 'micro' symbol can cause problems in 125 # certain terminals. 126 # See bug: https://bugs.launchpad.net/ipython/+bug/348466 127 # Try to prevent crashes by being more secure than it needs to 128 # E.g. eclipse is able to print a mu, but has no sys.stdout.encoding set. 129 units = ["s", "ms", "us", "ns"] # the save value 130 if hasattr(sys.stdout, "encoding") and sys.stdout.encoding: 131 try: 132 "\xb5".encode(sys.stdout.encoding) 133 units = ["s", "ms", "\xb5s", "ns"] 134 except Exception: 135 pass 136 scaling = [1, 1e3, 1e6, 1e9] 137 138 if timespan > 0.0: 139 order = min(-int(math.floor(math.log10(timespan)) // 3), 3) 140 else: 141 order = 3 142 return "{1:.{0}g} {2}".format(precision, timespan * scaling[order], units[order]) 143 144 145class Timer(timeit.Timer): 146 """Timer class that explicitly uses self.inner 147 which is an undocumented implementation detail of CPython, 148 not shared by PyPy. 149 """ 150 151 # Timer.timeit copied from CPython 3.4.2 152 def timeit(self, number=timeit.default_number): 153 """Time 'number' executions of the main statement. 154 To be precise, this executes the setup statement once, and 155 then returns the time it takes to execute the main statement 156 a number of times, as a float measured in seconds. The 157 argument is the number of times through the loop, defaulting 158 to one million. The main statement, the setup statement and 159 the timer function to be used are passed to the constructor. 160 """ 161 it = itertools.repeat(None, number) 162 gcold = gc.isenabled() 163 gc.disable() 164 try: 165 timing = self.inner(it, self.timer) 166 finally: 167 if gcold: 168 gc.enable() 169 return timing 170 171 172INNER_TEMPLATE = """ 173def inner(_it, _timer): 174 #setup 175 _t0 = _timer() 176 for _i in _it: 177 {stmt} 178 _t1 = _timer() 179 return _t1 - _t0 180""" 181 182 183def timeit_alias(args, stdin=None): 184 """Runs timing study on arguments.""" 185 # some real args 186 number = 0 187 quiet = False 188 repeat = 3 189 precision = 3 190 # setup 191 ctx = builtins.__xonsh_ctx__ 192 timer = Timer(timer=clock) 193 stmt = " ".join(args) 194 innerstr = INNER_TEMPLATE.format(stmt=stmt) 195 # Track compilation time so it can be reported if too long 196 # Minimum time above which compilation time will be reported 197 tc_min = 0.1 198 t0 = clock() 199 innercode = builtins.compilex( 200 innerstr, filename="<xonsh-timeit>", mode="exec", glbs=ctx 201 ) 202 tc = clock() - t0 203 # get inner func 204 ns = {} 205 builtins.execx(innercode, glbs=ctx, locs=ns, mode="exec") 206 timer.inner = ns["inner"] 207 # Check if there is a huge difference between the best and worst timings. 208 worst_tuning = 0 209 if number == 0: 210 # determine number so that 0.2 <= total time < 2.0 211 number = 1 212 for _ in range(1, 10): 213 time_number = timer.timeit(number) 214 worst_tuning = max(worst_tuning, time_number / number) 215 if time_number >= 0.2: 216 break 217 number *= 10 218 all_runs = timer.repeat(repeat, number) 219 best = min(all_runs) / number 220 # print some debug info 221 if not quiet: 222 worst = max(all_runs) / number 223 if worst_tuning: 224 worst = max(worst, worst_tuning) 225 # Check best timing is greater than zero to avoid a 226 # ZeroDivisionError. 227 # In cases where the slowest timing is less than 10 microseconds 228 # we assume that it does not really matter if the fastest 229 # timing is 4 times faster than the slowest timing or not. 230 if worst > 4 * best and best > 0 and worst > 1e-5: 231 print( 232 ( 233 "The slowest run took {0:0.2f} times longer than the " 234 "fastest. This could mean that an intermediate result " 235 "is being cached." 236 ).format(worst / best) 237 ) 238 print( 239 "{0} loops, best of {1}: {2} per loop".format( 240 number, repeat, format_time(best, precision) 241 ) 242 ) 243 if tc > tc_min: 244 print("Compiler time: {0:.2f} s".format(tc)) 245 return 246 247 248_timings = {"start": clock()} 249 250 251def setup_timings(): 252 global _timings 253 if "--timings" in sys.argv: 254 events.doc( 255 "on_timingprobe", 256 """ 257 on_timingprobe(name: str) -> None 258 259 Fired to insert some timings into the startuptime list 260 """, 261 ) 262 263 @events.on_timingprobe 264 def timing_on_timingprobe(name, **kw): 265 global _timings 266 _timings[name] = clock() 267 268 @events.on_post_cmdloop 269 def timing_on_post_cmdloop(**kw): 270 global _timings 271 _timings["on_post_cmdloop"] = clock() 272 273 @events.on_post_init 274 def timing_on_post_init(**kw): 275 global _timings 276 _timings["on_post_init"] = clock() 277 278 @events.on_post_rc 279 def timing_on_post_rc(**kw): 280 global _timings 281 _timings["on_post_rc"] = clock() 282 283 @events.on_postcommand 284 def timing_on_postcommand(**kw): 285 global _timings 286 _timings["on_postcommand"] = clock() 287 288 @events.on_pre_cmdloop 289 def timing_on_pre_cmdloop(**kw): 290 global _timings 291 _timings["on_pre_cmdloop"] = clock() 292 293 @events.on_pre_rc 294 def timing_on_pre_rc(**kw): 295 global _timings 296 _timings["on_pre_rc"] = clock() 297 298 @events.on_precommand 299 def timing_on_precommand(**kw): 300 global _timings 301 _timings["on_precommand"] = clock() 302 303 @events.on_ptk_create 304 def timing_on_ptk_create(**kw): 305 global _timings 306 _timings["on_ptk_create"] = clock() 307 308 @events.on_chdir 309 def timing_on_chdir(**kw): 310 global _timings 311 _timings["on_chdir"] = clock() 312 313 @events.on_post_prompt 314 def timing_on_post_prompt(**kw): 315 global _timings 316 _timings = {"on_post_prompt": clock()} 317 318 @events.on_pre_prompt 319 def timing_on_pre_prompt(**kw): 320 global _timings 321 _timings["on_pre_prompt"] = clock() 322 times = list(_timings.items()) 323 times = sorted(times, key=lambda x: x[1]) 324 width = max(len(s) for s, _ in times) + 2 325 header_format = "|{{:<{}}}|{{:^11}}|{{:^11}}|".format(width) 326 entry_format = "|{{:<{}}}|{{:^11.3f}}|{{:^11.3f}}|".format(width) 327 sepline = "|{}|{}|{}|".format("-" * width, "-" * 11, "-" * 11) 328 # Print result table 329 print(" Debug level: {}".format(os.getenv("XONSH_DEBUG", "Off"))) 330 print(sepline) 331 print(header_format.format("Event name", "Time (s)", "Delta (s)")) 332 print(sepline) 333 prevtime = tstart = times[0][1] 334 for name, ts in times: 335 print(entry_format.format(name, ts - tstart, ts - prevtime)) 336 prevtime = ts 337 print(sepline) 338