Debug performance hiccups

[kdkavanagh]

Is there a recommended way to debug specific events with unusually high latency? I typically use profilers like Austin, but the issue I'm experiencing is sporadic and is difficult to track down when profiling the application as a whole.

The issue I'm looking to debug is a performance hiccup when scrolling thru large datatables. If I press/hold the down-arrow, the table will scroll smoothly for ~5lines, then pause for a few seconds, then continue scrolling, repeating the hiccup every ~5 lines or so. I'd like to track down why those key-down events arent being processed in a timely manner to keep the UI responsive

[willmcgugan]

Issues like this are typically caused by blocking operations. I would suspect anything that does IO, processes, or networking. The solution is usually to do that work concurrently (in a Textual worker).

Alternatively, look for anything that might be cpu intensive. And do that in a threaded worker.

You might want to use PyInstrument, which is a very simple Python profiler. It may indicate where your app is spending an excessive amount of time.

[kdkavanagh]

That was my thought as well, but there really isnt any of my code involved in the scenario causing the issue - Simply scrolling through a datatable. No background work or anything running either, afaik.

Profiler isnt super helpful because it's a small amount of wall-clock time where the app is unresponsive and since it's a repetitive action that elicits the issue (key-down on datatables), the stack frames for fast + slow periods look the same / timing information just accumulates under those frames

Is there any way to log individual events which take >x seconds to be queued+processed, or any way to generally debug sizable message queues across all components in the app?

[kdkavanagh]

Or perhaps even a way to track time between re-renderings

[willmcgugan]

You can see events being processed with the dev tools. That might give you a clue.

[kdkavanagh]

Added some additional logging to the dev console, incl microsecond-precise timestamps instead of seconds. I observe a delay during the bubbling of an event up the stack:

In this example, I see the key down events fire, which are handled/turned into CellHighlighted events from the datatable. In between the Horizontal(main_hori) handling the event and the bubbling up to the Screen, the app seems to pause for ~0.4s. The Horizontal object has no event listeners, so I dont suspect any latency to be introduced there.

Once the CellHighlighted event makes its way up to the app where I do have a handler, I measure the time it takes to dispatch that event + the time the event spent queued in the message_pump (using a timestamp taken on queue insert). The logs show that the event was processed quickly, but spent ~0.4s stuck in the message_pump queue

Not sure exactly where I'll proceed next, but figured I'd post here in case anyone has ideas

[kdkavanagh]

Interestingly as well, I've noticed that the problem is recreatable even when not holding the key-down pressed. Am able to reliably recreate the lag by single-pressing the key, waiting for the screen to update, etc. Every ~5-7 presses incurs excess latency. This suggests that the message bus isnt overloaded or something

[kdkavanagh]

Added more logging, the pauses seem to align with fires of Screen._on_timer_update. (Might be worth having those timer fires logged by default).

In particular, it seems that the latency is introduced by the call to _compositor_refresh , specifically this call: self._compositor.render_update. It's still unclear to me why that call incurs a high latency only some of the time

[kdkavanagh]

Okay! Found the source - Py interpreter GC'ing... Correlates with those compositor refreshes as it seems those allocate a bunch of temporary objects. Confirmed by calling gc.disable() after startup and seeing smooth scrolling from then-on...

@willmcgugan Do you think the garbage collector could be disabled by Textual and instead manually invoked in on_idle? Perhaps just during event handling (i.e pause gc on event recv, reenable after all handlers have run)?

[kdkavanagh]

In fact, python's generational GC is ill-suited for scrolling down specifically... New objects are created at the bottom of the terminal, and then survive for a long time until they're pushed off the top of the screen. By then, it's likely that those objects have been promoted into the older generations and as such, they'll only get collected during 2nd generation collections which are particularly slow

[kdkavanagh]

As a strawman test impl, I added this logic to the app's main MessagePump with good results. Waits for 3s of no messages before triggering a GC, then blocks till the next message as before

    async def _process_messages_loop(self, manage_gc = False) -> None:
        """Process messages until the queue is closed."""
        _rich_traceback_guard = True
        import gc
        self._thread_id = threading.get_ident()
        end = 0
        if manage_gc:
            gc.disable()
        while True:
            try:
                queue_check_start = time()
                if manage_gc:
                    try:
                        start, message = await asyncio.wait_for(self._get_message(), 3)
                    except asyncio.TimeoutError:
                        gc.collect()
                        start, message = await self._get_message()
                    
                else:
                    start, message = await self._get_message()

Also added some stats to detect the types of objects being created/collected; it may be worth considering object-pooling some of these types:

 ▊  │[02:50:41.988421] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'textual.cache.FIFOCache'>=1275049                                                                                                                                                                                                                                                                         
 ▊  │[02:50:41.988807] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'rich.segment.Segment'>=524005                                                                                                                                                                                                                                                                             
 ▊  │[02:50:41.989141] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'list'>=422244                                                                                                                                                                                                                                                                                             
 ▊  │[02:50:41.989473] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'tuple'>=292105                                                                                                                                                                                                                                                                                            
 ▊  │[02:50:41.989818] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'textual.strip.Strip'>=212509                                                                                                                                                                                                                                                                              
 ▊  │[02:50:41.990136] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'dict'>=211736                                                                                                                                                                                                                                                                                             
 ▊  │[02:50:41.990456] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'frame'>=67700                                                                                                                                                                                                                                                                                             
 ▊  │[02:50:41.990782] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'method'>=25387                                                                                                                                                                                                                                                                                            
 ▊  │[02:50:41.991108] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'textual.geometry.Size'>=24111                                                                                                                                                                                                                                                                             
 ▊  │[02:50:41.991447] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'textual.geometry.Region'>=20926                                                                                                                                                                                                                                                                           
 ▊  │[02:50:41.991771] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'inspect.Traceback'>=19068                                                                                                                                                                                                                                                                                 
 ▊  │[02:50:41.992084] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'dis.Positions'>=19068                                                                                                                                                                                                                                                                                     
 ▊  │[02:50:41.992391] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'set'>=14163                                                                                                                                                                                                                                                                                               
 ▊  │[02:50:41.992716] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'textual.Logger'>=13573                                                                                                                                                                                                                                                                                    
 ▊  │[02:50:41.993039] PRINT                                                                                                                                                                                                                                                                             browser.py:460
 ▊  │<class 'textual.map_geometry.MapGeometry'>=12582