Good day,
I have a suspicion that time() decorator is not thread-safe in some way. Consider the following code:
from prometheus_client import start_http_server, Summary
import sys
import time
from concurrent.futures import ThreadPoolExecutor
from timeit import default_timer
S_TIME = Summary("timing_with_time", "Time spent processing request")
S_MANUAL = Summary("timing_manually", "Time spent processing request")
@S_TIME.time()
def process_request():
"""A dummy function that takes some time."""
start = default_timer()
time.sleep(1)
S_MANUAL.observe(max(default_timer() - start, 0))
if __name__ == "__main__":
start_http_server(8000)
threads = int(sys.argv[1])
pool = ThreadPoolExecutor(max_workers=threads)
for i in range(1000):
pool.submit(process_request)
Running it as python bug.py 1 produce the following metrics:
timing_with_time_count 12.0
timing_with_time_sum 12.013219268759713
timing_manually_count 12.0
timing_manually_sum 12.012461822945625
I.e. both _sum values are similar as expected. However if I increase the concurrency, then the metric that is
tracked with time() does NOT have its _sum increasing:
With python bug.py 2:
timing_with_time_count 10.0
timing_with_time_sum 5.004416585084982
timing_manually_count 10.0
timing_manually_sum 10.009211090975441
I.e. the count matches, but the sum of the first one is wrong! I did 10 requests each 1 second long, not 0.5 second long. The problem scales linearly. E.g. with python bug.py 10:
timing_with_time_count 60.0
timing_with_time_sum 6.0030247694812715
timing_manually_count 60.0
timing_manually_sum 60.06247438094579
I.e. _sum metric measured with time() decorator always thinks it's single threaded.
Python 3.6.5 on ubuntu 16.04 64-bit, P8s client version 0.2.0 (also happens with 0.1.1)
Good day,
I have a suspicion that time() decorator is not thread-safe in some way. Consider the following code:
Running it as
python bug.py 1produce the following metrics:I.e. both _sum values are similar as expected. However if I increase the concurrency, then the metric that is
tracked with
time()does NOT have its _sum increasing:With
python bug.py 2:I.e. the count matches, but the sum of the first one is wrong! I did 10 requests each 1 second long, not 0.5 second long. The problem scales linearly. E.g. with
python bug.py 10:I.e. _sum metric measured with
time()decorator always thinks it's single threaded.Python 3.6.5 on ubuntu 16.04 64-bit, P8s client version 0.2.0 (also happens with 0.1.1)