Python 3 Logging: QueueListener + SocketHandler, really slow to clear queue the 1st time

Viewed 601

In my Python 3 code I have a logger set up like this:

class TmpQListener(logging.handlers.QueueListener):
    def dequeue(self, block):
        print('QSIZE : ' + str(self.queue.qsize())) # only change to the QueueListener
        return self.queue.get(block)

log_q = queue.Queue(-1) # unlimited size
logger = logging.getLogger('TestLogger')
socket_handler = logging.handlers.SocketHandler('localhost', 1337)
q_handler = logging.handlers.QueueHandler(log_q)
q_listener = TmpQListener(log_q, socket_handler)
logger.addHandler(q_handler)
q_listener.start()

When I run my program (the server that receives the log messages is already up and running) the queue will fill up quite fast. It's only removing (i.e. sending) 2-3 messages from the queue for every 20-30 messages added to it. My memory will gradually fill up, making the program slower and slower, until my RAM is basically full at which point the program slows down to a crawl and tries to clear the entire queue at once (i.e. sends everything). If it doesn't manage to clear everything fast enough (for whatever reason) it will continue to be slow until the program finishes. If it does manage to clear the queue and send what's basically a few GBs of LogRecords at this point it will speed up again and work as I would expect it to, meaning from this point onwards it will send all messages as soon as they're added to the queue without affecting performance.

Since this probably isn't intended behavior I assume I'm doing something wrong.

It is worth mentioning that I'm using the LogRecord's 'extra' arguement to send lists along with some of my LogRecords. Those logging calls look like this:

logger.info("PROX_MARKER", extra={'vector': [some_list]})

where some_list is a list of several thousand double values making the LogRecord pretty big in size. I realize that this isn't exactly what logging calls are for, however I don't see how this is an issue seeing how it works perfectly fine if the program manages to clear the initial build-up of messages.

I've looked at the code of the SocketHandler/QueueHandler/QueueListener and can't find anything that would explain this behavior. In my original code I use a custom SocketHandler that serializes the log records. I've replaced that with the default SocketHandler but the result was the same. Now I'm all out of ideas.

Any hints on how to fix this are greatly appreciated.

1 Answers

My post may be too late. From your question, the queue capacity was set unlimited and the memory consumption was increasing, then it may be that the queue listening was unable to clear as fast as the log producer. It might be due to slow network connection, remote socket end could not clear log messages fast enoguh.

Possible solution are

  1. Set a reasonable queue limit and monitor the unprocessed queue size. For your case, try to get a reasonable value and set your queue to this number, instead of no limit.

  2. Review your log message generators, comment out unnecessary log messages from being generated. Monotor the unprocessed queue size and resize it based on this tuning.

  3. Could consider to use MemoryHandler. It is for you to buffer relevant log messages and send at one go if there are errors at the end.

  4. Set debug level to higher value.

Related