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

Gerlando Falauto

unread,

Jul 14, 2018, 9:56:05 AM7/14/18

to

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("---")

dieter

unread,

Jul 16, 2018, 12:56:19 AM7/16/18

to

Gerlando Falauto <gerlando...@gmail.com> writes:
> ...

> 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).

Maybe, you look at the source code of "listener.stop"?

Gerlando Falauto

unread,

Jul 16, 2018, 1:39:17 AM7/16/18

to

On Monday, July 16, 2018 at 6:56:19 AM UTC+2, dieter wrote:
> > ...
> > 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).
>
> Maybe, you look at the source code of "listener.stop"?

I did, forgot to mention that. Culprit is self._thread.join().
Which is where it waits for the internal thread to terminate,
which I would've expected to wait on a lock or semaphore (pthread_join()?)
So there's something I'm totally missing here, which has more to do
with queues and threads in general than it has with logging.
Any ideas?

Thomas Jollans

unread,

Jul 16, 2018, 2:13:46 AM7/16/18

to

I have no idea what's really going on there, but a quick look through
the source reveals that the actual waiting in Thread.join() is done by
sem_wait().

via
https://github.com/python/cpython/blob/13ff24582c99dfb439b1af7295b401415e7eb05b/Python/thread_pthread.h#L304
via
https://github.com/python/cpython/blob/master/Modules/_threadmodule.c#L45
via
https://github.com/python/cpython/blob/master/Modules/_threadmodule.c#L136
via https://github.com/python/cpython/blob/master/Lib/threading.py#L1000

Gerlando Falauto

unread,

Jul 16, 2018, 2:24:53 AM7/16/18

to

On Monday, July 16, 2018 at 8:13:46 AM UTC+2, Thomas Jollans wrote:
> On 16/07/18 07:39, Gerlando Falauto wrote:
> > On Monday, July 16, 2018 at 6:56:19 AM UTC+2, dieter wrote:
> >>> ...
> >>> 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).
> >>
> >> Maybe, you look at the source code of "listener.stop"?
> >
> > I did, forgot to mention that. Culprit is self._thread.join().
> > Which is where it waits for the internal thread to terminate,
> > which I would've expected to wait on a lock or semaphore (pthread_join()?)
> > So there's something I'm totally missing here, which has more to do
> > with queues and threads in general than it has with logging.
> > Any ideas?
> >
>
> I have no idea what's really going on there, but a quick look through
> the source reveals that the actual waiting in Thread.join() is done by
> sem_wait().
>
> via
> https://github.com/python/cpython/blob/13ff24582c99dfb439b1af7295b401415e7eb05b/Python/thread_pthread.h#L304
> via
> https://github.com/python/cpython/blob/master/Modules/_threadmodule.c#L45

Hmm... do you think it's possible it's really getting interrupted the whole time, effectively turning the lock into a sort of spinlock?
Any idea how to confirm that without recompiling the whole code?

Thomas Jollans

unread,

Jul 16, 2018, 2:35:57 AM7/16/18

to

Profiling, maybe? Or you might be able to find out if it's being
interrupted by listening for signals yourself (though I'm not sure which
one(s))?

Cameron Simpson

unread,

Jul 16, 2018, 4:00:51 AM7/16/18

to

On 16Jul2018 08:33, Thomas Jollans <tj...@tjol.eu> wrote:
>On 16/07/18 08:24, Gerlando Falauto wrote:
>> On Monday, July 16, 2018 at 8:13:46 AM UTC+2, Thomas Jollans wrote:
>>> On 16/07/18 07:39, Gerlando Falauto wrote:
>>>> On Monday, July 16, 2018 at 6:56:19 AM UTC+2, dieter wrote:
>>>>>> ...
>>>>>> 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).

Presuming you're using Linux on the Pi, the strace command will show you
exactly what system calls the processis making. A real spin lock situation will
be very apparent. 100% CPU with no system calls means a busy wait (polling).

Strace is an outstandingly useful and often overlooked tool for debugging
otherwise opaque behaviour.

Cheers,
Cameron Simpson <c...@cskk.id.au>