TimeService rapidly falls behind actual time.

[greg-barnett]

TimeService falls behind actual time by about half a second every second. It is supposed to reset every 10 minutes, but doesn't.

More details and a fix are available at:
greg-barnett@de0cc62

[asvetlov]

Hmm.
On what load you've got 50% accuracy?
I suspect it's possible only on overwhelmed event loop (or code with long blocking synchronous calls).
Also what problem it produces?
Time service is used for measuring relative slow timeouts for things like automatic socket disconnection etc. If socket will be disconnected a little later -- no problem at all!

[greg-barnett]

TimeService falling behind is not load dependent.

loop_time() (which is what I'm guessing is used for timeouts) will never fall behind by more than about 1 second.

time() and strtime() will fall behind, no matter what the load is. strtime() falling behind causes Date headers in responses to be incorrect (this is how I discovered this).

See https://gist.github.com/greg-barnett/00b67d3b098bc782db642b068ad4b0d3 for a test script, and output from the master branch and my bugfix.

[socketpair]

Sorry, it's not documented why we have TimeService either. Why not to use just time.time() ?

[asvetlov]

It is implementation detail, not part of public API.
The main idea is: formatting time for Date HTTP header is expensive operation, it might take longer than preparing and sending response.

But the header has 1 second accuracy. We could amortize formatting time by caching a string for 1 second.

[asvetlov]

Sorry, I did mislead: time service is never used for timeout calculations but for datatime formatting only.

[socketpair]

So, caching may be implemented MUCH easier. Why not ?

_cached_time = None
_cached_time_formatted = None
def format_current_datetime():
    global _cached_time
    global _cached_time_formatted
    now = int(time.time())
    if now != _cached_time:
        _cached_time_formatted = some_format(now)
    return _cached_time_formatted

[fafhrd91]

+1

[greg-barnett]

TimeService is also used in _process_keepalive in RequestHandler, but that should be replaceable with a call to loop.time()

[greg-barnett]

This commit has a version of TimeService that only caches the formatted string for use in Date headers.
greg-barnett@eef354e

[fafhrd91]

if we make decision to simplify TimeService, then it should be removed at all.

[greg-barnett]

This commit has slightly cleaner/faster formatting
greg-barnett@51e793d

I agree that getting rid of TimeService completely probably makes sense, but I don't know the codebase well enough to know where the functionality should reside. I don't want to add global variables if it can be avoided.

[greg-barnett]

Doing some more benchmarking, I'm not even convinced that caching is required.

import time
import timeit
timeit.timeit("time.strftime('%a, %d %b %Y %H:%M:%S GMT', time.gmtime())", number=10000)
0.016672083060257137

[fafhrd91]

it is, 5-7% cpu

[greg-barnett]

@fafhrd91 do you have any benchmarking code that shows TimeService's caching of formatted date makes any significant performance difference? I have not been able to replicate any conditions where it has a noticeable impact.

[fafhrd91]

I don't have benchmarks now, but I did a lot of benchmarking when worked on performance.

[greg-barnett]

#2182
Meant to associate pull request with this issue.

[asvetlov]

I hope the problem is fixed in 2.3
@greg-barnett @socketpair can we close the issue?

[greg-barnett]

I'm currently on medical leave and can't devote any time to verifying the fix, so I will defer to @socketpair regarding closing this issue.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a [new issue] for related bugs.
If you feel like there's important points made in this discussion, please include those exceprts into that [new issue].
[new issue]: https://github.com/aio-libs/aiohttp/issues/new