# HG changeset patch # User Tuomo Valkonen # Date 1517098278 0 # Node ID 4b08fca3ce34c6af3855121c38e010972c3e8ff6 # Parent 2a44b96492129fdd411efc0e37420dc6a3679733 Dreamtime scheduling: discount system sleep periods diff -r 2a44b9649212 -r 4b08fca3ce34 backup.py --- a/backup.py Sat Jan 27 12:19:39 2018 +0000 +++ b/backup.py Sun Jan 28 00:11:18 2018 +0000 @@ -7,6 +7,7 @@ import time import borgend import repository +import sleep from enum import IntEnum from instance import BorgInstance from threading import Thread, Lock, Condition @@ -53,20 +54,19 @@ class Operation: CREATE='create' PRUNE='prune' - def __init__(self, operation, when_monotonic, **kwargs): + def __init__(self, operation, time, **kwargs): self.operation=operation - self.when_monotonic=when_monotonic + self.time=time self.detail=kwargs def when(self): - return self.when_monotonic-time.monotonic()+time.time() + return self.time.realtime() class Status(Operation): def __init__(self, backup, op=None): if op: - super().__init__(op.operation, op.when_monotonic, - **op.detail) + super().__init__(op.operation, op.time, **op.detail) else: super().__init__(None, None) @@ -137,6 +137,20 @@ 'Retry interval', loc, config.defaults['retry_interval']) + + scheduling=config.check_string(cfg, 'scheduling', + 'Scheduling mode', loc, + default="dreamtime") + + if scheduling=="dreamtime": + self.timeclass=sleep.DreamTime + elif scheduling=="realtime": + self.timeclass=sleep.MonotonicTime + elif scheduling=="manual": + self.backup_interval=0 + else: + logging.error("Invalid time class '%s' for %s" % (scheduling, loc)) + self.paths=config.check_nonempty_list_of_strings(cfg, 'paths', 'Paths', loc) self.borg_parameters=config.BorgParameters.from_config(cfg, loc) @@ -158,6 +172,7 @@ self.lastrun_finished=None self.state=State.INACTIVE self.errors=Errors.OK + self.timeclass=sleep.DreamTime self.__decode_config(cfg) @@ -285,7 +300,7 @@ self.current_operation=op # Update scheduled time to real starting time to schedule # next run relative to this - self.current_operation.when_monotonic=time.monotonic() + self.current_operation.time=sleep.MonotonicTime.now() self.state=State.ACTIVE # Reset error status when starting a new operation self.errors=Errors.OK @@ -354,7 +369,7 @@ self.errors=self.errors.combine(Errors.ERRORS) if self.current_operation.operation=='create': - self.lastrun_when=self.current_operation.when_monotonic + self.lastrun_when=self.current_operation.time.monotonic() self.lastrun_finished=time.monotonic() self.thread_res=None self.thread_log=None @@ -404,17 +419,17 @@ if not self.scheduled_operation: op=self.__next_operation_unlocked() if op: - now=time.monotonic() - delay=max(0, op.when_monotonic-now) - self.logger.info("Scheduling '%s' (detail: %s) in %d seconds" % - (str(op.operation), op.detail or 'none', delay)) + self.logger.info("Scheduling '%s' (detail: %s) in %d seconds [%s]" % + (str(op.operation), op.detail or 'none', + op.time.seconds_to(), + op.time.__class__.__name__)) self.scheduled_operation=op self.state=State.SCHEDULED self.__update_status() # Wait under scheduled wait - self.scheduler.wait_until(now+delay, self._cond, self.backup_name) + self.scheduler.wait_until(op.time, self._cond, self.backup_name) else: # Nothing scheduled - just wait self.logger.info("Waiting for manual scheduling") @@ -444,7 +459,6 @@ def __next_operation_unlocked(self): # TODO: pruning as well - now=time.monotonic() if not self.lastrun_finished: initial_interval=self.retry_interval if initial_interval==0: @@ -452,21 +466,20 @@ if initial_interval==0: return None else: - return Operation(Operation.CREATE, now+initial_interval, - reason='initial') + tm=self.timeclass.after(initial_interval) + return Operation(Operation.CREATE, tm, reason='initial') elif not self.errors.ok(): if self.retry_interval==0: return None else: - return Operation(Operation.CREATE, - self.lastrun_finished+self.retry_interval, - reason='retry') + tm=sleep.MonotonicTime(self.lastrun_finished+self.retry_interval) + return Operation(Operation.CREATE, tm, reason='retry') else: if self.backup_interval==0: return None else: - return Operation(Operation.CREATE, - self.lastrun_when+self.backup_interval) + tm=self.timeclass.from_monotonic(self.lastrun_when+self.backup_interval) + return Operation(Operation.CREATE, tm) def __status_unlocked(self): callback=self.__status_update_callback @@ -505,13 +518,13 @@ return res[0] def create(self): - op=Operation(Operation.CREATE, time.monotonic(), reason='manual') + op=Operation(Operation.CREATE, sleep.MonotonicTime.now(), reason='manual') with self._cond: self.scheduled_operation=op self._cond.notify() def prune(self): - op=Operation(Operation.PRUNE, time.monotonic(), reason='manual') + op=Operation(Operation.PRUNE, sleep.MonotonicTime.now(), reason='manual') with self._cond: self.scheduled_operation=op self._cond.notify() diff -r 2a44b9649212 -r 4b08fca3ce34 borgend.py --- a/borgend.py Sat Jan 27 12:19:39 2018 +0000 +++ b/borgend.py Sun Jan 28 00:11:18 2018 +0000 @@ -103,6 +103,9 @@ from backup import Backup from queue import Queue import signal, os + import sleep + + sleep.start_monitoring() scheduler = Scheduler() scheduler.start() diff -r 2a44b9649212 -r 4b08fca3ce34 config.example.yaml --- a/config.example.yaml Sat Jan 27 12:19:39 2018 +0000 +++ b/config.example.yaml Sun Jan 28 00:11:18 2018 +0000 @@ -39,6 +39,9 @@ backup_interval: 86400 # Retry every 15 minutes if unable to connect / unfinished backup retry_interval: 900 + # Scheduling mode: dreamtime/realtime/manual + # Dreamtime scheduling discounts system sleep periods. + scheduling: dreamtime repository: myserver archive_prefix: 'all@mylaptop-' archive_template: '{now:%Y-%m-%d_%H:%M:%S}' @@ -54,19 +57,23 @@ # 2. A subset of files $HOME more frequently to ssh://myserver.invalid - name: Work to 'myserver' - # Backup every 3 hours - backup_interval: 10800 - # Retry every 15 minutes if unable to connect / unfinished backup - retry_interval: 900 - repository: myserver - archive_prefix: 'work@mylaptop-' - archive_template: '{now:%Y-%m-%d_%H:%M:%S}' - paths: - - $HOME/work + # Backup every 3 hours + backup_interval: 10800 + # Retry every 15 minutes if unable to connect / unfinished backup + retry_interval: 900 + # Scheduling mode: dreamtime/realtime/manual + # Dreamtime scheduling discounts system sleep periods. + scheduling: dreamtime + repository: myserver + archive_prefix: 'work@mylaptop-' + archive_template: '{now:%Y-%m-%d_%H:%M:%S}' + paths: + - $HOME/work # 3. Manual backup to external hard drive - name: Home to 'backup1' # Manual backup + scheduling: manual backup_interval: 0 retry_interval: 0 repository: backup1 diff -r 2a44b9649212 -r 4b08fca3ce34 scheduler.py --- a/scheduler.py Sat Jan 27 12:19:39 2018 +0000 +++ b/scheduler.py Sun Jan 28 00:11:18 2018 +0000 @@ -6,6 +6,7 @@ import time import borgend +import sleep from threading import Condition, Lock, Thread logger=borgend.logger.getChild(__name__) @@ -45,8 +46,11 @@ n.prev=p if p: p.next=n + self.next=None + self.prev=None class ScheduledEvent(QueuedEvent): + #@accepts(ScheduledEvent, sleep.Time, threading.Cond, str) def __init__(self, when, cond, name=None): super().__init__(cond, name=name) self.when=when @@ -90,6 +94,16 @@ self._list=ev.next ev.unlink() + def _resort(self): + oldlist=self._list + self._list=None + while oldlist: + ev=oldlist + oldlist=oldlist.next + ev.unlink() + self._insert(ev) + + class Scheduler(QueueThread): # Default to precision of 60 seconds: the scheduler thread will never @@ -99,6 +113,7 @@ self.precision = precision self._next_event_time = None super().__init__(target = self._scheduler_thread, name = 'Scheduler') + sleep.add_callback(self, self._wakeup_callback) def _scheduler_thread(self): logger.debug("Scheduler thread started") @@ -110,7 +125,7 @@ else: # Wait at most precision seconds, or until next event if it # comes earlier - timeout=min(self.precision, self._list.when-now) + timeout=min(self.precision, self._list.when.realtime()-now) if not timeout or timeout>0: logger.debug("Scheduler waiting %d seconds" % (timeout or (-1))) @@ -119,7 +134,7 @@ logger.debug("Scheduler timed out") - while self._list and self._list.when <= now: + while self._list and self._list.when.monotonic() <= 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 @@ -128,6 +143,11 @@ ev.unlink() ev.cond.notifyAll() + def _wakeup_callback(self): + logger.debug("Rescheduling events after wakeup") + with self._cond: + self._resort() + def _wait(self, ev): with self._cond: self._insert(ev) @@ -143,6 +163,7 @@ # cond has to be acquired on entry! def wait_until(self, when, cond, name=None): - logger.debug("Scheduling '%s' at %d" % (name, when)) + logger.debug("Scheduling '%s' in %s seconds [%s]" % + (name, when.seconds_to(), when.__class__.__name__)) self._wait(ScheduledEvent(when, cond, name)) diff -r 2a44b9649212 -r 4b08fca3ce34 sleep.py --- a/sleep.py Sat Jan 27 12:19:39 2018 +0000 +++ b/sleep.py Sun Jan 28 00:11:18 2018 +0000 @@ -4,34 +4,199 @@ import Foundation import AppKit +import platform +import time +import threading import borgend -import platform +import weakref +import datetime logger=borgend.logger.getChild(__name__) +_dreamtime_monitor=[None] + +# +# Support classes for dealing with different times +# + +def dreamtime(): + if _dreamtime_monitor[0]: + return max(0, time.monotonic()-_dreamtime_monitor[0].diff()) + else: + return time.monotonic() + +class Time: + def realtime(self): + raise NotImplementedError + + def monotonic(self): + raise NotImplementedError + + @staticmethod + def _now(): + raise NotImplementedError + + @classmethod + def now(cls): + return cls(cls._now()) + + @classmethod + def from_realtime(cls, realtime): + return cls(realtime-time.time()+cls._now()) + + @classmethod + def from_monotonic(cls, monotonic): + return cls(monotonic-time.monotonic()+cls._now()) + + @classmethod + def after(cls, seconds): + return cls(cls._now()+seconds) + + def datetime(self): + return datetime.datetime.fromtimestamp(self.realtime()) + + def seconds_to(self): + return self._value-self._now() + + def __lt__(self, other): + return self.monotonic() < other.monotonic() + + def __gt__(self, other): + return self.monotonic() > other.monotonic() + + def __le__(self, other): + return self.monotonic() <= other.monotonic() + + def __ge__(self, other): + return self.monotonic() >= other.monotonic() + + def __eq__(self, other): + return self.monotonic() == other.realtime() + +class RealTime(Time): + def __init__(self, when): + self._value=when + + def realtime(self): + return self._value + + def monotonic(self): + return self._value+(time.monotonic()-time.time()) + + @staticmethod + def _now(): + return time.time() + +class MonotonicTime(Time): + def __init__(self, when): + self._value=when + + def realtime(self): + return self._value+(time.time()-time.monotonic()) + + def monotonic(self): + return self._value + + @staticmethod + def _now(): + return time.monotonic() + +class DreamTime(Time): + def __init__(self, when): + self._value=when + + def realtime(self): + return self._value+(time.time()-dreamtime()) + + def monotonic(self): + return self._value+(time.monotonic()-dreamtime()) + + @staticmethod + def _now(): + return dreamtime() + +# +# Wake up / sleep handling +# + class SleepHandler(Foundation.NSObject): """ Handle wake/sleep notifications """ - def handleSleepNotification(self, aNotification): + def init(self): + self.__sleeptime=None + self.__slept=0 + self.__epoch=time.monotonic() + self._lock=threading.Lock() + self._callbacks=weakref.WeakKeyDictionary() + + return self + + def handleSleepNotification_(self, aNotification): logger.info("System going to sleep") + now=time.monotonic() + with self._lock: + self.__sleeptime=now - def handleWakeNotification(self, aNotification): + def handleWakeNotification_(self, aNotification): logger.info("System waking up from sleep") + try: + now=time.monotonic() + with self._lock: + if self.__sleeptime: + slept=max(0, now-self.__sleeptime) + logger.info("Slept %f seconds" % slept) + self.__slept=self.__slept+slept + self.__sleeptime=None + callbacks=self._callbacks.copy() + except: + logger.exception("Bug in wakeup handler") -if platform.system()=='Darwin': - workspace = AppKit.NSWorkspace.sharedWorkspace() - notification_center = workspace.notificationCenter() - sleep_handler = SleepHandler.new() + for callback in callbacks.values(): + try: + callback() + except Exception: + logger.exception("Error in wake notification callback") - notification_center.addObserver_selector_name_object_( - sleep_handler, - "handleSleepNotification", - AppKit.NSWorkspaceWillSleepNotification, - None) + # Return difference to time.monotonic() + def diff(self): + with self._lock: + diff=self.__epoch+self.__slept + return diff + + # Obj-C hates this + # def add_callback(self, obj, callback): + # with self.lock: + # self.__callbacks[obj]=callback + +# obj is to use a a key in a weak key dictionary +def add_callback(obj, callback): + monitor=_dreamtime_monitor[0] + if not monitor: + raise Exception("Dreamtime monitor not started") + else: + #monitor.add_my_callback(obj, callback) + with monitor._lock: + monitor._callbacks[obj]=callback - notification_center.addObserver_selector_name_object_( - sleep_handler, - "handleWakeNotification", - AppKit.NSWorkspaceDidWakeNotification, - None) +def start_monitoring(): + if platform.system()=='Darwin': + logger.debug("Starting to monitor system sleep") + workspace = AppKit.NSWorkspace.sharedWorkspace() + notification_center = workspace.notificationCenter() + _dreamtime_monitor[0] = SleepHandler.new() + notification_center.addObserver_selector_name_object_( + _dreamtime_monitor[0], + "handleSleepNotification:", + AppKit.NSWorkspaceWillSleepNotification, + None) + + notification_center.addObserver_selector_name_object_( + _dreamtime_monitor[0], + "handleWakeNotification:", + AppKit.NSWorkspaceDidWakeNotification, + None) + else: + logger.warning(("No system sleep monitor implemented for '%s'" + % platform.system())) + diff -r 2a44b9649212 -r 4b08fca3ce34 ui.py --- a/ui.py Sat Jan 27 12:19:39 2018 +0000 +++ b/ui.py Sun Jan 28 00:11:18 2018 +0000 @@ -8,6 +8,7 @@ import logging import borgend import backup +import sleep from threading import Lock, Timer from config import settings import objc @@ -154,31 +155,25 @@ def __init__(self, backups): self.lock=Lock() self.backups=backups + self.refresh_timer=None + self.refresh_timer_time=None self.statuses=[None]*len(backups) - with self.lock: - # Initialise reporting callbacks and local status copy - # (since rumps doesn't seem to be able to update menu items - # without rebuilding the whole menu, and we don't want to lock - # when calling Backup.status(), especially as we will be called - # from Backup reporting its status, we keep a copy to allow - # rebuilding the entire menu - for index in range(len(backups)): - b=backups[index] - # Python closures suck dog's balls; hence the _index=index hack - # See also http://math.andrej.com/2009/04/09/pythons-lambda-is-broken/ - cb=(lambda status, errors=None, _index=index: - self.__status_callback(_index, status, errorlog=errors)) - b.set_status_update_callback(cb) - self.statuses[index]=b.status() + for index in range(len(backups)): + self.statuses[index]=backups[index].status() + + menu, title=self.build_menu_and_timer() + + super().__init__(title, menu=menu, quit_button=None) - self.refresh_timer=None - self.refresh_timer_time=None + for index in range(len(backups)): + # Python closures suck dog's balls; hence the _index=index hack + # See also http://math.andrej.com/2009/04/09/pythons-lambda-is-broken/ + cb=(lambda status, errors=None, _index=index: + self.__status_callback(_index, status, errorlog=errors)) + backups[index].set_status_update_callback(cb) - menu, title=self.build_menu_and_timer() - - super().__init__(title, menu=menu, quit_button=None) - + sleep.add_callback(self, self.refresh_ui) def __rebuild_menu(self): menu=[]