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