title: python logging performance comparison and options
body: <p>I am researching high performance logging in Python and so far have been disappointed by the performance of the python standard logging module - but there seem to be no alternatives. Below is a piece of code to performance test 4 different ways of logging:</p>
  
  <pre><code>import logging
  import timeit
  import time
  import datetime
  from logutils.queue import QueueListener, QueueHandler
  import Queue
  import threading
  
  tmpq = Queue.Queue()
  
  def std_manual_threading():
      start = datetime.datetime.now()
      logger = logging.getLogger()
      hdlr = logging.FileHandler('std_manual.out', 'w')
      logger.addHandler(hdlr)
      logger.setLevel(logging.DEBUG)
      def logger_thread(f):
          while True:
              item = tmpq.get(0.1)
              if item == None:
                  break
              logging.info(item)
      f = open('manual.out', 'w')
      lt = threading.Thread(target=logger_thread, args=(f,))
      lt.start()
      for i in range(100000):
          tmpq.put("msg:%d" % i)
      tmpq.put(None)
      lt.join()
      print datetime.datetime.now() - start
  
  def nonstd_manual_threading():
      start = datetime.datetime.now()
      def logger_thread(f):
          while True:
              item = tmpq.get(0.1)
              if item == None:
                  break
              f.write(item+"\n")
      f = open('manual.out', 'w')
      lt = threading.Thread(target=logger_thread, args=(f,))
      lt.start()
      for i in range(100000):
          tmpq.put("msg:%d" % i)
      tmpq.put(None)
      lt.join()
      print datetime.datetime.now() - start
  
  
  def std_logging_queue_handler():
      start = datetime.datetime.now()
      q = Queue.Queue(-1)
  
      logger = logging.getLogger()
      hdlr = logging.FileHandler('qtest.out', 'w')
      ql = QueueListener(q, hdlr)
  
  
      # Create log and set handler to queue handle
      root = logging.getLogger()
      root.setLevel(logging.DEBUG) # Log level = DEBUG
      qh = QueueHandler(q)
      root.addHandler(qh)
  
      ql.start()
  
      for i in range(100000):
          logging.info("msg:%d" % i)
      ql.stop()
      print datetime.datetime.now() - start
  
  def std_logging_single_thread():
      start = datetime.datetime.now()
      logger = logging.getLogger()
      hdlr = logging.FileHandler('test.out', 'w')
      logger.addHandler(hdlr)
      logger.setLevel(logging.DEBUG)
      for i in range(100000):
          logging.info("msg:%d" % i)
      print datetime.datetime.now() - start
  
  if __name__ == "__main__":
      """
      Conclusion: std logging about 3 times slower so for 100K lines simple file write is ~1 sec while std
      logging ~3. If threads are introduced some overhead causes to go to ~4 and if QueueListener and events
      are used with enhancement for thread sleeping that goes to ~5 (probably because log records are being
      inserted into queue).
      """
      print "Testing"
      #std_logging_single_thread() # 3.4
      std_logging_queue_handler() # 7, 6, 7 (5 seconds with sleep optimization)
      #nonstd_manual_threading() # 1.08
      #std_manual_threading() # 4.3
  </code></pre>
  
  <ol>
  <li>The nonstd_manual_threading option works best since there is no overhead of the logging module but obviously you miss out on a lot of features such as formatters, filters and the nice interface</li>
  <li>The std_logging in a single thread is the next best thing but still about 3 times slower than nonstd manual threading. </li>
  <li>The std_manual_threading option dumps messages into a threadsafe queue and in a separate thread uses the standard logging module. That comes out to be about 25% higher than option 2, probably due to context switching costs.</li>
  <li>Finally, the option using "logutils"'s QueueHandler comes out to be the most expensive. I tweaked the code of logutils/queue.py's _monitor method to sleep for 10 millis after processing 500 messages as long as there are less than 100K messages in the queue. That brings the runtime down from 7 seconds to 5 seconds (probably due to avoiding context switching costs).</li>
  </ol>
  
  <p>My question is, why is there so much performance overhead with the logging module and are there any alternatives? Being a performance sensitive app does it even make sense to use the logging module?</p>
  
  <p>p.s.: I have profiled the different scenarios and seems like LogRecord creation is expensive.</p>