Conversation
|
With this PR all backends produce 7 events for this script: |
|
I added tests and they all pass locally for me, but I can't seem to get things working on the CI runners, so I'm going to put some thoughts/notes down here. I'm wondering if there are issues with trying to assert against timing on shared resources? Thinking it was just trying to run things too fast on limited resources, I increased the timer interval to 500ms and that didn't seem to help. Currently, I am asserting against the expected number of calls, is there possibly a delay involved in first timer spin-up so I should be asserting against the final timer interval somehow instead? If anyone has ideas for better tests here let me know. |
8596fb6 to
7f40ba5
Compare
|
Since this is only failing on 3.13 (on macOS at least), one possibly suspicious change is in
But I thought you had used |
|
I can reproduce the failure on AppVeyor locally (Expected 8, got 5); given #28647 (comment), I think that means it is re-evaluating the timeout after the slow callback and not attempting to create a consistent time. |
|
That is actually a different failure than the one we are seeing here of course 😂 https://github.com/matplotlib/matplotlib/actions/runs/11688137387/job/32547874573?pr=29062#step:15:200 These tests on CI systems seem flakey because I had a job right before this push where all the tests passed. I think this gets to the comment you left about system resources and scheduling because sometimes QT is the one failing in CI, others it is GTK. We are running pytest with as many processors as possible Running locally with this script: import time
import matplotlib.pyplot as plt
fig = plt.figure()
last_time = orig_time = time.perf_counter()
x = 0
def on_timer():
global x
global last_time
t = time.perf_counter()
print(f"{x:02d}: {t - last_time:.3f} ({t - orig_time:.3f})")
last_time = t
if x == 0:
time.sleep(0.5)
else:
time.sleep(0.1)
x += 1
timer = fig.canvas.new_timer(interval=150)
timer.add_callback(on_timer)
timer.start()
fig.canvas.start_event_loop(3)GTK has an ~8ms drift associated with it, whereas all the other backends hit within ~1ms. |
|
It looks like GTK has no plans on changing this: https://gitlab.gnome.org/GNOME/glib/-/issues/503 |
7f40ba5 to
8bc2e95
Compare
8bc2e95 to
54e07ed
Compare
54e07ed to
1affa9e
Compare
|
Rebased and pushed again. All tests passing locally, going to see how this does on CI now... |
1affa9e to
6842ed2
Compare
| // we shouldn't do it ourselves when the object is deleted. | ||
| self->timer = NULL; | ||
| } | ||
| self->timer = [NSTimer scheduledTimerWithTimeInterval: interval |
There was a problem hiding this comment.
While I realize that this is an old PR, I'm going through all of the old issues and pull requests tagged with as Apple/macOS.
+scheduledTimerWithTimeInterval:… does the following:
CFRunLoopAddTimer(CFRunLoopGetCurrent(), timer, NSDefaultRunLoopMode));CFRunLoopGetCurrent() will create a run loop for the current thread if one does not already exist. I'm not sure if this is the behavior that you want if this is called on a background thread created from Python.
That said, in the case of a background thread, the previous behavior of calling -addTimer:forMode: on the main thread is also technically wrong - NSRunLoop is marked as a thread-unsafe class. It works, but only because CFRunLoopAddTimer() is currently implemented to take out a pthread mutex.
I think the right behavior is to dispatch_async() over to the main queue and then add the timer from there.
There was a problem hiding this comment.
🤔 I have went through and removed the dispatch_async() updates I had previously and this is now more minimal and focused on just getting the timing/functionality consistent. I think we should defer the better macos timer implementation to your PRs rather than try to fit that into this one.
There was a problem hiding this comment.
Would it be easiest to ignore the macosx backend in this PR since everything is changing and then we can go back and patch it up once the dust settles?
The new macos timer implementation has been specifically written with this PR in mind.
There was a problem hiding this comment.
Potentially. Look at the new updates though because they are very minimal and just add an update() method and rearrange the call order. The tests will be the important part that will need to pass for the new branch too.
I'm fine rebasing this if your PR goes in first. This has been open for 2 years now, so I don't anticipate it getting in soon at all :)
There was a problem hiding this comment.
I see that now - I was looking at the old files still. In any case: this is going to be a high priority in my review queue!
| repeats: !single | ||
| block: ^(NSTimer *timer) { | ||
| dispatch_async(dispatch_get_main_queue(), ^{ | ||
| gil_call_method((PyObject*)self, "_on_timer"); |
There was a problem hiding this comment.
This is a rare crash.
- The timer fires and queues up a block onto the main dispatch queue. This will execute the block on the next run loop cycle.
Timer_deallocgets called on this runloop cycle. While the timer is invalidated, it has has already fired and we have "lost track" of the queued block.- The queued block runs and tries to use a de-allocated
self.
There was a problem hiding this comment.
Note: I ended up implementing an Objective-C class that mimics the behavior of a QTimer - changing the interval of a running timer will restart, singleShot is a simple flag that gets checked on fire, etc. It's also thread-safe if that is desired.
I wrote it with compatibility with this PR in mind so it should (hopefully) not conflict when this PR lands someday.
Only notify the backend when the value actually changes, so reassigning the same interval no longer restarts the timer, and give every backend a way to apply both to a timer that is already running.
start_event_loop() counted sleeps rather than elapsed time, so it ran long by however much time flush_events() took. GTK used that polling fallback; give it a GLib.MainLoop instead.
Tk and asyncio waited a full interval after each callback returned, so they drifted by the callback duration, and Qt's default coarse timer is allowed to drift by 5%. Schedule against the next firing time instead and drop the firings missed when a callback overruns.
Tk, GTK and macOS cleared the stored handle after running the callbacks, discarding the timer a callback had just started so stop() could no longer cancel it.
Cover the property updates, single shot behaviour, restarting from a callback, and that a slow callback does not push back the firings after it. The drift check measures the spacing between firings against the interval so it holds up on a runner that is short on CPU.
6842ed2 to
8537e32
Compare
|
I had AI do a code review of the previous implementation I had for me since it had been sitting for so long. After that I made some updates to:
|
2349ae5 to
4befb1a
Compare
|
@greglucas - Regarding your recent commits, are you sure that this is an issue with CPU contention (other threads are saturating the CPU) and not a CPU scheduling/napping issue? Are our CI machines shared at all or running in a VM? Would |
Nope, I am just taking shots in the dark here. I'm having AI try to do some debugging on this now for me... This is also why the PR wasn't merged before because I was playing whack-a-mole with CI. These are the macos runners failing, but not just the macos backend, it is even the asyncio timers with no GUI toolkit. |
Point the AI at the |
|
Great suggestions, thank you!
I think we are potentially getting somewhere now... A few more things to try here. |
|
My best guess based on your latest commits is that this is an artifact of how Microsoft is virtualizing the machine in Azure Pipelines.
There's never been a real Mac with only 3 cores and 14GB of RAM, so that definitely points to some kind of virtualization. |
Test against N firings and measure the gaps rather than against a specific amount of time and measuring the firings. Use a baseline reference run to get an initial estimate of the system's CPU slowness for CI systems that can be unreliable with timings. Adjust QT timer intervals ourselves to avoid drift
1a0f0a5 to
cace96c
Compare
PR summary
Currently, all of the backend timers have subtly different behavior relating to long-running callbacks. Meaning we don't make any guarantees about when the timers will fire currently and it is the wild-west of what will happen. This PR has quite a few things going on to try and bring these all into consistency and adds tests for these cases. I'll describe the main updates below:
default backend main loop
This is a really bad error IMO. We are currently running the loop for x number of sleeps(), but if the callback takes longer than the sleep duration this makes the runloop run longer than a user requested. I have updated this to be dependent on total duration within the loop.
interval updates
When setting the interval or singleshot attribute of a timer, we would always call the underlying
start()again. Meaning that this would trigger a timer "reset" in a sense, even if the interval was exactly the same as before (i.e. setting it constantly in a loop). I have updated this to only "reset"/"restart" the timer if the value has changed.Tk
We need to keep track of the expected firing time ourselves since there is no repeating timer. We keep track of the original requested firing time and the callback trigger to account for the case of a callback taking longer than the repeat timer when we actually want the timer to fire immediately and not on the next interval.
Added singleshot and interval handler updates.
wx
Added singleshot update handler.
macos
Added an asynchronous dispatch to the main queue. This prevents timer drift with synchronous slow callbacks.
Added singleshot and interval update handling.
Removed previously started repeating timer
testing
Added a test for a slow callback to the interactive timers and refactored the tests to try to process in parallel and reduce some of the time spent in the tests.
closes #28647
closes #29029
closes #29076
PR checklist