logging from time critical tasks -- QueueListener().stop() takes the whole CPU

[Gerlando Falauto]

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("---")
-- 
https://mail.python.org/mailman/listinfo/python-list