Trace in Python

Python allows you to trace in detail the execution of a script. The function is provided by sys.settrace() ans sys.setprofile

Time Function Calls

Use the profile or cProfile module

python -m profile myscript.py
python -m cProfile myscript.py

Count Function Calls

Use the trace module.

python -m trace --ignore-dir /opt -s --count --missing myscript.py

Write your own trace function

#!/usr/bin/env python
# -*- coding: utf-8 -*-
"""Development module to quickly trace a program"""

import sys
import time

# _trace is a list of tuplets
# (True/False = call/return, code object, timestamp)
_trace=[]
_processed = False
_running = False

def traceit(frame, event, arg):
    if event == "call":
        _trace.append( (True, frame.f_code, time.time()) )
    elif event == "return":
        _trace.append( (False, frame.f_code, time.time()) )
    # print "f_code          " , frame.f_code
    # print "f_locals        " , frame.f_locals
    # print "f_lineno        " , frame.f_lineno
    return traceit

class Codecall:
    code          = None
    count         = 0
    exclusivetime = 0.0
    childtime     = 0.0
    totaltime     = 0.0
    def __init__(self, code):
        self.code = code
        self.count = 1
    def incCallCount(self, inc=1):
        self.count += inc
    def incExclusiveTime(self, inc=1):
        self.exclusivetime += inc
    def incTotalTime(self, inc=1):
        self.totaltime += inc
    def name(self):
        return self.code.co_name
    def filename(self):
        return self.code.co_filename
    def firstlineno(self):
        return self.code.co_firstlineno


class MyCode:
    co_name        = "__main__"
    co_filename    = "a file"
    co_firstlineno = 1

def processtrace():
    
    stop()
    # _codecalls is a dictionary id(code object) => 
    # tuple(code object, call count, time spent (excl child functions), time spent (incl child functions))
    if len(_trace) == 0:
        raise Exception("No trace to process")
    codecalls = {}
    # list of tuples (id(code object), timestamp)
    stack = []
    prevtime = None
    counter = 0
    tracelen = len(_trace)
    for (state, code, time) in _trace:
        counter += 1
        # print "process %s %s %f with stack %s" % (state, code.co_name, time, stack)
        print "%5d/%5d %6s %-20s %8f  %s" % (counter, tracelen, state, code.co_name+'()', time, stack)
        if len(stack) > 0:
            (prevcodeid, starttime) = stack[-1]
            codecalls[prevcodeid].incExclusiveTime(time-prevtime)
        prevtime = time
        codeid = id(code)
        if state: # call object; add to stack
            if not codeid in codecalls:
                codecalls[codeid] = Codecall(code)
            else:
                codecalls[codeid].incCallCount()
            stack.append( (codeid,time) )
        else: # return; remove from stack
            if len(stack) == 0
                raise Exception("Stack is empty while processing return trace %d/%d of %s() at t=%f" % (counter,tracelen,code.co_name,time))
            stack.pop()
            codecalls[prevcodeid].incTotalTime(time-starttime)
    for codecall in codecalls.values():
        codecall.childtime = codecall.totaltime - codecall.exclusive.time


def summary(maxcalls=100):
    if not _processed:
        processtrace()
    calllen = len(codecalls)
    counter = 0
    print "Total: %d different functions called" % calllen
    print "%-20s %-30s %5s  %5s %14s + %14s = %14s" % ("function name", "filename", "line", "calls", "time spent", "time in childs", "total time spent")
    for codecall in codecalls.values():
        counter += 1
        print "%-20s %-30s %5d  %5d %11f ms + %11f ms = %11f ms" % (codecall.name()+'()', codecall.filename(), codecall.firstlineno(), codecall.count, 1000*codecall.exclusivetime, 1000*codecall.childtime, 1000*codecall.totaltime)
        if counter > maxcalls:
            break

def start():
    sys.settrace(traceit)
    if not _running:
        mycode = MyCode()
        _trace.append( (True, mycode, time.time()) )
    _running = True

def stop():
    if _running:
        _trace.append( (False, mycode, time.time()) )
    sys.settrace(None)
    _running = False