#!/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 division

import time

from collections import defaultdict

from contextlib import 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__ = ('path', 'lineno', 'function', '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__ = ('stack', '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 = os.environ.get('STATPROF_DEST')

        save_data(statprofpath)

def save_data(path=None):

    try:

        path = path or (os.environ['HOME'] + '/statprof.data')

        file = open(path, "w+")

        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')

        file.close()

        # The home directory probably didn't exist, or wasn't writable. Oh well.

        pass

def load_data(path=None):

    path = path or (os.environ['HOME'] + '/statprof.data')

    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, **kwargs):

    '''Print statistics, either to stdout or the given file object.'''

    if fp is None:

        import sys

        fp = sys.stdout

    if len(state.samples) == 0:

        print >> fp, ('No samples recorded.')

        return

    if format == DisplayFormats.ByLine:

        display_by_line(fp)

    elif format == DisplayFormats.ByMethod:

        display_by_method(fp)

    elif format == DisplayFormats.AboutMethod:

        display_about_method(fp, **kwargs)

    elif format == DisplayFormats.Hotpath:

        display_hotpath(fp, **kwargs)

    elif format == DisplayFormats.FlameGraph:

        write_to_flame(fp, **kwargs)

    elif format == DisplayFormats.Json:

        write_to_json(fp)

    else:

        raise Exception("Invalid display format")

    if format != DisplayFormats.Json:

        print >> fp, ('---')

        print >> fp, ('Sample count: %d' % len(state.samples))

        print >> fp, ('Total time: %f seconds' % state.accumulated_time)

def display_by_line(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(state.samples)

    stats.sort(reverse=True, key=lambda x: x.selfseconds())

    print >> fp, ('%5.5s %10.10s   %7.7s  %-8.8s' %

                  ('%  ', 'cumulative', 'self', ''))

    print >> fp, ('%5.5s  %9.9s  %8.8s  %-8.8s' %

                  ("time", "seconds", "seconds", "name"))

    for stat in stats:

        site = stat.site

        sitelabel = '%s:%d:%s' % (site.filename(), site.lineno, site.function)

        print >> fp, ('%6.2f %9.2f %9.2f  %s' % (stat.selfpercent(),

                                                 stat.totalseconds(),

                                                 stat.selfseconds(),

                                                 sitelabel))

def display_by_method(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 >> fp, ('%5.5s %10.10s   %7.7s  %-8.8s' %

                  ('%  ', 'cumulative', 'self', ''))

    print >> fp, ('%5.5s  %9.9s  %8.8s  %-8.8s' %

                  ("time", "seconds", "seconds", "name"))

    stats = SiteStats.buildstats(state.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 >> fp, ('%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

        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 >> fp, ('%33.0f%% %6.2f   line %s: %s' % (stattuple))