Python3 threading.Event().wait time is twice as large as Python27 #85471
Comments
|
The overhead in Python 3 for threading.Event().wait() is much larger than Python 2. I am trying to run a script at 60hz which worked correctly in Python2 but does not in Python 3. Here is a minimal example to demonstrate: #!/usr/bin/env python import threading
import time
def sample_thread(stop_ev):
while not stop_ev.is_set():
t2 = time.time()
stop_ev.wait(0.016999959945)
print((time.time() - t2))
def main():
stop_ev = threading.Event()
sample_t = threading.Thread(target=sample_thread, args=(stop_ev, ))
sample_t.start()
# Other stuff here, sleep is just dummy
time.sleep(14)
stop_ev.set()
print('End reached.')
if __name__ == '__main__':
main()Python 2.7.0 consistently prints : 0.0169999599457 Python 3.8.2 waits much longer 0.031026363372802734 |
SD
mannequin
added
3.8
|
Please provide the results of running the following with the two pythons you are using: python -m test.pythoninfo For what it's worth, running on macOS 10.15.5, I see a slight difference with more variability in the Python 3 results but nothing as pronounced as what you see. Also the Python 3 results were very similar across recent versions of 3.7.x, 3.8.x, and pre-release 3.9. $ /usr/local/bin/python2.7 ~/test_41299.py | sort
0.017021894455
0.0170249938965
0.017028093338
0.017028093338
0.0170290470123
0.0170290470123
0.0170290470123
0.0170300006866
0.017030954361
0.0170311927795
[...]
0.0190448760986
0.0190479755402
0.0190498828888
0.0190510749817
0.0190589427948
0.019061088562
0.0190629959106
0.019079208374
0.0190861225128
0.0190970897675
End reached.0.0158078670502
$ /usr/local/bin/python3.8 ~/test_41299.py | sort
0.009722232818603516
0.017028093338012695
0.017033100128173828
0.017034053802490234
0.017034053802490234
0.017035961151123047
0.017037153244018555
0.017037153244018555
0.01703786849975586
0.017038822174072266
[...]
0.021351099014282227
0.021355152130126953
0.021355152130126953
0.02135610580444336
0.021361112594604492
0.021363258361816406
0.02136397361755371
0.021379947662353516
0.02138543128967285
0.021442890167236328
End reached. |
|
I reproduced something similar on Python 3.9.0b1, Windows 64-bit version: NUMBER Mean +- std dev On the smaller scale, it looks quantized to multiples of ~15ms (?), but then it gets more accurate as the times get larger. I don't think it's a measurement error since the first measurement manages microseconds. Perhaps this is just an OS-level thread-scheduling issue? |
|
I have tested this both on vs code terminal and cygwin for windows. 3.8.2 : python -m test.pythoninfo Py_DEBUG: No (sys.gettotalrefcount() missing) 2.7.18 : python -m test.pythoninfo Py_DEBUG: No (sys.gettotalrefcount() missing) |
|
Thanks for the version info. Windows and/or threading experts: any ideas? |
|
At a guess, it's probably the signal emulation (a.k.a. Ctrl+C support). We could save some time by checking the requested handle first without blocking, and only beginning the blocking call if it's not available. |
NT's default system timer resolution for thread dispatching is 15.625 ms. If a wait is for 17 ms, expect to see actual wait times mostly in the range 17 ms up to 31.25 ms. A few outliers may wait longer because the due time on the kernel wait is when the thread is ready to be dispatched, but other threads may preempt it. The system timer resolution can be increased to about 1 ms (or 500 us with the undocumented NtSetSystemTime system call). But stricter timing still requires combining a dispatcher wait for long course-grained waits with a performance-counter busy wait for short precise waits. --- But something else is also involved here. I lowered the system timer resolution to 1 ms, and this allowed time.sleep(0.017) to wait for 17-18 ms in about 95% of cases. But the wait for acquiring a _thread.lock stubbornly refused to cooperate. Ultimately it's just calling WaitForSingleObjectEx on a semaphore, so I used ctypes to make a simple alternative lock via CreateSemaphoreW, ReleaseSemaphore, and WaitForSingleObject. This simple implementation performed exactly like the time.sleep wait with regard to the system timer resolution, so the difference is in the _thread.lock wait. I traced it to the following code in EnterNonRecursiveMutex in Python/thread_nt.h: /* wait at least until the target */
ULONGLONG now, target = GetTickCount64() + milliseconds;
while (mutex->locked) {
if (PyCOND_TIMEDWAIT(&mutex->cv, &mutex->cs, (long long)milliseconds*1000) < 0) {
result = WAIT_FAILED;
break;
}
now = GetTickCount64();
if (target <= now)
break;
milliseconds = (DWORD)(target-now);
}GetTickCount64 is documented to be "limited to the resolution of the system timer", but what they don't say is that changing the resolution of the system timer has no effect on the minimum increment of the tick count. It still increments by 15-16 ms even if the system timer resolution is set to 1 ms. OTOH, the value of QueryInterruptTime 1 and QueryUnbiasedInterruptTime 2 is incremented with the timer interrupt. The biased version 1 is preferred for long waits that may straddle a system sleep or hibernate, but it's only available in Windows 10. I patched EnterNonRecursiveMutex to call QueryInterruptTime instead of GetTickCount64, and this did enable increased precision when waiting on a lock. For example (patched behavior): >>> lock = _thread.allocate_lock()
>>> lock.acquire()
True
>>> setup = 'from __main__ import lock'
>>> stmt = 'lock.acquire(True, 0.017)'15.625 ms system timer: >>> timeit.timeit(stmt, setup, number=1000)
30.1737135999999851 ms system timer: >>> with set_timer_resolution(0.001):
... timeit.timeit(stmt, setup, number=1000)
...
17.66828049999998That said, increasing the timer resolution is discouraged in most cases, so we may simply document that lock waits are limited to the default system timer resolution of 15.625 ms, and increasing the system timer resolution has no effect on this limit. --- Note that this is unrelated to cancel support via Ctrl+C. Windows Python has no support for canceling a wait on a _thread.lock. It's just a single-object wait in _PyCOND_WAIT_MS, not a multiple-object wait that we set up to include the SIGINT event when called on the main thread (or a variant that I like, which queues a user APC to the main thread for SIGINT instead of using an event, and switches to using alertable waits with SleepEx, WaitForSingleObjectEx, and without needing a wait slot in WaitForMultipleObjectsEx). It's possible to implement a Ctrl+C cancel as long as the lock implementation waits on a kernel semaphore object. However, some effort has gone into developing a different implementation based on condition variables and SRW locks. I don't know whether there's a way to cancel SleepConditionVariableSRW, or whether maybe a different implementation could be used for _thread.lock instead of sharing an implementation with the GIL. |
Umm... that should be NtSetTimerResolution. ;-) |
|
So there is no advised way around this then. I am currently using time.sleep() to hit my 60hz. |
Changing the implementation of EnterNonRecursiveMutex() to use WinAPI QueryInterruptTime() instead of GetTickCount64() would allow increasing the wait precision by setting the system timer resolution to the minimum supported period via timeBeginPeriod() [1]. It seems reasonable to at least support doing this. That said, changing the system timer resolution shouldn't be encouraged since it affects the entire system and can increase power consumption. If you have results in 2.7 similar what's shown in msg373660, check clockres in a separate terminal to see the current timer interval [2]. --- |
|
I just ran into this. GetTickCount64() is a bad choice even without improving the Windows timer resolution, as every mutex wait will have 16ms of jitter. Here are some lock.acquire(timeout=0.001) times measured with time.perf_counter(): elapsed=21.215ms
elapsed=30.960ms
elapsed=21.686ms
elapsed=30.998ms
elapsed=30.794msHere's the same lock.acquire(timeout=0.001) with CPython patched to use QueryPerformanceCounter() instead of GetTickCount64(). Notice this is less overhead than even the original post's Python 2.x times. elapsed=9.554ms
elapsed=14.516ms
elapsed=13.985ms
elapsed=13.434ms
elapsed=13.724msHere's the QueryPerformanceCounter() test in a timeBeginPeriod(1) block: elapsed=1.135ms
elapsed=1.204ms
elapsed=1.189ms
elapsed=1.052ms
elapsed=1.052msI'd like to submit a PR to fix the underlying issue by switching to QueryPerformanceCounter() in EnterNonRecursiveMutex(). QueryInterruptTime() is a bad candidate because it's only supported on Windows 10, and CPython still supports Windows 8. Improvements based on QueryPerformanceCounter() can be backported to at least 3.8 (3.8 dropped Windows XP support, which was the last Windows version where QueryPerformanceCounter() could fail). I checked and the only other use of GetTickCount64() seems to be in time.monotonic(). Honestly I would vote to change time.monotonic() to QueryPerformanceCounter() as well, as QueryPerformanceCounter() can no longer fail on any Windows newer than XP (which is no longer supported by Python), but that's probably a topic for a new BPO. |
lunixbochs
mannequin
added
3.9
lunixbochs
mannequin
added
3.9
|
Ok, I filed a PR for this. I used pytime's interface to avoid duplicating the QueryPerformanceFrequency() code. I found a StackOverflow answer that says QueryPerformance functions will only fail if you pass in an unaligned pointer: https://stackoverflow.com/a/27258700 Per that, I used Py_FatalError to catch this case, as there is probably something wrong with the compiler at that point, and the other recovery options would be likely to result in incorrect program behavior (e.g. dead lock). |
|
Change looks good. 3.8 is security fixes only at this stage, but it can go back to 3.9 |
|
I suggest to remove the (now <= 0) check. _PyTime_t now = _PyTime_GetPerfCounter();
if (now <= 0) {
Py_FatalError("_PyTime_GetPerfCounter() == 0");
}Please don't add such Py_FatalError() in the middle of a function. If this case happens, it means that Python immediately exits and creates a debug report (ex: coredump on Unix, popup on Windows asking to open a debugger), and worse: it exits the process immediately. I'm not aware of anyone reporting that _PyTime_GetPerfCounter() returns 0. Do you fear that the clock is broken and *always* report 0? If yes, please add at check when Python starts. But why do you think that it could happen? |
|
I agree with not throwing fatal errors, but that check is unlikely to actually be hit, and you removed the startup checks covering the underlying clocks here: ae6cd7c I think if the time source is broken, a user would probably prefer an exception or fatal error to the deadlock they will otherwise get (as time not advancing means it's impossible to timeout), so it doesn't make sense to remove the check without doing something else about it. There are three places win_perf_counter_frequency() can fail: Line 974 in bb3e0c2 I mention the QueryPerformanceFrequency error case here (stack misalignment): https://bugs.python.org/issue41299#msg395237 The other option, besides startup checks, would be to better parameterize the timer used (mentioned in bpo-44328): Prefer QueryUnbiasedInterruptTimePrecise if available (Win 10+ via GetProcAddress), then QPC, then QueryUnbiasedInterruptTime (which has the original bug wrt jitter but should never be used as QPC is unlikely to be broken). |
|
Perhaps the simplest initial fix would be to move that check down to PyThread__init_thread() in the same file. I'm not sure what the cpython convention for that kind of init error is, would it just be the same Py_FatalError block or is there a better pattern? |
|
I'm fine with adding _PyTime_Init() again, and maybe only implement checks on Windows. On Linux, I only saw a single failure in _PyTime_Init() once, when Python was run in a sandbox, and the time syscalls were not allowed. It was a corner case about the new 64-bit time_t syscalls on a 32-bit system (container): |
Do you think that pytime.c has the bug? I don't think so.
In theory yes, in practice we got zero error reports. So it sounds like it cannot happen. I don't think that it's a good pratice to start to add checks in all functions using a clock "just in case" the clock might fail. |
No, a misaligned stack would be an issue in the caller or compiler, not pytime.c. I have hit misaligned stack in practice, but it should be rare enough to check on init only.
My read is that as long as we're not confident enough to remove those checks from pytime.c, a caller should assume they're reachable. If the pytime checks need to stay, adding a Windows only pytime init check to make sure that locks won't deadlock sounds fine to me. |
If you consider that the risk is non-zero, you can add a check at startup. Do you expect that a startup check is enough, or do you expect failures later? I understood that if the first call succeed, later calls are very unlikely to fail. The first call should be enough to check for all possible errors. |
|
I created PR bpo-28548 to remove the Py_FatalError() code path. |
|
Calling Py_FatalError() must be avoided by any mean. I spent significant time to remove Py_FatalError() at Python startup in my PEP-587 implementation: https://www.python.org/dev/peps/pep-0587/ I also removed Py_FatalError() calls to report errors to the caller: https://bugs.python.org/issue38631 Calling Py_FatalError() is really bad when Python is embedded in an application. It kills the whole process, the caller has no way to catch the error. |
|
I close the issue.
I don't think that it's worth it to backport this change to 3.9 and 3.10. In practice, Py_FatalError() will never be called, and _PyTime_GetMonotonicClock() result must always be greater than 0. But I wanted to remove it in the main branch to reduce the number of functions calling Py_FatalError(). |
Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.
Show more details
GitHub fields:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: