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>
This commit is contained in:
Kevin O'Connor 2016-11-11 20:22:39 -05:00
parent afecf7ce36
commit 1dee1ba64e
3 changed files with 58 additions and 6 deletions

View File

@ -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.

View File

@ -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()

48
klippy/queuelogger.py Normal file
View File

@ -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