how to get a Python timing object to retain appropriate information within function and decorator scopes
Question: I'm writing a module for quick and easy timing in a Python program. The idea
is that little instances of clocks can be created throughout the code. These
clocks are available as objects that can be started, stopped, started again
and queried. Any clocks instantiated are added to a module list of all clocks.
At the conclusion of the program, a printout of all clocks (either a listing
of all clocks or the means of all similar clocks) can be requested of this
list.

I've got a lot of it working, but the timing of functions is still causing me
difficulty. Specifically, the times measured for the functions are measured as
0 using either explicit clocks or using a decorator, when the time measured
for functions 1 and 1 should be ~3 seconds and ~4 seconds respectively.

I suspect that I am not retaining the clock attribute `_startTimeTmp` in an
appropriate way (it can be reset for the purposes of internal calculations).

I would really appreciate some guidance on getting the timers working
correctly. I've got myself a bit confused on how to solve it!

I'm aware that the code may look slightly long, but I've minimized it as much
as I know how to without obscuring the vision of what I'm trying to do overall
(so that any suggestions proposed don't remove critical functionality). I do
think it's reasonably clear how it works, at least.

# module (shijian.py):

    
    
    from __future__ import division
    import os
    import time
    import uuid as uuid
    import datetime
    import inspect
    import functools
    
    def _main():
        global clocks
        clocks = Clocks()
    
    def time_UTC(
        style = None
        ):
        return(
            style_datetime_object(
                datetimeObject = datetime.datetime.utcnow(),
                style = style
            )
        )
    
    def style_datetime_object(
        datetimeObject = None,
        style = "YYYY-MM-DDTHHMMSS"
        ):
        # filename safe
        if style == "YYYY-MM-DDTHHMMSSZ":
            return(datetimeObject.strftime('%Y-%m-%dT%H%M%SZ'))
        # microseconds
        elif style == "YYYY-MM-DDTHHMMSSMMMMMMZ":
            return(datetimeObject.strftime('%Y-%m-%dT%H%M%S%fZ'))
        # elegant
        elif style == "YYYY-MM-DD HH:MM:SS UTC":
            return(datetimeObject.strftime('%Y-%m-%d %H:%M:%SZ'))
        # UNIX time in seconds with second fraction
        elif style == "UNIX time S.SSSSSS":
            return(
                (datetimeObject -\
                datetime.datetime.utcfromtimestamp(0)).total_seconds()
            )
        # UNIX time in seconds rounded
        elif style == "UNIX time S":
            return(
                int((datetimeObject -\
                datetime.datetime.utcfromtimestamp(0)).total_seconds())
            )
        # filename safe
        else:
            return(datetimeObject.strftime('%Y-%m-%dT%H%M%SZ'))
    
    def UID():
        return(str(uuid.uuid4()))
    
    class Clock(object):
    
        def __init__(
            self,
            name               = None,
            start              = True
            ):
            self._name         = name
            self._start        = start # Boolean start clock on instantiation
            self._startTime    = None # internal (value to return)
            self._startTimeTmp = None # internal (value for calculations)
            self._stopTime     = None # internal (value to return)
            self._updateTime   = None # internal
            # If no name is specified, generate a unique one.
            if self._name is None:
                self._name     = UID()
            # If a global clock list is detected, add a clock instance to it.
            if "clocks" in globals():
                clocks.add(self)
            self.reset()
            if self._start:
                self.start()
    
        def start(self):
            self._startTimeTmp = datetime.datetime.utcnow()
            self._startTime    = datetime.datetime.utcnow()
    
        def stop(self):
            self._updateTime   = None
            self._startTimeTmp = None
            self._stopTime     = datetime.datetime.utcnow()
    
        # Update the clock accumulator.
        def update(self):
            if self._updateTime:        
                self.accumulator += (
                    datetime.datetime.utcnow() - self._updateTime
                )
            else:
                self.accumulator += (
                    datetime.datetime.utcnow() - self._startTimeTmp
                )
            self._updateTime   = datetime.datetime.utcnow()
    
        def reset(self):
            self.accumulator   = datetime.timedelta(0)
            self._startTimeTmp = None
    
        # If the clock has a start time, add the difference between now and the
        # start time to the accumulator and return the accumulation. If the clock
        # does not have a start time, return the accumulation.
        def elapsed(self):
            if self._startTimeTmp:
                self.update()
            return(self.accumulator)
    
        def name(self):
            return(self._name)
    
        def time(self):
            return(self.elapsed().total_seconds())
    
        def startTime(self):
            if self._startTime:
                return(style_datetime_object(datetimeObject = self._startTime))
            else:
                return("none")
    
        def stopTime(self):
            if self._stopTime:
                return(style_datetime_object(datetimeObject = self._stopTime))
            else:
                return("none")
    
        def report(
            self
            ):
            string = "clock attribute".ljust(39)     + "value"
            string += "\nname".ljust(40)             + self.name()
            string += "\ntime start (s)".ljust(40)   + self.startTime()
            string += "\ntime stop (s)".ljust(40)    + self.stopTime()
            string += "\ntime elapsed (s)".ljust(40) + str(self.time())
            string += "\n"
            return(string)
    
        def printout(self):
            print(self.report())
    
    def timer(function):
    
        #@functools.wraps(function)
        def decoration(
            *args,
            **kwargs
            ):
            arguments = inspect.getcallargs(function, *args, **kwargs)
            clock     = Clock(name = function.__name__)
            result    = function(*args, **kwargs)
            clock.stop()
    
        return(decoration)
    
    class Clocks(object):
    
        def __init__(
            self
            ):
            self._listOfClocks       = []
            self._defaultReportStyle = "statistics"
    
        def add(
            self,
            clock
            ):
            self._listOfClocks.append(clock)
    
        def report(
            self,
            style = None
            ):
            if style is None:
                style = self._defaultReportStyle
            if self._listOfClocks != []:
                if style == "statistics":
                    # Create a dictionary of clock types with corresponding lists of
                    # times for all instances.
                    dictionaryOfClockTypes = {}
                    # Get the names of all clocks and add them to the dictionary.
                    for clock in self._listOfClocks:
                        dictionaryOfClockTypes[clock.name()] = []
                    # Record the values of all clocks for their respective names in
                    # the dictionary.
                    for clock in self._listOfClocks:
                        dictionaryOfClockTypes[clock.name()].append(clock.time())
                    # Create a report, calculating the average value for each clock
                    # type.
                    string = "clock type".ljust(39) + "mean time (s)"
                    for name, values in dictionaryOfClockTypes.iteritems():
                        string += "\n" +\
                                  str(name).ljust(39) + str(sum(values)/len(values))
                    string += "\n"
                elif style == "full":
                    # Create a report, listing the values of all clocks.
                    string = "clock".ljust(39) + "time (s)"
                    for clock in self._listOfClocks:
                        string += "\n" +\
                                  str(clock.name()).ljust(39) + str(clock.time())
                    string += "\n"
            else:
                string = "no clocks"
            return(string)
    
        def printout(
            self,
            style = None
            ):
            if style is None:
                style = self._defaultReportStyle
            print(self.report(style = style))
    
    _main()
    

# main code example (examples.py):

    
    
    import shijian
    import time
    import inspect
    
    def main():
    
        print("create clock alpha")
        alpha = shijian.Clock(name = "alpha")
        print("clock alpha start time: {time}".format(time = alpha.startTime()))
        print("sleep 2 seconds")
        time.sleep(2)
        print("clock alpha current time (s): {time}".format(time = alpha.time()))
    
        print("\ncreate clock beta")
        beta = shijian.Clock(name = "beta")
        print("clock beta start time: {time}".format(time = beta.startTime()))
        print("clock beta stop time: {time}".format(time = beta.stopTime()))
        print("sleep 2 seconds")
        time.sleep(2)
        print("clock beta current time (s): {time}".format(time = beta.time()))
        print("stop clock beta")
        beta.stop()
        print("clock beta start time: {time}".format(time = beta.startTime()))
        print("clock beta stop time: {time}".format(time = beta.stopTime()))
        print("sleep 2 seconds")
        time.sleep(2)
        print("clock beta start time: {time}".format(time = beta.startTime()))
        print("clock beta stop time: {time}".format(time = beta.stopTime()))
        print("clock beta current time (s): {time}".format(time = beta.time()))
    
        print("\nclock beta printout:\n")
        beta.printout()
    
        print("create two gamma clocks")
        gamma = shijian.Clock(name = "gamma")
        gamma = shijian.Clock(name = "gamma")
        print("sleep 2 seconds")
        time.sleep(2)
    
        print("\ncreate two unnamed clocks")
        delta = shijian.Clock()
        epsilon = shijian.Clock()
        print("sleep 2 seconds")
        time.sleep(2)
    
        print("\nrun function 1 (which is timed using internal clocks)")
        function1()
    
        print("\nrun function 2 (which is timed using a decorator)")
        function2()
    
        print("\nclocks full printout:\n")
        shijian.clocks.printout(style = "full")
    
        print("clocks statistics printout:\n")
        shijian.clocks.printout()
    
    def function1():
        functionName = inspect.stack()[0][3]
        clock = shijian.Clock(name = functionName)
        print("initiate {functionName}".format(functionName = functionName))
        time.sleep(3)
        print("terminate {functionName}".format(functionName = functionName))
        clock.stop()
    
    @shijian.timer
    def function2():
        functionName = inspect.stack()[0][3]
        print("initiate {functionName}".format(functionName = functionName))
        time.sleep(4)
        print("terminate {functionName}".format(functionName = functionName))
    
    if __name__ == '__main__':
        main()
    

# example terminal output:

    
    
    create clock alpha
    clock alpha start time: 2015-01-03T090124Z
    sleep 2 seconds
    clock alpha current time (s): 2.000887
    
    create clock beta
    clock beta start time: 2015-01-03T090126Z
    clock beta stop time: none
    sleep 2 seconds
    clock beta current time (s): 2.002123
    stop clock beta
    clock beta start time: 2015-01-03T090126Z
    clock beta stop time: 2015-01-03T090128Z
    sleep 2 seconds
    clock beta start time: 2015-01-03T090126Z
    clock beta stop time: 2015-01-03T090128Z
    clock beta current time (s): 2.002123
    
    clock beta printout:
    
    clock attribute                        value
    name                                   beta
    time start (s)                         2015-01-03T090126Z
    time stop (s)                          2015-01-03T090128Z
    time elapsed (s)                       2.002123
    
    create two gamma clocks
    sleep 2 seconds
    
    create two unnamed clocks
    sleep 2 seconds
    
    run function 1 (which is timed using internal clocks)
    initiate function1
    terminate function1
    
    run function 2 (which is timed using a decorator)
    initiate function2
    terminate function2
    
    clocks full printout:
    
    clock                                  time (s)
    alpha                                  17.023659
    beta                                   2.002123
    gamma                                  11.018138
    gamma                                  11.018138
    1919f9de-85ce-48c9-b1c8-5164f3a2633e   9.017148
    d24c818c-f4e6-48d0-ad72-f050a5cf86d3   9.017027
    function1                              0.0
    function2                              0.0
    
    clocks statistics printout:
    
    clock type                             mean time (s)
    function1                              0.0
    function2                              0.0
    1919f9de-85ce-48c9-b1c8-5164f3a2633e   9.017283
    beta                                   2.002123
    alpha                                  17.023834
    d24c818c-f4e6-48d0-ad72-f050a5cf86d3   9.017163
    gamma                                  11.0182835
    


Answer: The `Clock` does not get `update`d when it is `stop`ped. The minimal fix is:

    
    
    def stop(self):
        self.update()
        self._updateTime   = None
        self._startTimeTmp = None
        self._stopTime     = datetime.datetime.utcnow()
    

You have three other errors:

  * You should test for `None` by identity (`if foo is not None`) not truthiness (`if foo`), to avoid issues with `False`-y values that aren't `None`;
  * `shijian.timer` doesn't `return result`, so although the timing will work you'll break any code that expects a return from the decorated function; and
  * If you want the code to work in Python 2 and 3, you can't use `dict.iteritems`, which doesn't exist in the latter. If you only want it to work in Python 2, either `from __future__ import print_function` or use `print whatever` rather than `print(whatever)`.

Additionally, your code is not at all compliant with [the style
guide](https://www.python.org/dev/peps/pep-0008/) (or, worse, even internally
consistent - compare the definition of `Clock.start` with that of
`Clock.report`, for example).

There is also room for improvement in the design and functionality (e.g.
`Clock.name` could be a `@property`, and I would separate the table printing
from the generation of results). You should consider submitting your code for
[Code Review](http://codereview.stackexchange.com/), once you have:

  * completed;
  * tested; and 
  * style-guide-complianced it 

(you might find using [`pylint`](http://www.pylint.org/) helpful for the
latter).

Finally, I assume you're doing this for learning purposes rather than because
you need the functionality, as Python [has its own
profilers](https://docs.python.org/2/library/profile.html).

