Omxplayer hangs on RPi 4 #749
Description
I've been trying to play a list of files one after each other using omxplayer with the new RPi 4, but I've found that after 1 hour or 2 hours of playing the files continously omxplayer hangs and it is not possible to run it again because it does nothing. I've tried with 2 of the latest Raspbian Buster images I have (2019-09-26, 2019-07-10) both with and without updating to the lastest packages versions, and also both with Legacy and Fake KMS desktop driver, and omxplayer is always hanging after 1 or 2 hours of repeatedly playing 1 or several videos.
I've also tried the same with a RPi 3B+ and omxplayer seems to play correctly for at least much longer (3 or 4 days continously right now...) than with the RPi 4, so it looks like the problem is only with RPi 4.
When omxplayer hangs, all I get using the -g option is a log file with this output:
19:13:36 T:18446744073481586412 DEBUG: DllBcm: Using omx system library
19:13:36 T:18446744073481587492 DEBUG: DllOMX: Using omx system library
19:13:36 T:18446744073481588100 DEBUG: DllAvFormat: Using libavformat system library
19:13:36 T:18446744073481589439 DEBUG: DBus connection succeeded
19:13:36 T:18446744073481590184 DEBUG: Keyboard: DBus connection succeeded
19:13:36 T:18446744073481590344 DEBUG: OMXThread::Create - Thread with id -1387290944 started
19:13:36 T:18446744073481590446 DEBUG: DllAvUtilBase: Using libavutil system library
19:13:36 T:18446744073481590467 DEBUG: DllAvCodec: Using libavcodec system library
19:13:36 T:18446744073481590482 DEBUG: DllAvFormat: Using libavformat system library
19:13:37 T:18446744073481870283 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.clock input port 80 output port 81 m_handle 0x16515d0
19:13:37 T:18446744073481870515 DEBUG: OMXClock::OMXStop
19:13:37 T:18446744073481870607 DEBUG: OMXClock::OMXSetSpeed(0.00) pause_resume:1
19:13:37 T:18446744073481870769 DEBUG: DllAvUtilBase: Using libavutil system library
19:13:37 T:18446744073481870790 DEBUG: DllAvCodec: Using libavcodec system library
19:13:37 T:18446744073481870806 DEBUG: DllAvFormat: Using libavformat system library
19:13:37 T:18446744073481871903 DEBUG: COMXCoreComponent::Initialize OMX.broadcom.video_decode input port 130 output port 131 m_handle 0x16514e0
19:13:37 T:18446744073481872600 DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.video_decode) - port(130), nBufferCountMin(1), nBufferCountActual(60), nBufferSize(81920), nBufferAlignmen(16)
Also, I can see in dmesg there are some repeating messages every 120 seconds:
[10811.525813] INFO: task kworker/1:0:13008 blocked for more than 120 seconds.
[10811.525821] Tainted: G C 4.19.75-v7l+ #1270
[10811.525825] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10811.525830] kworker/1:0 D 0 13008 2 0x00000000
[10811.525851] Workqueue: events dbs_work_handler
[10811.525869] [<c0997424>] (__schedule) from [<c0997a94>] (schedule+0x50/0xa8)
[10811.525877] [<c0997a94>] (schedule) from [<c0997ef0>] (schedule_preempt_disabled+0x18/0x1c)
[10811.525886] [<c0997ef0>] (schedule_preempt_disabled) from [<c0998fa0>] (__mutex_lock.constprop.5+0x1a8/0x590)
[10811.525894] [<c0998fa0>] (__mutex_lock.constprop.5) from [<c09994a4>] (__mutex_lock_slowpath+0x1c/0x20)
[10811.525902] [<c09994a4>] (__mutex_lock_slowpath) from [<c0999504>] (mutex_lock+0x5c/0x60)
[10811.525910] [<c0999504>] (mutex_lock) from [<c08109d0>] (rpi_firmware_transaction+0x54/0xd0)
[10811.525919] [<c08109d0>] (rpi_firmware_transaction) from [<c0810b8c>] (rpi_firmware_property_list+0x140/0x2b0)
[10811.525926] [<c0810b8c>] (rpi_firmware_property_list) from [<c0810d78>] (rpi_firmware_property+0x7c/0xfc)
[10811.525934] [<c0810d78>] (rpi_firmware_property) from [<c07e7e74>] (bcm2835_cpufreq_clock_property.constprop.1+0x58/0x80)
[10811.525943] [<c07e7e74>] (bcm2835_cpufreq_clock_property.constprop.1) from [<c07e7ef8>] (bcm2835_cpufreq_driver_target_index+0x5c/0xe4)
[10811.525951] [<c07e7ef8>] (bcm2835_cpufreq_driver_target_index) from [<c07e2b54>] (__cpufreq_driver_target+0x2d8/0x5a8)
[10811.525958] [<c07e2b54>] (__cpufreq_driver_target) from [<c07e65a0>] (od_dbs_update+0xec/0x174)
[10811.525966] [<c07e65a0>] (od_dbs_update) from [<c07e71bc>] (dbs_work_handler+0x3c/0x68)
[10811.525975] [<c07e71bc>] (dbs_work_handler) from [<c023db40>] (process_one_work+0x170/0x458)
[10811.525984] [<c023db40>] (process_one_work) from [<c023de84>] (worker_thread+0x5c/0x5a4)
[10811.525990] [<c023de84>] (worker_thread) from [<c0244170>] (kthread+0x138/0x168)
[10811.525997] [<c0244170>] (kthread) from [<c02010ac>] (ret_from_fork+0x14/0x28)
[10811.526002] Exception stack(0xd4e1ffb0 to 0xd4e1fff8)
[10811.526007] ffa0: 00000000 00000000 00000000 00000000
[10811.526012] ffc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[10811.526017] ffe0: 00000000 00000000 00000000 00000000 00000013 00000000
[10811.526023] INFO: task kworker/1:1:14776 blocked for more than 120 seconds.
[10811.526027] Tainted: G C 4.19.75-v7l+ #1270
[10811.526031] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10811.526035] kworker/1:1 D 0 14776 2 0x00000000
[10811.526053] Workqueue: events get_values_poll [raspberrypi_hwmon]
[10811.526065] [<c0997424>] (__schedule) from [<c0997a94>] (schedule+0x50/0xa8)
[10811.526072] [<c0997a94>] (schedule) from [<c099ba7c>] (schedule_timeout+0x200/0x428)
[10811.526080] [<c099ba7c>] (schedule_timeout) from [<c0998704>] (wait_for_common+0xd4/0x1b0)
[10811.526088] [<c0998704>] (wait_for_common) from [<c0998800>] (wait_for_completion+0x20/0x24)
[10811.526095] [<c0998800>] (wait_for_completion) from [<c08109f4>] (rpi_firmware_transaction+0x78/0xd0)
[10811.526102] [<c08109f4>] (rpi_firmware_transaction) from [<c0810b8c>] (rpi_firmware_property_list+0x140/0x2b0)
[10811.526109] [<c0810b8c>] (rpi_firmware_property_list) from [<c0810d78>] (rpi_firmware_property+0x7c/0xfc)
[10811.526117] [<c0810d78>] (rpi_firmware_property) from [<bf2aa0c0>] (get_values_poll+0x4c/0x15c [raspberrypi_hwmon])
[10811.526134] [<bf2aa0c0>] (get_values_poll [raspberrypi_hwmon]) from [<c023db40>] (process_one_work+0x170/0x458)
[10811.526141] [<c023db40>] (process_one_work) from [<c023de84>] (worker_thread+0x5c/0x5a4)
[10811.526147] [<c023de84>] (worker_thread) from [<c0244170>] (kthread+0x138/0x168)
[10811.526153] [<c0244170>] (kthread) from [<c02010ac>] (ret_from_fork+0x14/0x28)
[10811.526158] Exception stack(0xd1e59fb0 to 0xd1e59ff8)
[10811.526162] 9fa0: 00000000 00000000 00000000 00000000
[10811.526167] 9fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[10811.526172] 9fe0: 00000000 00000000 00000000 00000000 00000013 00000000
Testing the issue is "as easy as" running this command:
while omxplayer -g video.mp4; do :; done
where video.mp4 is the testing video. After some time omxplayer hangs. Killing the omxplayer.bin process results in a defunct process, and trying to run any other omxplayer instance results in another hanged player that doesn't play any video. Rebooting is the only solution to make everything work again.
I've tried with a 256M and 128M video memory split, but nothing seems to improve the behaviour.
Does anybody have any clue on which could be the problem and how to solve it?
Thank you!