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...
The built-in python logger is I/O blocking. This means that using the built-in logging module will interfere with your asynchronous application performance. aiologger aims to be the standard Asynchronous non-blocking logging for python and asyncio.
It will slow down your application (obviously) but it depends a lot on your application if the slow down qualifies as "serious". I think you need to let it run and then decide if the performance is acceptable... Show activity on this post.
The multiprocessing module has its own logger with the name “multiprocessing“. This logger is used within objects and functions within the multiprocessing module to log messages, such as debug messages that processes are running or have shutdown. We can get this logger and use it for logging.
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.
As hasan has proposed, async log handler can be the way to go.
Recently I have tried using Logbook
and can say, it will provide you all what you need for this - ZeroMQHandler as well as ZeroMQSubscriber
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With