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