logging from time critical tasks -- QueueListener().stop() takes the whole CPU
Gerlando Falauto
gerlando.falauto at gmail.com
Sat Jul 14 09:55:52 EDT 2018
Hi,
I'm adding logging to a time critical task running resource-constrained hardware (Raspberry Pi).
I read about the QueueListener/QueueHandler in:
https://docs.python.org/3/howto/logging-cookbook.html#dealing-with-handlers-that-block
and I'm trying to understand how it really works and what's happening under the hood, and what the impact would be.
So I wrote a test program (here at the bottom) that logs 500000 times and then waits for the listener to terminate. I ran it on a PC:
$ python3 logtest.py 0
PID= 5974
[ 0.000] Logging like crazy 500000 times with que = queue.Queue
[ 18.038] Done logging, waiting for completion
[ 37.824] Test finished
---
Here's the output while it's logging (within the first 18 seconds):
$ ps um -L 5974
USER PID LWP %CPU NLWP %MEM VSZ RSS TTY STAT START TIME COMMAND
iurly 5974 - 96.3 2 2.1 264232 170892 pts/2 - 15:30 0:07 python3 logtest.py 0
iurly - 5974 72.8 - - - - - Rl+ 15:30 0:05 -
iurly - 5975 23.3 - - - - - Sl+ 15:30 0:01 -
So the main thread is taking most of the CPU while the background thread is writing to disk, and that's reasonable.
However, as soon as I start waiting for the logger terminate, I get something like this:
$ ps um -L 5974
USER PID LWP %CPU NLWP %MEM VSZ RSS TTY STAT START TIME COMMAND
iurly 5974 - 100 2 3.9 406724 313588 pts/2 - 15:30 0:31 python3 logtest.py 0
iurly - 5974 45.2 - - - - - Sl+ 15:30 0:14 -
iurly - 5975 54.8 - - - - - Rl+ 15:30 0:17 -
Why is the main thread taking up so much CPU?
I believe at this point listener.stop() should only be waiting for the helper thread to terminate, which I reckon would be implemented by waiting on a semaphore or something (i.e. iowait i.e. 0% CPU).
Thank you,
Gerlando
RANGE=500000
import logging
import logging.handlers
import multiprocessing as mp
import queue
import time
import gc
import sys
import os
if len(sys.argv) > 1:
testlist = [int(q) for q in sys.argv[1:]]
else:
print ("no test list given, defaulting to 0 1 0 1")
testlist = [0, 1, 0, 1]
print("PID=", os.getpid())
for i, qtype in enumerate(testlist):
handlers = []
if qtype == 0:
que = queue.Queue(-1)
qstring = "queue.Queue"
else:
que = mp.Queue(-1)
qstring = "mp.Queue"
handlers.append(logging.handlers.RotatingFileHandler("test%d.log" % (i), maxBytes=100000, backupCount=5))
#handlers.append(logging.lastResort)
listener = logging.handlers.QueueListener(que, *handlers)
formatter = logging.Formatter('%(asctime)s:%(threadName)s: %(message)s')
for handler in handlers:
handler.setFormatter(formatter)
listener.start()
queue_handler = logging.handlers.QueueHandler(que)
logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
logger.addHandler(queue_handler)
start = time.time()
print("[%7.03f] Logging like crazy %d times with que = %s" % (time.time()-start, RANGE, qstring))
for i in range(0,RANGE):
logger.info("AAAAAA")
if i % 2000 == 0:
print(i, "/", RANGE, end='\r')
print("[%7.03f] Done logging, waiting for completion" % (time.time() - start))
listener.stop()
print("[%7.03f] Test finished" % (time.time() - start))
gc.collect()
print("---")
More information about the Python-list
mailing list