From 2c9424345f774002099f1d01b047e793dc1674a4 Mon Sep 17 00:00:00 2001 From: Timofey Titovets Date: Mon, 19 Jan 2026 23:39:58 +0100 Subject: [PATCH 1/2] reactor: slow timer tracker For debug purporses Signed-off-by: Timofey Titovets --- klippy/reactor.py | 43 +++++++++++++++++++++++++++++++++++++++---- 1 file changed, 39 insertions(+), 4 deletions(-) diff --git a/klippy/reactor.py b/klippy/reactor.py index 03742b149..c30c094a0 100644 --- a/klippy/reactor.py +++ b/klippy/reactor.py @@ -6,18 +6,29 @@ import os, gc, select, math, time, logging, queue import greenlet import chelper, util +import inspect _NOW = 0. _NEVER = 9999999999999999. +_SLOW_TIMER = .050 class ReactorError(Exception): pass class ReactorTimer: - def __init__(self, callback, waketime): + def __init__(self, callback, waketime, whoami=None): self.callback = callback self.waketime = waketime self.timer_is_running = False + self.whoami = whoami + if whoami is None: + if inspect.isfunction(callback) or inspect.ismethod(callback): + fn_name = callback.__name__ + ln = inspect.getsourcelines(callback)[1] + file = os.path.basename(inspect.getsourcefile(callback)) + self.whoami = "%s:%d:%s" % (file, ln, fn_name) + else: + self.whoami = repr(callback) class ReactorCompletion: class sentinel: pass @@ -63,6 +74,11 @@ class ReactorGreenlet(greenlet.greenlet): def __init__(self, run): greenlet.greenlet.__init__(self, run=run) self.timer = None + # Time tracking + self.tstart = .0 + self.tstop = .0 + self.tpause = .0 + self.whoami = None class ReactorMutex: def __init__(self, reactor, is_locked): @@ -138,8 +154,8 @@ class SelectReactor: return timer_handler.waketime = waketime self._next_timer = min(self._next_timer, waketime) - def register_timer(self, callback, waketime=NEVER): - timer_handler = ReactorTimer(callback, waketime) + def register_timer(self, callback, waketime=NEVER, whoami=None): + timer_handler = ReactorTimer(callback, waketime, whoami) timers = list(self._timers) timers.append(timer_handler) self._timers = timers @@ -174,9 +190,16 @@ class SelectReactor: if eventtime >= waketime: t.waketime = self.NEVER t.timer_is_running = True + g_dispatch.tstart = self.monotonic() + g_dispatch.whoami = t.whoami t.waketime = waketime = t.callback(eventtime) + g_dispatch.tstop = self.monotonic() t.timer_is_running = False + time_spend = g_dispatch.tstop - g_dispatch.tstart + if time_spend > _SLOW_TIMER and t.whoami != "pause_wrapper": + logging.info("Slow: %s %.6f", t.whoami, time_spend) if g_dispatch is not self._g_dispatch: + g_dispatch.tstart = .0 self._next_timer = min(self._next_timer, waketime) self._end_greenlet(g_dispatch) return 0. @@ -233,6 +256,8 @@ class SelectReactor: # Switch to _check_timers (via g.timer.callback return) if self._prevent_pause_count: self.verify_can_pause() + if g.tstart > .0: + g.tpause = self.monotonic() return self._g_dispatch.switch(waketime) # Pausing the dispatch greenlet - prepare a new greenlet to do dispatch if self._prevent_pause_count: @@ -243,7 +268,17 @@ class SelectReactor: g_next = ReactorGreenlet(run=self._dispatch_loop) self._all_greenlets.append(g_next) g_next.parent = g.parent - g.timer = self.register_timer(g.switch, waketime) + # Track time spend in pause + if g.tstart > .0: + g.tpause = self.monotonic() + def pause_wrapper(_waketime): + _g = g + if _g.tpause > .0: + pause_time = self.monotonic() - _g.tpause + _g.tstart += pause_time + _g.tpause = .0 + return _g.switch(_waketime) + g.timer = self.register_timer(pause_wrapper, waketime, "pause_wrapper") self._next_timer = self.NOW # Switch to _dispatch_loop (via _end_greenlet or direct) eventtime = g_next.switch() From c765de49a664e420583fdec80ddbbff8716807fb Mon Sep 17 00:00:00 2001 From: Timofey Titovets Date: Fri, 16 Jan 2026 02:38:46 +0100 Subject: [PATCH 2/2] virtual_sdcard: fadvice sequential read os.read() will block. It is therefore possible that it can block for a long time. Long enough to block the reactor and cause an TTC error. Advise OS to always readahead file to reduce the probability of the event. Signed-off-by: Timofey Titovets --- klippy/extras/virtual_sdcard.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/klippy/extras/virtual_sdcard.py b/klippy/extras/virtual_sdcard.py index a2d6d0a0b..b26341f7b 100644 --- a/klippy/extras/virtual_sdcard.py +++ b/klippy/extras/virtual_sdcard.py @@ -174,6 +174,13 @@ class VirtualSD: if filename.startswith('/'): filename = filename[1:] self._load_file(gcmd, filename) + def _fadvice_willneed(self, f_io, size): + if not hasattr(os, 'posix_fadvise'): + return + # Python 3.3+, advice os to readahead + fd = f_io.fileno() + offset = f_io.tell() + os.posix_fadvise(fd, offset, size, os.POSIX_FADV_WILLNEED) def _load_file(self, gcmd, filename, check_subdirs=False): files = self.get_file_list(check_subdirs) flist = [f[0] for f in files] @@ -187,6 +194,7 @@ class VirtualSD: f.seek(0, os.SEEK_END) fsize = f.tell() f.seek(0) + self._fadvice_willneed(f, 0) except: logging.exception("virtual_sdcard file open") raise gcmd.error("Unable to open file") @@ -241,6 +249,7 @@ class VirtualSD: # Read more data try: data = self.current_file.read(8192) + self._fadvice_willneed(self.current_file, 8192*2) except: logging.exception("virtual_sdcard read") break