Mercurial > repos > borgend / file diff

--- a/borgend/scheduler.py	Sun Feb 04 02:19:26 2018 +0000
+++ b/borgend/scheduler.py	Sun Feb 04 09:38:55 2018 +0000
@@ -151,36 +151,45 @@
         logger.debug("Scheduler thread started")
         with self._cond:
             while not self._terminate:
-                snapshot = dreamtime.Snapshot()
-                now = snapshot.monotonic()
-                if not self._list:
-                    timeout = None
-                else:
-                    delta = self._list.when.horizon(snapshot)-now
-                    if delta==math.inf:
-                        timeout=None
-                    else:
-                        timeout = min(self.precision, delta)
+                try:
+                    self.__schedule_one()
+                except:
+                    logger.exception("Bug in scheduler")
+
+    def __schedule_one(self):
+        snapshot = dreamtime.Snapshot()
+        now = snapshot.monotonic()
+        if not self._list:
+            timeout = None
+            delta = None
+            nextname = None
+        else:
+            nextname=self._list.name
+            delta = self._list.when.horizon(snapshot)-now
+            if delta==math.inf:
+                timeout=None
+            else:
+                timeout = min(self.precision, delta)
 
-                if not timeout or timeout>0:
-                    logger.debug("Scheduler waiting %s seconds" % str(timeout))
-                    self._cond.wait(timeout)
-                    snapshot = dreamtime.Snapshot()
-                    now = snapshot.monotonic()
-
-                logger.debug("Scheduler timed out")
+        if not timeout or timeout>0:
+            logger.debug("Scheduler waiting %s seconds [next event '%s' in %s seconds]"
+                         % (str(timeout), nextname, str(delta)))
+            self._cond.wait(timeout)
+            snapshot = dreamtime.Snapshot()
+            now = snapshot.monotonic()
+            logger.debug("Scheduler timed out")
 
-                while self._list and self._list.when.horizon(snapshot) <= now:
-                    ev=self._list
-                    logger.debug("Scheduler activating %s" % (ev.name or "(unknown)"))
-                    # We are only allowed to remove ev from list when ev.cond allows
-                    self._unlink(ev)
-                    # We need to release the lock on self._cond before acquire
-                    # one ev.cond to avoid race conditions with self._wait
-                    self._cond.release()
-                    with ev.cond:
-                        ev.cond.notify_all()
-                    self._cond.acquire()
+        while self._list and self._list.when.horizon(snapshot) <= now:
+            ev=self._list
+            logger.debug("Scheduler activating %s" % (ev.name or "(unknown)"))
+            # We are only allowed to remove ev from list when ev.cond allows
+            self._unlink(ev)
+            # We need to release the lock on self._cond before acquire
+            # one ev.cond to avoid race conditions with self._wait
+            self._cond.release()
+            with ev.cond:
+                ev.cond.notify_all()
+            self._cond.acquire()
 
 
     def _sleepwake_callback(self, woke):
@@ -211,7 +220,8 @@
 
     # cond has to be acquired on entry!
     def wait_until(self, when, cond, name=None):
-        logger.debug("Scheduling '%s' in %s seconds [%s]" %
-                     (name, when.seconds_to(), when.__class__.__name__))
+        logger.info("Scheduling '%s' in %0.01f seconds / on %s [%s]" %
+                    (name, when.seconds_to(), when.isoformat(),
+                     when.__class__.__name__))
         self._wait(ScheduledEvent(when, cond, name))