Python logging causing latencies?

Question

I'm developing a real-time REST API using Python3+bottle/UWSGI. I was experiencing latencies in my code, sometimes 100s of ms, which does matter in my app.

Using logging module, I was trying to identify slow parts of my code, printing how long individual codeblocks took to run. I know this is an extremely poor way of profiling the code, but sometimes it is able to do the job quite well.

Even though I identified some slow parts, I was still missing something -- the individual parts seemed to take 10s of ms, but very often they took 100s of ms as the whole. After some increasingly insane experiments which drove me almost completely nuts, I've come to the following:

t = round(100*time.time())
logging.info('[%s] Foo' % t)
logging.info('[%s] Bar' % t)

Surprisingly, it gives:

2014-07-16 23:21:23,531  [140554568353] Foo
2014-07-16 23:21:24,312  [140554568353] Bar

Even though this seems hard to believe, there are two consequent logging.info() calls, and for some reason, there is a gap of almost 800 ms between them. Can anybody tell me what is going on? It is noteworthy that if there are multiple info() calls, the latency only appears once in the whole API method, most frequently at its very beginning (after first call). My only hypothesis are disk latencies, there are several (but not so many!) workers running simultaneously and I'm using rotational disk, no SSD. But I thought there are buffers and that the OS will do the disk-flush asynchronously for me. Am I wrong in my assumptions? Should I avoid logging completely to avoid the latencies?

EDIT

Based on Vinay Sajip's suggestion, I switched to the following initialization code:

log_que = queue.Queue(-1)
queue_handler = logging.handlers.QueueHandler(log_que)
log_handler = logging.StreamHandler()
queue_listener = logging.handlers.QueueListener(log_que, log_handler)
queue_listener.start()
logging.basicConfig(level=logging.DEBUG, format="%(asctime)s  %(message)s", handlers=[queue_handler])

It seems like it works fine (if I comment queue_listener.start(), there is no output), but the very same latencies still appear. I don't see how is it even possible, the call should be non-blocking. I also put gc.collect() at the end of each request to ensure the problem is not caused by the garbage collector -- without any effect. I've also tried to turn off the logging for the whole day. The latencies disappeared, so I think their source must be in the logging module...

Answer 1

You can use asynchronous handlers (QueueHandler and corresponding QueueListener, added in Python 3.2, and described in this post) and do the I/O processing of your logging events in a separate thread or process.