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>

3 files changed, 58 insertions, 6 deletions

diff --git a/docs/Code_Overview.md b/docs/Code_Overview.md
index 1522c60b..207b37f4 100644
--- a/docs/Code_Overview.md
+++ b/docs/Code_Overview.md
@@ -98,9 +98,11 @@ printer object calls, which frequently translate the actions to
 commands to be executed on the micro-controller (as declared via the
 DECL_COMMAND macro in the micro-controller code).
 
-There are three threads in the Klippy host code. The main thread
+There are four threads in the Klippy host code. The main thread
 handles incoming gcode commands. A second thread (which resides
 entirely in the **klippy/serialqueue.c** C code) handles low-level IO
 with the serial port. The third thread is used to process response
 messages from the micro-controller in the Python code (see
-**klippy/serialhdl.py**).
+**klippy/serialhdl.py**). The fourth thread writes debug messages to
+the log (see **klippy/queuelogger.py**) so that the other threads
+never block on log writes.
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