Profiling of objects in Python 3

mogh

@a_block Sorry for my ignorance, I had no output before just errors and then I didn't check old time.clock() anymore so I thought time.clock() does not work at all.

The numbers I get with the new time.process_time() are strange and every other is 0.

anyway got it working with the old time.clock()

this works for now, but a error free console would be nice in the future ...
or perhaps I can get my head around that decorator profilling from zipit ...
still a little to much for me.

If somebody feels generous perhaps post a decorator version of

import cProfile, math, pstats, c4d

def some_function():
    profile = cProfile.Profile()

    # Start of profiling
    profile.enable()
    data = [math.sqrt(abs(math.sin(i * .001) * math.cos(i * .001)))
            for i in range(100000)]
    profile.disable()
    # End of profiling

    stats = pstats.Stats(profile)
    stats.strip_dirs()
    stats.sort_stats("cumtime")
    stats.print_stats()

if __name__ == "__main__":
    c4d.CallCommand(13957) # Konsole löschen / delete console log
    some_function()

anyway thanks

a_block

???
So, what are the errors?
I have none...

ferdinand

Hi,

your code is not faulty, at least not in a strict sense. The problem is that you did choose time.time() for the profiling, which is not a reliable tick source in any version of Python. You can use it if you are only interested in timings above the 100 ms mark. For everything else you should cProfile. The code below demonstrates the difference and also goes a bit into the details. The bottom line is (at least from my point of view) that you cannot do what you want to do in any language, especially on Windows.

You might have to run the code a few times, because unreliability also means that it can work when you don't want it to ;).

Cheers,
Ferdinand

#!py3

"""Simple example for a profiling decorator.

Okay, here are three problems at play.

    1. The accuracy of the high precision system clock depends on the OS,
       with Windows usually being said to be substantially worse than
       MacOS and Linux (this ranking should be taken with a grain of salt).
    2. time.time() is not very precise in general, it has been considered
       for depreciation in 3.X but still "lingers" for some reason unknown
       to me.
    3. Meaningful profiling, i.e. the measuring of timings, is in general a
       complicated thing, when it goes below the 10-20 ms mark. This is not
       just a Python thing, but basically applies to anything that runs on
       a complex OS.

Technical Solutions:

time.time() is in general a bad choice for timings unless you want to 
measure timings in the smaller than 100 ms range.

There are some "tips" out there which recommend to use something like 
time.perf_counter_ns() or time.process_time() instead. Which does not make
much sense to me since these are the clocks time.time() is choosing from
when looking for the most accurate system clock. The same thing does IMHO
apply to the recommendation of using DateTime instead of time.

The only reasonable way to measure timings in the smaller than 100 ms range
are Python's profiling libraries, e.g. cProfile I did use above. But note,
that also cProfile only grantees accuracy in the bigger than 100 ms range.

Script & Stuff:

The script below demonstrates, that using time.time() will sometimes return
faulty timings of zero seconds, while cProfile won't do that. You might have
to run the script multiple times to get such failure case, because the 
one-at-a-time accuracy of time.time() depends on many factors.

The most reasonable thing to do here, is to move your profiling "up one 
level", i.e. do not measure a single call, but rather the loop in your code.
This will have obviously have the same absolute error, but a much more
reasonable relative error.

About the "100 ms": From experience this seems to be a very conservative
figure on modern Windows machines, you can actually expect ~25-50 ms.   
"""

import cProfile
import pstats
import time

def profile(func):
    """A simple profiling decorator.
    """
    profiler = cProfile.Profile()

    def wrapper(*args, **kwargs):
        result = None
        try:
            result = profiler.runcall(func, *args, **kwargs)
        except Exception as error:
            raise error
        finally:
            stats = pstats.Stats(profiler)
            # To get the full profile do this.
            # stats.strip_dirs().print_stats()
            t = round(stats.total_tt, 3)
            print (f"{func.__name__} took {t} sec.")
        return result
    return wrapper

def timing(func):
    """A time.time() based decorator for timings.

    !SHOULD NOT BE USED!
    """
    def wrapper(*args, **kwargs):
        try:
            t = time.time()
            result = func(*args, **kwargs)
            t = round((time.time() - t), 3)
        except Exception as error:
            raise error
        finally:
            print (f"{func.__name__} took {t} sec.")
        return result
    return wrapper

@profile
def foo_profile():
    """
    """
    [1/3333 for _ in range(100000)]


@timing
def foo_time():
    """
    """
    [1/3333 for _ in range(100000)]


def main():
    """
    """
    # Take 10 rounds with each decorator.
    for _ in range(10):
        foo_profile()
    for _ in range(10):
        foo_time()


if __name__ == "__main__":
    main()

ferdinand

What I forgot to mention is, that time.time(), only guarantees a precision of greater or equal to 1 sec. The 100 ms figure I do mention, only applies to the high precision clocks it might or might not be able to poll. Which should always happen on Windows/MacOs, but just to be clear about the precsion of time.time().

Cheers,
Ferdinand

mogh

thank you both @a_block for enduring my beginner questions and zipit always keeping it precise and clean ,,,

I managed to get an old script to run 20 times faster by just finding junk I was able to cleanup ! Even though as a beginner I sometimes do not know what I am doing this profiling helps to find stupid code!

so few more scripts to cleanup.