queuelogger: Add support for background log writing

Writing to the debug log can cause an unbounded delay due to disk IO.
This is particularly so on embedded machines such as the Raspberry Pi
that run on SD cards.  These log writing delays can cause problems for
the main processing threads.

The new "queuelogger" code forwards all the main thread log messages
to a queue, and a background thread writes the log messages from the
queue to the destination file.  This eliminates the IO delay from the
main threads.

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

2 files changed, 54 insertions, 4 deletions

diff --git a/klippy/klippy.py b/klippy/klippy.py
index cb81364e..6668ef4c 100644
--- a/klippy/klippy.py
+++ b/klippy/klippy.py
@@ -5,7 +5,7 @@
 #
 # This file may be distributed under the terms of the GNU GPLv3 license.
 import sys, optparse, ConfigParser, logging, time, threading
-import gcode, toolhead, util, mcu, fan, heater, extruder, reactor
+import gcode, toolhead, util, mcu, fan, heater, extruder, reactor, queuelogger
 
 class ConfigWrapper:
     def __init__(self, printer, section):
@@ -132,7 +132,7 @@ def main():
         opts.error("Incorrect number of arguments")
     conffile = args[0]
 
-    debuginput = debugoutput = None
+    debuginput = debugoutput = bglogger = None
 
     debuglevel = logging.INFO
     if options.verbose:
@@ -142,8 +142,7 @@ def main():
     if options.outputfile:
         debugoutput = open(options.outputfile, 'wb')
     if options.logfile:
-        logoutput = open(options.logfile, 'wb')
-        logging.basicConfig(stream=logoutput, level=debuglevel)
+        bglogger = queuelogger.setup_bg_logging(options.logfile, debuglevel)
     else:
         logging.basicConfig(level=debuglevel)
     logging.info("Starting Klippy...")
@@ -159,5 +158,8 @@ def main():
         store_dictionary(options.write_dictionary, printer)
     printer.run()
 
+    if bglogger is not None:
+        bglogger.stop()
+
 if __name__ == '__main__':
     main()
diff --git a/klippy/queuelogger.py b/klippy/queuelogger.py
new file mode 100644
index 00000000..8494c6a8
--- /dev/null
+++ b/klippy/queuelogger.py
@@ -0,0 +1,48 @@
+# Code to implement asynchronous logging from a background thread
+#
+# Copyright (C) 2016  Kevin O'Connor <kevin@koconnor.net>
+#
+# This file may be distributed under the terms of the GNU GPLv3 license.
+import logging, threading, Queue
+
+# Class to forward all messages through a queue to a background thread
+class QueueHandler(logging.Handler):
+    def __init__(self, queue):
+        logging.Handler.__init__(self)
+        self.queue = queue
+    def emit(self, record):
+        try:
+            self.format(record)
+            record.msg = record.message
+            record.args = None
+            record.exc_info = None
+            self.queue.put_nowait(record)
+        except Exception:
+            self.handleError(record)
+
+# Class to poll a queue in a background thread and log each message
+class QueueListener(object):
+    def __init__(self, handler):
+        self.handler = handler
+        self.queue = Queue.Queue()
+        self.thread = threading.Thread(target=self._bg_thread)
+        self.thread.start()
+    def _bg_thread(self):
+        while 1:
+            record = self.queue.get(True)
+            if record is None:
+                break
+            self.handler.handle(record)
+    def stop(self):
+        self.queue.put_nowait(None)
+        self.thread.join()
+
+def setup_bg_logging(filename, debuglevel):
+    logoutput = open(filename, 'wb')
+    handler = logging.StreamHandler(logoutput)
+    ql = QueueListener(handler)
+    qh = QueueHandler(ql.queue)
+    root = logging.getLogger()
+    root.addHandler(qh)
+    root.setLevel(debuglevel)
+    return ql