mmal_vc_port_disable() stuck in mmal_vc_sendwait_message()

[janus926]

Describe the bug I was working with the RPi camera using picamera v1.13 and found the python doesn't return from stop_recording() sometimes. It is blocked in mmal_vc_sendwait_message() from mmal_port_disable(). So I tried to reproduce with the default image and raspivid, and found it is also reproducible.

To reproduce Run command while true; do raspivid -w 640 -h 480 -b 450000 -fps 24 -t 5000 -v -o tcp://x.x.x.x:yyyy; sleep 3; done, then just leave it there for a while (usually it takes hours to reproduce).

Expected behaviour mmal_port_disable() to return.

Actual behaviour mmal_port_disable() stuck in mmal_vc_sendwait_message(). If I stop raspivid (Ctrl+C) when the issue occurs and rerun it, it will be blocked in the first call to mmal_vc_sendwait_message(). A reboot is required to recover.

System Copy and paste the results of the raspinfo command in to this section. Alternatively, copy and paste a pastebin link, or add answers to the following questions:

• Which model of Raspberry Pi? e.g. Pi3B+, PiZeroW Pi Zero v1.3 and Pi Camera v2.1
• Which OS and version (cat /etc/rpi-issue)? Raspberry Pi reference 2020-05-27 Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 825107f04027269db77426046f5085475b1a22f, stage4
• Which firmware version (vcgencmd version)? Apr 15 2020 11:44:24 Copyright (c) 2012 Broadcom version 82f9bb929ce2186eb1824178c1ae82902ad6275c (clean) (release) (start_x)
• Which kernel version (uname -a)? Linux raspberrypi 4.19.118+ #1311 Mon Apr 27 14:16:15 BST 2020 armv6l GNU/Linux

Logs

 mmal: mmal_port_disconnect: vc.ril.camera:out:0(OPQV)(0xaec1b0)
 mmalipc: mmal_vc_sendwait_message: wait 0xb6efd3c4, reply to 0xbebb5538
 mmalipc: mmal_vc_vchiq_callback: reason 2
 mmalipc: mmal_vc_vchiq_callback: waking up waiter at 0xb6efd3c4
 mmalipc: mmal_vc_vchiq_callback: copying payload @0xbebb5538 to 0xb4b08718 len 28
 mmalipc: mmal_vc_sendwait_message: got reply (len 28/28)
 mmalipc: release_waiter: at 0xb6efd3c4
 mmal: mmal_connection_destroy: 0xb03490, vc.ril.camera:out:1/vc.ril.video_encode:in:0
 mmal: mmal_connection_disable: 0xb03490, vc.ril.camera:out:1/vc.ril.video_encode:in:0
 mmal: mmal_port_disable: vc.ril.camera(3:1) port 0xaec890
 mmalipc: mmal_vc_sendwait_message: wait 0xb6efd3c4, reply to 0xbebb54f0

Additional context I added some logs to vchiq_2835_arm.c in the linux kernel, and found vchiq_doorbell_irq() for BELL0 wasn't triggered.

[17452.138027] vchiq: vchiq_ioctl - instance b52957a8, cmd AWAIT_COMPLETION, arg b6c62d7c
[17452.143248] vchiq: vchiq_ioctl - instance b52957a8, cmd QUEUE_MESSAGE, arg be8e1b64
[17452.143712] vchiq: 0: qm DATA@338f3751,64 (12->90)
[17452.143755] vchiq: Sent: 00000000: 6d 6d 61 6c 0a 00 00 00 e8 05 00 00 dc c1 f1 b6 mmal............
[17452.143768] vchiq: Sent Msg DATA(5) to mmal s:12 d:90 len:100
[17452.143778] vchiq: remote_event_signal BELL2 a=1 e=525227796
[17452.143789] vchiq:   ioctl instance d7879000, cmd QUEUE_MESSAGE -> status 0, 0
# 

[6by9]

Can you try adding start_debug=1 to config.txt, and then run sudo vcdbg log assert when it locks up?

[janus926]

I have been trying for more than a week, but haven't succeeded to reproduce it with start_debug=1. Note I can still reproduce it without start_debug=1.

[janus926]

I haven't succeeded reproducing this with start_debug=1 on RPi using the official image. However I reproduced once with fixup_db.dat and start_db.elf using buildroot image (rpi-firmware-1.20200601, rpi-userland-188d3bfe4a0ac36b119a2cee35a6be8d0c68e09e, Linux 4.19.118 PREEMPT). The first four asserts were existed after boot up. Not sure if this helps.

# vcdbg log assert
001514.142: assert( source ) failed; ../../../../../middleware/confzilla/cp_front_fdt.c::cp_front_fdt_load_builtin line 115 rev 82f9bb9
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
001550.508: assert( edid_state[hdmi_core].i2c_driver ) failed; ../../../../../middleware/hdmi/edid.c::hdmi_edid_shutdown line 736 rev 82f9bb9
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
006614.091: assert( card not initialised ) failed; ../../../../../filesystem/media/sdcard/sdcard.c::sdhost_close line 1045 rev 82f9bb9
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
011162.790: assert( camera_subsystem_state.power_enable_ref_count[port] > 0 ) failed; ../../../../../vcfw/drivers/device/camera_subsystem/camera_subsystem.c::camera_disable_ctrl line 1141 rev 82f9bb9
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
647886.630: assert( st == 0 ) failed; ../../../../../middleware/openmaxil/components/ve_worker.c::ve_worker_close line 480 rev 82f9bb9
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
# 

[6by9]

That last assert in ve_worker_close is that it's asked part of the codec to disable, and it hasn't done so within a second, so something would appear to have gone fairly badly wrong.

Can I confirm that this is H264 encoding (not MJPEG)? How "busy" a scene are you encoding?

Sorry I'm busy on other things at present, but could you try dropping the bitrate lower still and see if that increases the reproduction rate? I'm just wondering if things go weird if the bitrate control decided to drop the last frame submitted as we'd exceeded the target bitrate, so that there isn't a corresponding output frame for the input. Unfortunately that'll be down in the bowels of the codec so quite an involved one to debug.

[janus926]

Can I confirm that this is H264 encoding (not MJPEG)? How "busy" a scene are you encoding?

Yes, this is H264 encoding. I just leave the camera on my desk (in the office), which is not busy.

Sorry I'm busy on other things at present, but could you try dropping the bitrate lower still and see if that increases the reproduction rate?

Sure, I'll try that and update later.

[janus926]

I shorten the sleep time from 3s to 1s between raspivid invocations, and try to make a "busy" scene by shaking a paper card in front of the camera. The tests run for 5 minutes each.

bitrate	reproduce rate
450000	0/5
200000	0/5
50000	4/5

[6by9]

Thanks. It sounds like it is the codec getting upset should the last frame be discarded due to bitrate control. It's an area I knew could sometimes complain somewhat, but I hadn't seen a full lockup. I'll see if I can find some time to investigate this week.

[HughWarrington]

I seem to be seeing the same problem on the RPi4. It looks like @janus926 has already got a lot further, but here's my details anyway. Let me know if I can provide more useful info.

• Which model of Raspberry Pi? Pi4 4GB
• Which OS and version? I'm running a Python3.8 program using picamera 1.13 to access the camera, inside a Docker container based on balenalib/raspberrypi3-debian-python:buster-20200716. Host OS is balenaOS 2.53.12+rev1.
• Which firmware version?

$ vcgencmd version
Jun  1 2020 13:24:51 
Copyright (c) 2012 Broadcom
version 6379679d1ec6a8c746d7e77e015f5b56b939976f (clean) (release) (start_x)

• Which kernel version?

$ uname -a
Linux ac505c76ee18 4.19.118 #1 SMP PREEMPT Thu Aug 6 07:28:20 UTC 2020 aarch64 GNU/Linux

• Describe the bug The program is very straightforward and records chunked h264 to disk. The main loop is basically

for _ in camera.record_sequence(filename_seq, sps_timing=True, format="h264"):
    camera.wait_recording(60)

Today the video reader process on one of our devices froze. Nothing obviously unique about the device we saw it on; this is the first time I have seen this problem in ~10k hours of the same code running across a small fleet of identical devices. There was a partly written video file still open with no further bytes being appended. Restarting the process didn't help but rebooting the device fixed it.

I'm not familiar with how to debug this kind of problem but I ran the following, which led me via Google to this ticket.

$ gdb python 17

(gdb) bt
#0  0xf793b524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
#1  0xf79387d8 in do_futex_wait.constprop () from /lib/arm-linux-gnueabihf/libpthread.so.0
#2  0xf79388b8 in __new_sem_wait_slow.constprop.1 () from /lib/arm-linux-gnueabihf/libpthread.so.0
#3  0xf6a08da4 in mmal_vc_sendwait_message () from /opt/vc/lib/libmmal_vc_client.so
#4  0xf6a0bbd4 in mmal_vc_port_disable () from /opt/vc/lib/libmmal_vc_client.so
#5  0xf69b793c in mmal_port_disable_internal () from /opt/vc/lib/libmmal_core.so
#6  0xf69b8530 in mmal_port_disable () from /opt/vc/lib/libmmal_core.so
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

(gdb) info threads
  Id   Target Id                                    Frame 
* 1    Thread 0xf7bf1010 (LWP 17) "python3"         0xf793b524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  2    Thread 0xf68b1460 (LWP 19) "VCHIQ completio" 0xf7825f08 in ioctl () from /lib/arm-linux-gnueabihf/libc.so.6
  3    Thread 0xf5eff460 (LWP 20) "HDispmanx Notif" 0xf793b524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  4    Thread 0xf56fe460 (LWP 21) "HTV Notify"      0xf793b524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  5    Thread 0xf4efd460 (LWP 22) "HCEC Notify"     0xf793b524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  6    Thread 0xf46fc460 (LWP 24) "vc.ril.camera"   0xf793b524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  7    Thread 0xf3efb460 (LWP 25) "vc.null_sink"    0xf793b524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  8    Thread 0xf36fa460 (LWP 26) "vc.ril.video_sp" 0xf793b524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  9    Thread 0xf24ff460 (LWP 28) "vc.ril.video_en" 0xf793b524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0

[HughWarrington]

Seen again today, I think. I had the same symptom of the Python process getting stuck, running the same code and hardware type as yesterday but on a different physical device.

The stack trace is slightly different. It does involve mmal_vc_sendwait_message but not mmal_vc_port_disable which is why I thought it would be worth posting here.

Please let me know if this turns out to be irrelevant, and I will file a separate ticket.

(gdb) bt
#0  0xf7cb6524 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
#1  0xf7cb37d8 in do_futex_wait.constprop () from /lib/arm-linux-gnueabihf/libpthread.so.0
#2  0xf7cb38b8 in __new_sem_wait_slow.constprop.1 () from /lib/arm-linux-gnueabihf/libpthread.so.0
#3  0xf6d43da4 in mmal_vc_sendwait_message () from /opt/vc/lib/libmmal_vc_client.so
#4  0xf6d465f0 in mmal_vc_component_create () from /opt/vc/lib/libmmal_vc_client.so
#5  0xf6cf5928 in mmal_component_supplier_create () from /opt/vc/lib/libmmal_core.so
#6  0xf6cf63b4 in mmal_component_create_core () from /opt/vc/lib/libmmal_core.so
#7  0xf6e0abd8 in ffi_call_VFP () from /usr/lib/arm-linux-gnueabihf/libffi.so.6
#8  0xf6e0b26c in ffi_call () from /usr/lib/arm-linux-gnueabihf/libffi.so.6

NB there were another 57 (!) stack frames but I've left them out since they were all in Python.

[Omccormack-blip]

Hi all - this problem is holding back our machine vision project. @6by9 I wonder if you've had the chance to look into it? I could pay for your/someone's time to bring it up the priority list if you think you can solve it!

[6by9]

@Omccormack-blip have you confirmed that it is exactly the same assert firing in your case? start_debug=1 in config.txt, and then sudo vcdbg log assert after it has locked up.

There's the ugly way of solving this (just shut down always), and the clean way (find the right flags and set them appropriately when RC asks for a skip). I'll see what I can come up with.

[HughWarrington]

I have tried putting start_debug=1 in config.txt on my Pi 4, but the device will then no longer boot.

[HughWarrington]

Any update on this? We have gone to some lengths to write a watchdog to detect this problem and reboot on our fleet of ~100 devices. This seems to work except just now and then the problem appears to spill over into stuck kernel workers and other general carnage so even our watchdog can't reboot the device.

[janus926]

It sounds like it is the codec getting upset should the last frame be discarded due to bitrate control. It's an area I knew could sometimes complain somewhat, but I hadn't seen a full lockup. I'll see if I can find some time to investigate this week.

@6by9

It has been a while, are there any chances to move this forward? Thanks.

[rolandjitsu]

I think I've stumbled upon the same issue. After a number of restarts of the binary that uses the camera and invokes the mmal_port_disable func, the function gets stuck at:

mmal: mmal_port_disable: vc.ril.rawcam(3:0) port 0x6b200db0

Upon the next start of the binary, the camera is stuck and the only way to resolve this is to reboot the pi.