Get total runtime and between times for checkpoints in arbitrary chunks of code

profiling.py

from timeit import default_timer as timer


class SimpleProfiler:

    """Class to test times over multiple named checkpoints.

    Usage:
    # Starts timer
    p = SimpleProfiler()

    ... some code ...

    # Add named checkpoint after some code
    p('preprocessing')

    ... more code ...
    # Add another named checkpoint after more code
    p('conversion of ints')

    # Print out profiling information
    print(p)
    """

    def __init__(self):
        self._start_time = timer()
        self._ckpts = [('start', self._start_time)]

    def __call__(self, name):
        """Call profiler('checkpoint name')
        and a time will be stored for that checkpoint.

        Parameters
        ----------
        name : str
            Name of checkpoint for profiling time
        """
        self._ckpts.append((name, timer()))

    def __repr__(self):
        """Formats checkpoint names, times between checkpoints,
        and total times from the start point over all checkpoints.
        """
        if len(self._ckpts) < 2:
            return "No checkpoints to report"
        width = max([len(name[0]) for name in self._ckpts])
        header_msg = "{name:{width}} | {between:10s} | {total:10s}\n"
        msg = header_msg.format(
            name="Ckpt Name",
            width=width,
            between="Between",
            total="Total"
        )
        row_msg = "{name:{width}} | {between:10.2f} | {total:10.2f}\n"
        for i, (ckpt_name, t) in enumerate(self._ckpts):
            if i == 0:
                msg += row_msg.format(
                    name='Start',
                    width=width,
                    between=0.0,
                    total=0.0
                )
            else:
                msg += row_msg.format(
                    name=ckpt_name,
                    width=width,
                    between=t-self._ckpts[i-1][1],
                    total=t-self._ckpts[0][1]
                )
        return msg


if __name__ == '__main__':
    import time

    # Start your timer!
    profiler = SimpleProfiler()
    # Some code here represented by sleep...
    time.sleep(.2)
    profiler('read in data')

    # More code here...
    time.sleep(.1)
    profiler('transform data')

    # Final bit of code...
    time.sleep(.4)
    profiler('extract features')

    # Print out profiler's times
    print(profiler)

    '''
    Ckpt Name        | Between    | Total
    Start            |       0.00 |       0.00
    read in data     |       0.20 |       0.20
    transform data   |       0.10 |       0.30
    extract features |       0.40 |       0.71
    '''