Negative min_response_time shown in stats

[max-rocket-internet]

Describe the bug

Negative value shown for min_response_time:

Expected behavior

0 or positive value.

Actual behavior

Negative value shown for min_response_time

Steps to reproduce

I have a branch local docker-compose setup to reproduce it easily. But it's just 1 worker calling nginx in another docker container.

Environment

• OS: Docker
• Python version: -
• Locust version: current master

[max-rocket-internet]

This line is returning a negative value:

locust/locust/clients.py

Line 117 in b18cf1e

request_meta["response_time"] = (time.time() - request_meta["start_time"]) * 1000

Perhaps a docker clock source issue 🤔

Docker itself just using the host clock source but docker on Mac (what I'm using) uses HyperKit VM as Mac kernel doesn't support native docker. Perhaps this VM clock source is not reliable?

[max-rocket-internet]

There's lots of docker clock issues but as far as I can see they are related to sleep: moby/hyperkit#110

If it was a docker issue, it would be easy to reproduce outside of locust with a file like this:

import time

while True:
    t = time.time()
    if time.time() < t:
        print('ERROR: {0} is less than {1}'.format(time.time(), t))
        break

And then run it like docker run -v $PWD:/mnt python:latest python /mnt/time_test.py

[max-rocket-internet]

Ah, after leaving this for a while I get an error 😅

ERROR: 1595435189.4236984 is less than 1595435189.4583442

OK, good to know!

[max-rocket-internet]

Should we make a change to the locust code though? Like to record the response time as 0 in this case?

[cyberw]

Can you try replacing the two calls to time.time() with time.monotonic()?

I thought we did that a long time ago, but maybe it was only done for FastHttpUser or something.

[heyman]

Interesting.

Should we make a change to the locust code though? Like to record the response time as 0 in this case?

I don't think we should "hide" the clock issue by setting it to zero if it's negative.

[max-rocket-internet]

I don't think we should "hide" the clock issue by setting it to zero if it's negative.

Makes sense

Can you try replacing the two calls to time.time() with time.monotonic()?

This solves it for me. Both in docker without locust and in my locust test.

Shall I make a PR to switch any time measurement to use time.monotonic()? We should probably be using this anyway as even without docker the main clock on any host can go backwards (with NTP, chrony etc) anyway

[cyberw]

Please do!

[max-rocket-internet]

Done: #1492