Issue #131: handle log msgs thread safe using a queue

Multiple threads can log at the same time. By default Python's logging
system uses a lock to protect the shared resources for each handler.

But this may generate a lot of contention on the lock if there are a lot
of messages to be handled. More over the handling of the message writes
it to disk/console which it is slow.

Instead a QueueHandler is used to receive the messages and pass them to
the QueueListener using a thread-safe queue.

The listener sends the messages to the original handler (XStreamHandler)
in background without blocking the rest of the threads.

byexample/byexample.py

@@ -9,7 +9,7 @@
 
 from .cache import RegexCache
 from .jobs import Jobs, Status
-from .log import init_log_system
+from .log import init_log_system, shutdown_log_system
 
 
 def execute_examples(filename, harvester, executor, dry):
@@ -55,6 +55,9 @@ def main(args=None):
             sys.exit(Status.error)
 
         jobs = Jobs(args.jobs)
-        return jobs.run(
+        ret = jobs.run(
             execute_examples, testfiles, cfg['options']['fail_fast'], cfg
         )
+
+        shutdown_log_system()
+        return ret

byexample/log.py

@@ -1,5 +1,5 @@
 from logging import Formatter, Logger, getLogger
-import sys, logging
+import sys, logging, logging.handlers, queue
 import contextlib
 
 from .common import colored, highlight_syntax, indent
@@ -252,6 +252,11 @@ def release(self):
         return
 
 
+class XQueueHandler(logging.handlers.QueueHandler):
+    def prepare(self, record):
+        return record
+
+
 def init_log_system(level=NOTE, use_colors=False):
     global _logger_stack
 
@@ -273,8 +278,13 @@ def init_log_system(level=NOTE, use_colors=False):
     fmtter = XFormatter('%(message)s')
     ch.setFormatter(fmtter)
 
-    rlog.addHandler(ch)
+    q = queue.Queue()
+    qh = XQueueHandler(q)
+    ql = logging.handlers.QueueListener(q, ch)
+
+    rlog.addHandler(qh)
     rlog.xstream_handler = ch
+    rlog.bg_queue_listener = ql
 
     # Set up the global logger.
     # Activate and deactivate sub loggers using log_context
@@ -286,6 +296,9 @@ def init_log_system(level=NOTE, use_colors=False):
     configure_log_system(default_level=level, use_colors=use_colors)
     rlog.xstream_handler.concerns = None
 
+    # start forwarding the messages
+    rlog.bg_queue_listener.start()
+
 
 def configure_log_system(default_level=None, use_colors=None, concerns=None):
     rlog = getLogger(name='byexample')  # root
@@ -310,3 +323,8 @@ def setLogLevels(levels):
         l.setLevel(lvl)
 
     return prev_lvls
+
+
+def shutdown_log_system():
+    rlog = getLogger(name='byexample')  # root
+    rlog.bg_queue_listener.stop()