From 20d0936fa256e0caa41a18a79556c8ade3f8347f Mon Sep 17 00:00:00 2001
From: Kevin O'Connor <kevin@koconnor.net>
Date: Mon, 6 Feb 2017 13:31:34 -0500
Subject: [PATCH] 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>
---
 klippy/chelper.py    |  1 +
 klippy/gcode.py      |  4 ++--
 klippy/klippy.py     |  6 +++++-
 klippy/mcu.py        | 14 ++++++++------
 klippy/pyhelper.c    | 17 ++++++++++-------
 klippy/pyhelper.h    |  2 +-
 klippy/reactor.py    | 24 +++++++++++++-----------
 klippy/serialhdl.py  | 16 ++++++++--------
 klippy/serialqueue.c |  6 +++---
 klippy/toolhead.py   | 13 +++++++------
 10 files changed, 58 insertions(+), 45 deletions(-)

diff --git a/klippy/chelper.py b/klippy/chelper.py
index b7baf0610..ed4944566 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 407390e19..8b33e26a7 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 517bdf225..eac85829b 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 4fadc13dd..f6a217466 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 2716b9b7d..410fd764e 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 bca65fd29..1042214b4 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 1adf09a8d..1fd8426ab 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 143fd138e..b943f2dab 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 6cdd9f777..2286912a7 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 3f0394114..75ffe52ba 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):