Long event dispatching time leads to high async latency

[enkore]

Detached from #9 (comment)

while Pending():
    Dispatch() / DispatchTimeout(1)

can take a long time for various reasons. A particularly noticeable offender is wxListCtrl in LC_VIRTUAL mode, which in certain X11 configurations (I'm not really sure what causes it, but I'm ready to blame VNC anyway) can cause this loop to take up to ~1.5 seconds(!). Dispatch() and DispatchTimeout() themselves don't usually process a single event. They generally process many events, which in practice may take 0.1-0.2 s in some cases. I've observed this loop processing several thousand events in around a hundred iterations, taking several seconds to complete.

Modal event loops (including context/popup menus) block the main event loop as well.

These "hiccups" don't block the app itself - the event loop is running after all - but coroutines and callbacks are only run when the "MainLoop" coroutine yields, which only happens between these loops.

For gathering data my main loop has now grown into this... uh... neat abomination:

    async def MainLoop(self):
        # inspired by https://github.com/wxWidgets/Phoenix/blob/master/samples/mainloop/mainloop.py
        evtloop = wx.GUIEventLoop()
        with wx.EventLoopActivator(evtloop):
            while not self.exiting:
                if IS_MAC:
                    # evtloop.Pending() just returns True on MacOs
                    evtloop.DispatchTimeout(0)
                else:

                    def e2t(e):
                        s = f'{e.__class__.__name__} ({e.GetId()})'
                        #if e.__class__.__name__ in ('ListEvent',):  # Segfaults :)
                        #    s += f' ({e.GetEventObject().__class__.__name__})'
                        return s
                    st = time.perf_counter()
                    self._events.clear()
                    n = 0
                    while True:
                        s0 = time.perf_counter()
                        res = evtloop.Pending()
                        e0 = time.perf_counter() - s0
                        if e0 > 0.01:
                            logging.error('Pending() took %.3f s', e0)
                        if not res:
                            break

                        n += 1

                        l1 = len(self._events)
                        s1 = time.perf_counter()
                        evtloop.DispatchTimeout(1)
                        e1 = time.perf_counter() - s1
                        if e1 > 0.1:
                            logging.error('Event processing took %.3f s: %s', e1, [e2t(e) for e in self._events[l1:]])
                    el = time.perf_counter() - st
                    from collections import Counter

                    if el > 0.1:
                        c = Counter([e.__class__.__name__ for e in self._events])
                        evts = [f'{k} (x{v})' for k, v in sorted(c.items(), key=lambda s: s[1], reverse=True)]
                        logging.error('UI loop stalled for %.3f s (%d iterations, %d events): %s', el, n, len(self._events), evts) #, [e.__class__.__name__ + f' ({e.GetId()})' for e in self._events])

                await asyncio.sleep(0.005)
                self.ProcessPendingEvents()
                evtloop.ProcessIdle()

This makes it really easy to figure out what the issue is:

[17:52:32,289 ERROR] wxasync: UI loop stalled for 0.272 s (6 iterations, 75 events): ['EraseEvent (x48)', 'Event (x24)', 'ListEvent (x3)']
[17:52:42,756 ERROR] wxasync: UI loop stalled for 1.035 s (65 iterations, 605 events): ['EraseEvent (x360)', 'Event (x180)', 'ListEvent (x45)', 'SetCursorEvent (x10)', 'MouseEvent (x10)']
[17:52:44,772 ERROR] wxasync: UI loop stalled for 1.015 s (48 iterations, 598 events): ['EraseEvent (x368)', 'Event (x184)', 'ListEvent (x46)']
[17:52:59,931 ERROR] wxasync: UI loop stalled for 1.039 s (63 iterations, 615 events): ['EraseEvent (x368)', 'Event (x184)', 'ListEvent (x46)', 'MouseEvent (x9)', 'SetCursorEvent (x8)']
[17:53:01,941 ERROR] wxasync: UI loop stalled for 1.009 s (48 iterations, 585 events): ['EraseEvent (x360)', 'Event (x180)', 'ListEvent (x45)']
[17:53:19,728 ERROR] wxasync: UI loop stalled for 1.036 s (101 iterations, 662 events): ['EraseEvent (x368)', 'Event (x184)', 'ListEvent (x46)', 'SetCursorEvent (x36)', 'MouseEvent (x28)']
[17:53:21,051 ERROR] wxasync: UI loop stalled for 0.315 s (19 iterations, 174 events): ['EraseEvent (x104)', 'Event (x52)', 'ListEvent (x13)', 'SetCursorEvent (x3)', 'MouseEvent (x2)']
[17:53:22,074 ERROR] wxasync: UI loop stalled for 1.018 s (145 iterations, 705 events): ['EraseEvent (x360)', 'Event (x180)', 'SetCursorEvent (x65)', 'MouseEvent (x55)', 'ListEvent (x45)']
[17:53:24,289 ERROR] wxasync: UI loop stalled for 1.012 s (48 iterations, 585 events): ['EraseEvent (x360)', 'Event (x180)', 'ListEvent (x45)']
[17:53:54,083 ERROR] wxasync: UI loop stalled for 1.055 s (70 iterations, 623 events): ['EraseEvent (x368)', 'Event (x184)', 'ListEvent (x46)', 'SetCursorEvent (x15)', 'MouseEvent (x10)']
[17:53:55,316 ERROR] wxasync: UI loop stalled for 0.247 s (14 iterations, 122 events): ['EraseEvent (x72)', 'Event (x36)', 'ListEvent (x9)', 'SetCursorEvent (x3)', 'MouseEvent (x2)']
[17:53:56,372 ERROR] wxasync: UI loop stalled for 1.035 s (53 iterations, 603 events): ['EraseEvent (x368)', 'Event (x184)', 'ListEvent (x46)', 'SetCursorEvent (x3)', 'MouseEvent (x2)']
[17:53:58,595 ERROR] wxasync: UI loop stalled for 1.010 s (48 iterations, 585 events): ['EraseEvent (x360)', 'Event (x180)', 'ListEvent (x45)']
[17:54:19,547 ERROR] wxasync: UI loop stalled for 1.041 s (61 iterations, 612 events): ['EraseEvent (x368)', 'Event (x184)', 'ListEvent (x46)', 'MouseEvent (x8)', 'SetCursorEvent (x6)']
[17:54:21,564 ERROR] wxasync: UI loop stalled for 1.016 s (49 iterations, 598 events): ['EraseEvent (x368)', 'Event (x184)', 'ListEvent (x46)']

Sure enough, the window has a wxListCtrl in LC_VIRTUAL mode with eight columns and 45 or so visible rows. The ListEvent events are EVT_LIST_CACHE_HINT events (ignored in my case). Adding a wxListCtrl to the test case presented in #9 shows the same problem:

import wx
import time

from wxasync import AsyncBind, WxAsyncApp, StartCoroutine
import asyncio
from asyncio.events import get_event_loop


async def foo():
    while True:
        st = time.perf_counter()
        await asyncio.sleep(0.05)
        el = time.perf_counter() - st
        if el > 0.06:
            print(f'await sleep(0.05) took {el:0.3f} s!')


class List(wx.ListCtrl):
    def __init__(self, parent):
        super().__init__(parent, style=wx.LC_REPORT | wx.LC_VIRTUAL)
        for n in range(10):
            self.AppendColumn(f'Column {n+1}')
        self.SetItemCount(25000)

    def OnGetItemText(self, item, column):
        return f'{item} @ {column}'


class BasicFrame(wx.Frame):
    def __init__(self, parent=None, id=-1, title=""):
        wx.Frame.__init__(self, parent, id, title, size=(800,800))
        self.wx_panel = wx.Panel(self)
        self.wx_sizer = wx.BoxSizer(wx.VERTICAL)
        self.left = wx.ListBox(self.wx_panel, name="list1")
        self.wx_sizer.Add(self.left, flag=wx.EXPAND)
        self.right = wx.ListBox(self.wx_panel, name="list2")
        self.wx_sizer.Add(self.right, flag=wx.EXPAND)
        self.text = wx.TextCtrl(self.wx_panel, name="Username")
        self.wx_sizer.Add(self.text, flag=wx.EXPAND)
        self.list = List(self.wx_panel)
        self.wx_sizer.Add(self.list, 1, flag=wx.EXPAND)
        self.wx_panel.SetSizerAndFit(self.wx_sizer)



        # Fills the lists
        self.left.Append("One")
        self.left.Append("Two")
        self.left.Append("Three")
        self.right.Append("First")
        self.right.Append("Second")
        StartCoroutine(foo(), self)

def main():
    class MyApp(wx.App):

        def OnInit(self):
            frame = BasicFrame(title="test")
            frame.Show(True)

            import wx.lib.inspection
            wx.UpdateUIEvent.SetMode(wx.UPDATE_UI_PROCESS_SPECIFIED)
            self.SetTopWindow(frame)

            return True

    app = MyApp(0)
    app.MainLoop()
    # del app

def main_async():
    # see https://github.com/sirk390/wxasync
    app = WxAsyncApp()
    frame = BasicFrame(title="test")
    frame.Show(True)
    app.SetTopWindow(frame)
    loop = get_event_loop()
    loop.run_until_complete(app.MainLoop())

if __name__ == "__main__":
    main_async()

Adding a log call to the FilterEvent method of WxAsyncApp can directly show how slowly these are emitted:

[18:14:49,996 DEBUG] wxasync: ListEvent
[18:14:50,050 DEBUG] wxasync: ListEvent
[18:14:50,079 DEBUG] wxasync: ListEvent
[18:14:50,101 DEBUG] wxasync: ListEvent
[18:14:50,118 DEBUG] wxasync: ListEvent
[18:14:50,147 DEBUG] wxasync: ListEvent
[18:14:50,167 DEBUG] wxasync: ListEvent
[18:14:50,184 DEBUG] wxasync: ListEvent
[18:14:50,218 DEBUG] wxasync: ListEvent
[18:14:50,237 DEBUG] wxasync: ListEvent
[18:14:50,268 DEBUG] wxasync: ListEvent
[18:14:50,287 DEBUG] wxasync: ListEvent
[18:14:50,319 DEBUG] wxasync: ListEvent
[18:14:50,339 DEBUG] wxasync: ListEvent
[18:14:50,369 DEBUG] wxasync: ListEvent
[18:14:50,390 DEBUG] wxasync: ListEvent
[18:14:50,408 DEBUG] wxasync: ListEvent
[18:14:50,438 DEBUG] wxasync: ListEvent
[18:14:50,462 DEBUG] wxasync: ListEvent
[18:14:50,498 DEBUG] wxasync: ListEvent
[18:14:50,532 DEBUG] wxasync: ListEvent
[18:14:50,554 DEBUG] wxasync: ListEvent
[18:14:50,585 DEBUG] wxasync: ListEvent
[18:14:50,605 DEBUG] wxasync: ListEvent
[18:14:50,635 DEBUG] wxasync: ListEvent
[18:14:50,657 DEBUG] wxasync: ListEvent
[18:14:50,688 DEBUG] wxasync: ListEvent
[18:14:50,709 DEBUG] wxasync: ListEvent
[18:14:50,741 DEBUG] wxasync: ListEvent
[18:14:50,761 DEBUG] wxasync: ListEvent
[18:14:50,793 DEBUG] wxasync: ListEvent
[18:14:50,813 DEBUG] wxasync: ListEvent
[18:14:50,844 DEBUG] wxasync: ListEvent
[18:14:50,866 DEBUG] wxasync: ListEvent
[18:14:50,901 DEBUG] wxasync: ListEvent
[18:14:50,932 DEBUG] wxasync: ListEvent
[18:14:50,960 DEBUG] wxasync: ListEvent
[18:14:50,997 DEBUG] wxasync: ListEvent
[18:14:51,018 ERROR] wxasync: UI loop stalled for 1.024 s (40 iterations, 608 events): ['EraseEvent (x380)', 'Event (x190)', 'ListEvent (x38)']
await sleep(0.05) took 1.069 s!

Like I said above, this doesn't just happen on a normal Linux desktop, but only affects certain configurations. (Due to the somewhat absurd slowness I suspect that in my configuration draw calls might be executing synchronously over the network).

Now the interesting question is of course what can we do about this?

Several things:

1. Yield inside the loop, to limit the damage being done:

   while Pending():
       Dispatch()
       await asyncio.sleep(0)  # == yield None
   

   This isn't particularly clean or smart, but should reduce the latency enough that it isn't immediately obvious to a human. A one or two second hang between "button click" and "results show up on screen" is very obvious, an extra 100 ms less so.

2. Somehow yield in FilterEvent (careful: might reduce event throughput due to overhead). I'm pretty sure this would be a somewhat ugly hack with asyncio, since it lacks any kind of run_once / tick notion. Maybe asyncio.run_until_complete(asyncio.sleep(0)) would work. Maybe it doesn't.

3. Ensure perfect coupling [1]. I don't think this is possible with asyncio and wxEventLoop. It's what I built asynker for a few years ago, but it's somewhat annoying, since asynker is very specifically not asyncio, so there is a lot less functionality and no compatibility with 3rd party libs written for asyncio.

[1] Perfect coupling: Event loop A yields to event loop B as soon as B has runnable tasks and vice versa. Perfect coupling is always the case when A and B are identical (that's how asynker does it; it doesn't have a separate event loop). Perfect coupling is very desirable in my opinion, because achieving it coincidentally also tends to mean that there is no additional delay between events in A causing a coroutine in B to become runnable. It also means the overall mechanism of A and B doesn't have to constantly run like MainLoop in wxasync has to do; it only needs to run when there are events to process.

(eref 42d478fb6976)

[enkore]

Like I said above, this doesn't just happen on a normal Linux desktop, but only affects certain configurations. (Due to the somewhat absurd slowness I suspect that in my configuration draw calls might be executing synchronously over the network).

The configuration that causes this isn't actually anything fancy or broken: It's the default Gnome theme (okay, maybe that actually is a broken configuration ;D). It has these self-hiding tiny scroll bars on top of the scrollbar-bearing window's content. These are animated. So whenever you move the mouse over or out of a scrollbar-bearing window in the default Gnome theme, it will redraw itself at a rate of about 30+ redraws per second for one second. If you swipe over it, it will do that, then wait a second, then fade the scrollbars out again, which causes another second of redrawing. While the damaged regions are small (just what's under the scroll bars plus some margins), the wxListCtrl doesn't optimize for partial redraws. It always redraws everything on paint events and relies on the DC's clipper to cull drawing operations outside the damaged regions.

So each animation frame causes the wxListCtrl to do most of the work as if it were redrawing everything, which isn't all that fast. Because there is a constant onslaught on events (probably because GTK tries to redraw at 60 Hz, but my six core workstation is not fast enough to pull that off), it never runs out of events during these animations, and hence Pending() always has events to go on and doesn't return false.

So workaround No. 1 seems to work just fine to reduce the impact of these "Gnome design decisions".

[sirk390]

I'm not sure it's closed as it autoclosed when I merged, but it's reasonable to add this extra asyncio.sleep and shoudn't create issues.I also updated the package in pypi.

There are clearly still some locks in the event loop, but they are difficult to remove. The ones that I know of are: "Move the window", "Enter in a menu", or "Using Modal dialogs".
It would be really cool though to remove all these small locks.

[enkore]

wx is hardcoded to just use wxGUIEventLoop directly for stuff like modal event loops, so there is probably no possibility of easily - or cleanly - injecting our logic into these.

If wx had asyncio-style event loop policies, that wouldn't be a problem. Ironic - I always found event loop policies mildly useless in asyncio... now there'd be an obvious use, but not in asyncio... :D

[sirk390]

I don't know about GTK or macOS or other implementations, but for windows the issue is with the windows os message loop and not even wxwidgets code (e.g. wx c++ code). It is basically freezes in some situtations like on modals, on menu's and while moving a window.