Hi,
While trying to make a simple test to measure the time of specially fast functions.
I’ve realized that if I execute another call before executing the time measurement like time.sleep(0.01) or print(1) , the test would take more time than if nothing called before.
Here is a simple code to reproduce what I am referring to:
import sys
import time
def product_times_10(num) -> int:
return 10 * num
def measure_time(func, args) -> int:
t0 = time.perf_counter_ns()
func(*args)
return time.perf_counter_ns() - t0
def main_time():
test_func = product_times_10
test_args = (10,)
loops = 25
initial_call = measure_time(test_func, test_args)
call_without_break_ns = []
call_with_break_time_sleep_ns = []
for _ in range(loops):
call_without_break_ns.append(measure_time(test_func, test_args))
for _ in range(loops):
time.sleep(0.01)
call_with_break_time_sleep_ns.append(measure_time(test_func, test_args))
print(time.get_clock_info("perf_counter"))
print(sys.version_info)
print(f"{initial_call=},")
print(f"{call_without_break_ns=},")
print(f"{call_with_break_time_sleep_ns=}.")
if __name__ == "__main__":
main_time()
The code above causes the following output.
namespace(implementation='QueryPerformanceCounter()', monotonic=True, adjustable=False, resolution=1e-07)
sys.version_info(major=3, minor=12, micro=4, releaselevel='final', serial=0)
initial_call=2800,
call_without_break_ns=[800, 300, 200, 300, 200, 200, 300, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 100, 200, 200, 200, 200, 200, 200, 200],
call_with_break_time_sleep_ns=[900, 800, 2900, 2900, 2900, 4700, 4800, 4700, 4900, 9900, 5800, 5500, 8000, 3700, 4100, 2900, 3200, 3000, 3000, 4800, 9700, 5400, 5400, 5600, 5300].
I am ruunining on Windows 11 with python3.12, but I see same behavior on other versions 3.11, 3.10, 3.9, 3.8;
Also I tested on an old Raspberrypi with python 3.7 and observed the same behavior.
Question
I think I may be making an obvious error, here but I am unable to see it,
Could someone point out my mistake? explain please, Why this discrepancy exists?
Additional Info
What else I have tried:
- I have replaced the time.sleep() with a custom_sleep() function:
this helps, it make the difference between “with_break” and “without_break” loops shorter, but there is still an noticable differencedef custom_sleep(sleep_time: float) -> None: t0: int = time.perf_counter_ns() timeout: float = sleep_time * 1000_000_000 while time.perf_counter_ns() - t0 < timeout: pass - I have also replaced the time.sleep with other “simple” functions line
printor alambda x: x**x, the lambda function does not affect the measurements, but theprintfunction also affect the measurements. - I have tried to disable the garbage collector during the test, but this make no difference in the results.
- I have also tried using other counters (monotonic,process_time), but the resolution wasn’t enough to measure these calls.
Here I have a bit more complex code were I am testing all the mentioned scenarios:
import statistics
import sys
import time
def product_times_10(num) -> int:
return 10 * num
def custom_sleep(sleep_time: float) -> None:
t0: int = time.perf_counter_ns()
timeout: float = sleep_time * 1000_000_000
while time.perf_counter_ns() - t0 < timeout:
pass
GET_TIME_CLOCK = "perf_counter"
get_time_ns = time.perf_counter_ns
# sleep = custom_sleep
sleep = time.sleep
def measure_time(func, args) -> int:
t0 = get_time_ns()
func(*args)
return get_time_ns() - t0
def measure_time_with_brake(func, args):
sleep(0.01)
return measure_time(func=func, args=args)
def loop_func(func, args, loops):
return [measure_time(func=func, args=args) for _ in range(loops)]
def loop_func_with_break(func, args, loops):
return [measure_time_with_brake(func=func, args=args) for _ in range(loops)]
def print_py_info():
print(f"clock info for {GET_TIME_CLOCK}")
print(time.get_clock_info(GET_TIME_CLOCK))
print(sys.version_info)
def main_time():
global sleep
test_func = product_times_10
test_args = (10,)
loops = 25
initial_call = measure_time(test_func, test_args)
call_without_break = loop_func(test_func, test_args, loops=loops)
sleep = lambda x: x**x
call_with_break_lambda = loop_func_with_break(test_func, test_args, loops=loops)
sleep = custom_sleep
call_with_break_custom_sleep = loop_func_with_break(test_func, test_args, loops=loops)
sleep = print
call_with_break_print = loop_func_with_break(test_func, test_args, loops=loops)
sleep = time.sleep
call_with_break_time_sleep = loop_func_with_break(test_func, test_args, loops=loops)
print_py_info()
print(f"{initial_call=},")
print(f"{call_without_break=},")
mean_call_without_break = statistics.mean(call_without_break)
print(f"{call_with_break_lambda=}.")
print(f"{mean_call_without_break=}.")
mean_call_with_break_lambda = statistics.mean(call_with_break_lambda)
print(f"{mean_call_with_break_lambda=}")
print(f"{call_with_break_custom_sleep=}.")
mean_call_with_break_custom_sleep = statistics.mean(call_with_break_custom_sleep)
print(f"{mean_call_with_break_custom_sleep=}")
print(f"{call_with_break_print=}.")
mean_call_with_break_print = statistics.mean(call_with_break_print)
print(f"{mean_call_with_break_print=}")
print(f"{call_with_break_time_sleep=}.")
mean_call_with_break_time_sleep = statistics.mean(call_with_break_time_sleep)
print(f"{mean_call_with_break_time_sleep=}")
if __name__ == "__main__":
main_time()
output of above code:
0.01
...
0.01
clock info for perf_counter
namespace(implementation='QueryPerformanceCounter()', monotonic=True, adjustable=False, resolution=1e-07)
sys.version_info(major=3, minor=12, micro=4, releaselevel='final', serial=0)
initial_call=3200,
call_without_break=[400, 200, 200, 200, 200, 200, 200, 200, 100, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200],
call_with_break_lambda=[200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 200, 100, 200, 100, 200, 200, 200].
mean_call_without_break=204.
mean_call_with_break_lambda=192
call_with_break_custom_sleep=[600, 1200, 500, 1300, 700, 1100, 1100, 500, 500, 300, 500, 500, 300, 400, 500, 200, 500, 900, 300, 500, 300, 500, 500, 200, 400].
mean_call_with_break_custom_sleep=572
call_with_break_print=[1100, 900, 1000, 800, 1400, 700, 800, 900, 700, 900, 1100, 900, 900, 800, 700, 700, 900, 800, 900, 800, 1100, 1000, 700, 1000, 1100].
mean_call_with_break_print=904
call_with_break_time_sleep=[2400, 3000, 2300, 2200, 2500, 2000, 2600, 2300, 2600, 3900, 3600, 4100, 8500, 5300, 5600, 5300, 5700, 5800, 5400, 5600, 5700, 5600, 6000, 5500, 5600].
mean_call_with_break_time_sleep=4364
