Merge c765de49a6 into 6d7d3403e4

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

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()