reactor: Use the system monotonic clock instead of the normal system clock

The normal system clock can have sudden jumps if the system clock is
changed.  Use the system monotonic clock to avoid these sudden changes
in time.

It appears the Raspbian OS (which is used by OctoPi) is setup to
update the system clock upon network connectivity.  This could cause
sudden system clock changes which could lead to Klippy processing
errors.  Using the monotonic clock eliminates these issues.

Signed-off-by: Kevin O'Connor <kevin@koconnor.net>

10 files changed, 58 insertions, 45 deletions

diff --git a/klippy/chelper.py b/klippy/chelper.py
index b7baf061..ed494456 100644
--- a/klippy/chelper.py
+++ b/klippy/chelper.py
@@ -71,6 +71,7 @@ defs_serialqueue = """
 
 defs_pyhelper = """
     void set_python_logging_callback(void (*func)(const char *));
+    double get_monotonic(void);
 """
 
 # Return the list of file modification times
diff --git a/klippy/gcode.py b/klippy/gcode.py
index 407390e1..8b33e26a 100644
--- a/klippy/gcode.py
+++ b/klippy/gcode.py
@@ -3,7 +3,7 @@
 # Copyright (C) 2016  Kevin O'Connor <kevin@koconnor.net>
 #
 # This file may be distributed under the terms of the GNU GPLv3 license.
-import os, re, logging, collections, time
+import os, re, logging, collections
 import homing
 
 # Parse out incoming GCode and find and translate head movements
@@ -179,7 +179,7 @@ class GCodeParser:
     def bg_temp(self, heater):
         if self.is_fileinput:
             return
-        eventtime = time.time()
+        eventtime = self.reactor.monotonic()
         while self.is_printer_ready and heater.check_busy(eventtime):
             self.toolhead.reset_motor_off_time(eventtime)
             self.respond(self.get_temp())
diff --git a/klippy/klippy.py b/klippy/klippy.py
index 517bdf22..eac85829 100644
--- a/klippy/klippy.py
+++ b/klippy/klippy.py
@@ -195,6 +195,10 @@ class Printer:
         self.reactor.unregister_timer(self.connect_timer)
         return self.reactor.NEVER
     def run(self):
+        systime = time.time()
+        monotime = self.reactor.monotonic()
+        logging.info("Start printer at %s (%.1f %.1f)" % (
+            time.asctime(time.localtime(systime)), systime, monotime))
         try:
             self.reactor.run()
         except:
@@ -216,7 +220,7 @@ class Printer:
     def disconnect(self):
         try:
             if self.mcu is not None:
-                self.stats(time.time())
+                self.stats(self.reactor.monotonic())
                 self.mcu.disconnect()
         except:
             logging.exception("Unhandled exception during disconnect")
diff --git a/klippy/mcu.py b/klippy/mcu.py
index 4fadc13d..f6a21746 100644
--- a/klippy/mcu.py
+++ b/klippy/mcu.py
@@ -3,7 +3,7 @@
 # Copyright (C) 2016  Kevin O'Connor <kevin@koconnor.net>
 #
 # This file may be distributed under the terms of the GNU GPLv3 license.
-import sys, zlib, logging, time, math
+import sys, zlib, logging, math
 import serialhdl, pins, chelper
 
 class error(Exception):
@@ -163,7 +163,7 @@ class MCU_endstop:
         clock = int(mcu_time * self._mcu_freq)
         rest_ticks = int(rest_time * self._mcu_freq)
         self._homing = True
-        self._min_query_time = time.time()
+        self._min_query_time = self._mcu.monotonic()
         self._next_query_clock = clock + self._retry_query_ticks
         msg = self._home_cmd.encode(
             self._oid, clock, rest_ticks, 1 ^ self._invert)
@@ -173,7 +173,7 @@ class MCU_endstop:
         self._stepper.note_homing_finalized()
         self._home_timeout_clock = int(mcu_time * self._mcu_freq)
     def home_wait(self):
-        eventtime = time.time()
+        eventtime = self._mcu.monotonic()
         while self._check_busy(eventtime):
             eventtime = self._mcu.pause(eventtime + 0.1)
     def _handle_end_stop_state(self, params):
@@ -211,10 +211,10 @@ class MCU_endstop:
     def query_endstop(self, mcu_time):
         clock = int(mcu_time * self._mcu_freq)
         self._homing = False
-        self._min_query_time = time.time()
+        self._min_query_time = self._mcu.monotonic()
         self._next_query_clock = clock
     def query_endstop_wait(self):
-        eventtime = time.time()
+        eventtime = self._mcu.monotonic()
         while self._check_busy(eventtime):
             eventtime = self._mcu.pause(eventtime + 0.1)
         return self._last_state.get('pin', self._invert) ^ self._invert
@@ -377,7 +377,7 @@ class MCU:
         if not self._is_fileoutput:
             self.serial.connect()
             self._printer.reactor.update_timer(
-                self._timeout_timer, time.time() + self.COMM_TIMEOUT)
+                self._timeout_timer, self.monotonic() + self.COMM_TIMEOUT)
         self._mcu_freq = self.serial.msgparser.get_constant_float('CLOCK_FREQ')
         self._stats_sumsq_base = self.serial.msgparser.get_constant_float(
             'STATS_SUMSQ_BASE')
@@ -547,5 +547,7 @@ class MCU:
             raise error("Internal error in stepcompress")
     def pause(self, waketime):
         return self._printer.reactor.pause(waketime)
+    def monotonic(self):
+        return self._printer.reactor.monotonic()
     def __del__(self):
         self.disconnect()
diff --git a/klippy/pyhelper.c b/klippy/pyhelper.c
index 2716b9b7..410fd764 100644
--- a/klippy/pyhelper.c
+++ b/klippy/pyhelper.c
@@ -9,17 +9,20 @@
 #include <stdint.h> // uint8_t
 #include <stdio.h> // fprintf
 #include <string.h> // strerror
-#include <sys/time.h> // gettimeofday
 #include <time.h> // struct timespec
-#include "pyhelper.h" // get_time
+#include "pyhelper.h" // get_monotonic
 
-// Return the current system time as a double
+// Return the monotonic system time as a double
 double
-get_time(void)
+get_monotonic(void)
 {
-    struct timeval tv;
-    gettimeofday(&tv, NULL);
-    return (double)tv.tv_sec + (double)tv.tv_usec / 1000000.;
+    struct timespec ts;
+    int ret = clock_gettime(CLOCK_MONOTONIC, &ts);
+    if (ret) {
+        report_errno("clock_gettime", ret);
+        return 0.;
+    }
+    return (double)ts.tv_sec + (double)ts.tv_nsec * .000000001;
 }
 
 // Fill a 'struct timespec' with a system time stored in a double
diff --git a/klippy/pyhelper.h b/klippy/pyhelper.h
index bca65fd2..1042214b 100644
--- a/klippy/pyhelper.h
+++ b/klippy/pyhelper.h
@@ -1,7 +1,7 @@
 #ifndef PYHELPER_H
 #define PYHELPER_H
 
-double get_time(void);
+double get_monotonic(void);
 struct timespec fill_time(double time);
 void set_python_logging_callback(void (*func)(const char *));
 void errorf(const char *fmt, ...) __attribute__ ((format (printf, 1, 2)));
diff --git a/klippy/reactor.py b/klippy/reactor.py
index 1adf09a8..1fd8426a 100644
--- a/klippy/reactor.py
+++ b/klippy/reactor.py
@@ -3,8 +3,9 @@
 # Copyright (C) 2016  Kevin O'Connor <kevin@koconnor.net>
 #
 # This file may be distributed under the terms of the GNU GPLv3 license.
-import select, time, math
+import select, math
 import greenlet
+import chelper
 
 class ReactorTimer:
     def __init__(self, callback, waketime):
@@ -33,6 +34,7 @@ class SelectReactor:
         self._process = False
         self._g_dispatch = None
         self._greenlets = []
+        self.monotonic = chelper.get_ffi()[1].get_monotonic
     # Timers
     def _note_time(self, t):
         nexttime = t.waketime
@@ -67,7 +69,7 @@ class SelectReactor:
             self._note_time(t)
         if eventtime >= self._next_timer:
             return 0.
-        return min(1., max(.001, self._next_timer - time.time()))
+        return min(1., max(.001, self._next_timer - self.monotonic()))
     # Greenlets
     def pause(self, waketime):
         g = greenlet.getcurrent()
@@ -97,16 +99,16 @@ class SelectReactor:
     def _dispatch_loop(self):
         self._process = True
         self._g_dispatch = g_dispatch = greenlet.getcurrent()
-        eventtime = time.time()
+        eventtime = self.monotonic()
         while self._process:
             timeout = self._check_timers(eventtime)
             res = select.select(self._fds, [], [], timeout)
-            eventtime = time.time()
+            eventtime = self.monotonic()
             for fd in res[0]:
                 fd.callback(eventtime)
                 if g_dispatch is not self._g_dispatch:
                     self._end_greenlet(g_dispatch)
-                    eventtime = time.time()
+                    eventtime = self.monotonic()
                     break
         self._g_dispatch = None
     def run(self):
@@ -137,16 +139,16 @@ class PollReactor(SelectReactor):
     def _dispatch_loop(self):
         self._process = True
         self._g_dispatch = g_dispatch = greenlet.getcurrent()
-        eventtime = time.time()
+        eventtime = self.monotonic()
         while self._process:
             timeout = self._check_timers(eventtime)
             res = self._poll.poll(int(math.ceil(timeout * 1000.)))
-            eventtime = time.time()
+            eventtime = self.monotonic()
             for fd, event in res:
                 self._fds[fd](eventtime)
                 if g_dispatch is not self._g_dispatch:
                     self._end_greenlet(g_dispatch)
-                    eventtime = time.time()
+                    eventtime = self.monotonic()
                     break
         self._g_dispatch = None
 
@@ -172,16 +174,16 @@ class EPollReactor(SelectReactor):
     def _dispatch_loop(self):
         self._process = True
         self._g_dispatch = g_dispatch = greenlet.getcurrent()
-        eventtime = time.time()
+        eventtime = self.monotonic()
         while self._process:
             timeout = self._check_timers(eventtime)
             res = self._epoll.poll(timeout)
-            eventtime = time.time()
+            eventtime = self.monotonic()
             for fd, event in res:
                 self._fds[fd](eventtime)
                 if g_dispatch is not self._g_dispatch:
                     self._end_greenlet(g_dispatch)
-                    eventtime = time.time()
+                    eventtime = self.monotonic()
                     break
         self._g_dispatch = None
 
diff --git a/klippy/serialhdl.py b/klippy/serialhdl.py
index 143fd138..b943f2da 100644
--- a/klippy/serialhdl.py
+++ b/klippy/serialhdl.py
@@ -3,7 +3,7 @@
 # Copyright (C) 2016  Kevin O'Connor <kevin@koconnor.net>
 #
 # This file may be distributed under the terms of the GNU GPLv3 license.
-import time, logging, threading
+import logging, threading
 import serial
 
 import msgproto, chelper, util
@@ -60,7 +60,7 @@ class SerialReader:
         # Initial connection
         logging.info("Starting serial connect")
         while 1:
-            starttime = time.time()
+            starttime = self.reactor.monotonic()
             try:
                 self.ser = serial.Serial(self.serialport, self.baud, timeout=0)
             except OSError, e:
@@ -106,7 +106,7 @@ class SerialReader:
             est_clock = float(self.msgparser.config['CLOCK_FREQ'])
         self.serialqueue = self.ffi_lib.serialqueue_alloc(self.ser.fileno(), 1)
         self.est_clock = est_clock
-        self.last_ack_time = time.time()
+        self.last_ack_time = self.reactor.monotonic()
         self.last_ack_clock = 0
         self.ffi_lib.serialqueue_set_clock_est(
             self.serialqueue, self.est_clock, self.last_ack_time
@@ -232,7 +232,7 @@ class SerialRetryCommand:
         self.cmd = cmd
         self.name = name
         self.response = None
-        self.min_query_time = time.time()
+        self.min_query_time = self.serial.reactor.monotonic()
         self.serial.register_callback(self.handle_callback, self.name)
         self.send_timer = self.serial.reactor.register_timer(
             self.send_event, self.serial.reactor.NOW)
@@ -246,7 +246,7 @@ class SerialRetryCommand:
         if last_sent_time >= self.min_query_time:
             self.response = params
     def get_response(self):
-        eventtime = time.time()
+        eventtime = self.serial.reactor.monotonic()
         while self.response is None:
             eventtime = self.serial.reactor.pause(eventtime + 0.05)
         self.serial.unregister_callback(self.name)
@@ -267,7 +267,7 @@ class SerialBootStrap:
         self.send_timer = self.serial.reactor.register_timer(
             self.send_event, self.serial.reactor.NOW)
     def get_identify_data(self, timeout):
-        eventtime = time.time()
+        eventtime = self.serial.reactor.monotonic()
         while not self.is_done and eventtime <= timeout:
             eventtime = self.serial.reactor.pause(eventtime + 0.05)
         self.serial.unregister_callback('identify_response')
@@ -305,10 +305,10 @@ def stk500v2_leave(ser, reactor):
     ser.read(1)
     # Send stk500v2 leave programmer sequence
     ser.baudrate = 115200
-    reactor.pause(time.time() + 0.100)
+    reactor.pause(reactor.monotonic() + 0.100)
     ser.read(4096)
     ser.write('\x1b\x01\x00\x01\x0e\x11\x04')
-    reactor.pause(time.time() + 0.050)
+    reactor.pause(reactor.monotonic() + 0.050)
     res = ser.read(4096)
     logging.debug("Got %s from stk500v2" % (repr(res),))
     ser.baudrate = origbaud
diff --git a/klippy/serialqueue.c b/klippy/serialqueue.c
index 6cdd9f77..2286912a 100644
--- a/klippy/serialqueue.c
+++ b/klippy/serialqueue.c
@@ -23,7 +23,7 @@
 #include <termios.h> // tcflush
 #include <unistd.h> // pipe
 #include "list.h" // list_add_tail
-#include "pyhelper.h" // get_time
+#include "pyhelper.h" // get_monotonic
 #include "serialqueue.h" // struct queue_message
 
 
@@ -149,11 +149,11 @@ static void
 pollreactor_run(struct pollreactor *pr)
 {
     pr->must_exit = 0;
-    double eventtime = get_time();
+    double eventtime = get_monotonic();
     while (! pr->must_exit) {
         int timeout = pollreactor_check_timers(pr, eventtime);
         int ret = poll(pr->fds, pr->num_fds, timeout);
-        eventtime = get_time();
+        eventtime = get_monotonic();
         if (ret > 0) {
             int i;
             for (i=0; i<pr->num_fds; i++)
diff --git a/klippy/toolhead.py b/klippy/toolhead.py
index 3f039411..75ffe52b 100644
--- a/klippy/toolhead.py
+++ b/klippy/toolhead.py
@@ -3,7 +3,7 @@
 # Copyright (C) 2016  Kevin O'Connor <kevin@koconnor.net>
 #
 # This file may be distributed under the terms of the GNU GPLv3 license.
-import math, logging, time
+import math, logging
 import cartesian, delta, extruder
 
 # Common suffixes: _d is distance (in mm), _v is velocity (in
@@ -210,7 +210,7 @@ class ToolHead:
     def get_next_move_time(self):
         if not self.print_time:
             self.print_time = self.buffer_time_low + STALL_TIME
-            curtime = time.time()
+            curtime = self.reactor.monotonic()
             self.printer.mcu.set_print_start_time(curtime)
             self.reactor.update_timer(self.flush_timer, self.reactor.NOW)
         return self.print_time
@@ -224,15 +224,16 @@ class ToolHead:
         self.printer.mcu.flush_moves(self.print_time)
         self.print_time = 0.
         self.need_check_stall = -1.
-        self.reset_motor_off_time(time.time())
+        self.reset_motor_off_time(self.reactor.monotonic())
         self.reactor.update_timer(self.flush_timer, self.motor_off_time)
     def _check_stall(self):
         if not self.print_time:
             # XXX - find better way to flush initial move_queue items
             if self.move_queue.queue:
-                self.reactor.update_timer(self.flush_timer, time.time() + 0.100)
+                self.reactor.update_timer(
+                    self.flush_timer, self.reactor.monotonic() + 0.100)
             return
-        eventtime = time.time()
+        eventtime = self.reactor.monotonic()
         while 1:
             buffer_time = self.printer.mcu.get_print_buffer_time(
                 eventtime, self.print_time)
@@ -310,7 +311,7 @@ class ToolHead:
         logging.debug('; Max time of %f' % (last_move_time,))
     def wait_moves(self):
         self.move_queue.flush()
-        eventtime = time.time()
+        eventtime = self.reactor.monotonic()
         while self.print_time:
             eventtime = self.reactor.pause(eventtime + 0.100)
     def query_endstops(self):