After some time of regular querying (~hours), libgpiod_pulsein starts using 100% CPU and subsequent readings fail

[michaellass]

Reported by @darton in #47 (comment) and adafruit/Adafruit_Blinka#210 (comment):

The problem with 100% usage of libgpiod_pulsein CPU on Raspberry Pi with DHT22 still exists.

However, sometimes you have to wait several hours for it to appear and permanently prevent reading data from the DHT22 sensor.

After today's update to the version below, the script runs 8 hours without any problems.

Raspbian GNU/Linux 10 (buster)
Raspberry Pi 3 Model B Plus Rev 1.3
Python 3.7.3
Adafruit-Blinka-5.3.4
Adafruit-PlatformDetect-2.16
Adafruit-PureIO-1.1.5 RPi.GPIO-0.7.0
adafruit-circuitpython-dht-3.5.1
pyftdi-0.51.2 pyserial-3.4 pyusb-1.0.2
rpi-ws281x-4.2.4 sysv-ipc-1.0.1

But after 8 hours, the problem came back.

[michaellass]

@darton Did I describe your issue correctly with the title of this bug report? I have never tested such a use-case. If I understand correctly, something like the following should reproduce your issue?

#!/usr/bin/env python3

import adafruit_dht
import board
import sys
import time

pin = board.D2 # adjust to correct PIN
dht_device = adafruit_dht.DHT22(pin)

# With Adafruit_CircuitPython_DHT 3.5.1 the CPU will now just idle until it's actually used

# During this sleep libgpiod_pulsein will start taking 100% CPU
time.sleep(12 * 3600) # Sleep for 12 hours

# ... and subsequent readings will fail:
try:
    temperature = dht_device.temperature
    humidity = dht_device.humidity
except RuntimeError:
    print("Error while getting sensor data")
    sys.exit(1)

print("Temp: {}, Humid: {}", temperature, humidity)

[darton]

I read the sensor every 5 seconds. Problems begin after a few hours, but sometimes much earlier, e.g. 30 minutes, 1 hour.

[darton]

The DHT22 sensor is connected to the Raspberry Pi using a 50 cm shielded cable

[michaellass]

Thanks for the clarification. Unfortunately that means that I probably won't be able to reproduce your issue here. I am querying my sensor every minute for months now without any similar issue. Possible differences between our setups:

• 5 seconds vs 1 minute interval
• different cabling (here: 10cm unshielded, your setup: 50cm shielded)
• maybe different CPU loads (mine is basically idle)

Are you willing to invest some effort into debugging this? If so, please follow the following steps and post the output created by the final gdb command:

apt install gdb git build-essential libgpiod-dev

git clone https://github.com/adafruit/libgpiod_pulsein.git
cd libgpiod_pulsein/src

# modify Makefile: Add " -g" at the end of line 2 (defining CFLAGS). Then run:
make

# While your sensor polling script is running, figure out where libgpiod_pulsein is installed:
ls -lad /proc/$(pidof libgpiod_pulsein)/exe
# result may be sth like /home/youruser/.local/lib/python3.7/site-packages/adafruit_blinka/microcontroller/bcm283x/pulseio/libgpiod_pulsein
# or something in /usr/local/...

# Stop your sensor polling script. Then:
cp libgpiod_pulsein WHEREVER_YOUR_libgpiod_pulsein_IS_LOCATED

# Start your polling script again. Wait until it starts to consume 100% CPU and stops returning any sensible information. Then run:
gdb attach $(pidof libgpiod_pulsein) -ex "thread apply all bt" -ex "detach" -ex "quit"

The output of the final gdb command should be very helpful in debugging this. Maybe run the last command multiple times to see if it gives you different outputs. Then all of those might be of interest.

[darton]

sudo gdb attach $(pidof libgpiod_pulsein) -ex "thread apply all bt" -ex "detach" -ex "quit"
GNU gdb (Raspbian 8.2.1-2) 8.2.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "arm-linux-gnueabihf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
http://www.gnu.org/software/gdb/bugs/.
Find the GDB manual and other documentation resources online at:
http://www.gnu.org/software/gdb/documentation/.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
attach: No such file or directory.
Attaching to process 19266
[New LWP 19267]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
__libc_msgrcv (msgflg=1, msgtyp=1, msgsz=4095, msgp=0x7ed47bbc, msqid=163840) at ../sysdeps/unix/sysv/linux/msgrcv.c:28
28 ../sysdeps/unix/sysv/linux/msgrcv.c: No such file or directory.

Thread 2 (Thread 0x76d93460 (LWP 19267)):
#0 __lll_lock_wait (futex=futex@entry=0x24084 , private=0) at lowlevellock.c:46
#1 0x76eeaf44 in __GI___pthread_mutex_lock (mutex=0x24084 ) at pthread_mutex_lock.c:80
#2 0x000116dc in polling_thread_runner ()
#3 0x76f77968 in __pointer_chk_guard () from /lib/ld-linux-armhf.so.3
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 1 (Thread 0x76f76450 (LWP 19266)):
#0 __libc_msgrcv (msgflg=1, msgtyp=1, msgsz=4095, msgp=0x7ed47bbc, msqid=163840) at ../sysdeps/unix/sysv/linux/msgrcv.c:28
#1 __libc_msgrcv (msqid=163840, msgp=0x7ed47bbc, msgsz=4095, msgtyp=1, msgflg=0) at ../sysdeps/unix/sysv/linux/msgrcv.c:24
#2 0x00010f28 in main ()
Detaching from program: /home/pi/.local/lib/python3.7/site-packages/adafruit_blinka/microcontroller/bcm283x/pulseio/libgpiod_pulsein, process 19266
[Inferior 1 (process 19266) detached]

[darton]

19266 pi 20 0 10324 428 316 R 100.0 0.0 81:55.23 libgpiod_pulsei

[michaellass]

Thread 2 (Thread 0x76d93460 (LWP 19267)):
#0 __lll_lock_wait (futex=futex@entry=0x24084 , private=0) at lowlevellock.c:46
#1 0x76eeaf44 in __GI___pthread_mutex_lock (mutex=0x24084 ) at pthread_mutex_lock.c:80
#2 0x000116dc in polling_thread_runner ()

Looks like some of the steps above did not really work out as we are not getting the exact code position in libgpiod_pulsein.c here. However, It's very likely this one: https://github.com/adafruit/libgpiod_pulsein/blob/master/src/libgpiod_pulsein.c#L477. If not, it's https://github.com/adafruit/libgpiod_pulsein/blob/master/src/libgpiod_pulsein.c#L525.

#3 0x76f77968 in __pointer_chk_guard () from /lib/ld-linux-armhf.so.3
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 1 (Thread 0x76f76450 (LWP 19266)):
#0 __libc_msgrcv (msgflg=1, msgtyp=1, msgsz=4095, msgp=0x7ed47bbc, msqid=163840) at ../sysdeps/unix/sysv/linux/msgrcv.c:28
#1 __libc_msgrcv (msqid=163840, msgp=0x7ed47bbc, msgsz=4095, msgtyp=1, msgflg=0) at ../sysdeps/unix/sysv/linux/msgrcv.c:24
#2 0x00010f28 in main ()

Apart from the missing line numbers this looks exactly how it should look like:

• Thread 1 is currently in __libc_msgrcv, waiting for a message via IPC from python. This should be a blocking call and therefore it should not consume any CPU. [Side note: I'm note sure why #0 shows the same call as #1 but with a different order of arguments and in particular with msgflg=1. However, this is what I see here as well with 0% CPU use.]
• Thread 2 is somewhere within pthread_mutex_lock which is blocking as well, i.e. it should consume no CPU. We are not in one of the pthread_mutex_trylock here which would have explained the CPU usage.

To be honest I'm lacking a good explanation for the CPU consumption you are seeing. It could be that the message queue becomes invalid, such that msgrcv becomes non-blocking. I have to think about this and will try to come up with some debugging strategy...

[michaellass]

To check whether the msgrcv is the culprit here, could you please run the following commands whenever your script is misbehaving (i.e., showing 100% CPU)?

sudo apt install strace
strace -f -p $(pidof libgpiod_pulsein)

You can simply abort the strace after a short amount of time with Ctrl+C. Normally, the output should look something like this:

strace: Process 731 attached with 2 threads
[pid   732] futex(0x24084, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid   731] msgrcv(0,

I would assume that in your case you get lots of lines printed in a short amount of time. Can you please post your output here?

[Krakatomi]

Hi. I got this:
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 4402] msgrcv(0, 0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
^C0xbeef8bac, 4095, 1, 0) = -1 EINVAL (Invalid argument)
strace: Process 4402 detached
strace: Process 4403 detached

[michaellass]

@Kraka23 Thanks, that helps a lot!

[Krakatomi]

Your welcome!. You are helping us a lot too!

[michaellass]

I still cannot provoke this behavior, so I need some help again. Could you please run the following commands while libgpiod_pulsein is stuck at 100% CPU?

cat /proc/$(pidof libgpiod_pulsein)/cmdline
strace -f -p $(pidof libgpiod_pulsein) # exactly like in your last post but it is important to re-run it here
ipcs -q
lsipc

A couple of technical details on where we are right now:

• The 100% CPU use is caused by the fact that msgrcv returns an error and therefore becomes non-blocking
• The returned error is EINVAL, which according to msgop(2) can happen in one of these cases:
  • msqid was invalid
  • msgsz was less than 0
  • msgflg specified MSG_COPY, but not IPC_NOWAIT
  • msgflg specified both MSG_COPY and MSG_EXCEPT
• Since msgflg=0 and msgsz=4095>=0, this basically only leaves the option that msqid for some reason becomes invalid at some point in time.
• However: If the message queue was actually removed, the python script would abort with an Exception as soon as it tries to write to the message queue. Nothing like this has been reported here so far.
• Steps above will allow us to see what magic key the message queue uses, if the queue still exists, if so, what the corresponding msqid is and whether libgpiod_pulsein tries to access the queue using the correct msqid.

[Krakatomi]

No problem. Here we go:

cat /proc/$(pidof libgpiod_pulsein)/cmdline ==>
/home/pi/.local/lib/python3.7/site-packages/adafruit_blinka/microcontroller/bcm283x/pulseio/libgpiod_pulsein--pulses81--queue323-igpioc

strace -f -p $(pidof libgpiod_pulsein) ==>
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
[pid 7505] msgrcv(0, 0xbeb44bbc, 4095, 1, 0) = -1 EINVAL (Invalid argument)
^Cstrace: Process 7505 detached
strace: Process 7506 detached

ipcs -q ==>
------ Message Queues --------
key msqid owner perms used-bytes messages

lsipc ==>
RESOURCE DESCRIPTION LIMIT USED USE%
MSGMNI Number of message queues 32000 0 0.00%
MSGMAX Max size of message (bytes) 8192 - -
MSGMNB Default max size of queue (bytes) 16384 - -
SHMMNI Shared memory segments 4096 0 0.00%
SHMALL Shared memory pages 4278190079 0 0.00%
SHMMAX Max size of shared memory segment (bytes) 4278190079 - -
SHMMIN Min size of shared memory segment (bytes) 1 - -
SEMMNI Number of semaphore identifiers 32000 0 0.00%
SEMMNS Total number of semaphores 1024000000 0 0.00%
SEMMSL Max semaphores per semaphore set. 32000 - -
SEMOPM Max number of operations per semop(2) 500 - -
SEMVMX Semaphore max value 32767 - -

Hope that help.