Omxplayer hangs on RPi 4

[jordiblanchcarles]

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!

[popcornmix]

Does it matter what video.mp4 is? Does it fail more quickly if the video is very short (so starts/stops more often).
The dmesg log shows kernel hanging when requesting an arm frequency (cpufreq driver) change.
Not clear if that is the cause or a side effect of the issue.
Try disabling cpufreq driver. You can force it to always be low frequency with:

echo powersave | sudo tee /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor

or to force always high frequency with:

echo performance | sudo tee /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor

Do either of those affect the reliability? (entered before running your while script).

[jordiblanchcarles]

Hello, sorry for my delay answering, but I've been testing your suggestion of forcing the governor. The result has been that omxplayer test has lasted longer (about 10 hours with performance governor), but it has finally hanged for both governors (performance and powersave) the same way as with all my other tests...

I've tested with several videos, all of them of about 10 seconds length (for example this one) and omxplayer is always hanging.

Now I've started a new test with a longer video and I'll reply again if it also fails.

Do you have any other clue on what else to test? Is there any other way to get more information on where is omxplayer hanging?

Thank you!

[popcornmix]

I think I have found the issue. Can you test updated firmware:
https://drive.google.com/uc?id=1KDPcrIUhlv7peINnl0sJ_MS3ZgXlL1zb&export=download

and let me know if it helps?

[jordiblanchcarles]

Hello, started testing again right now with one of the "problematic" 10 seconds videos after updating the firmware files you attached. I'll give you feedback tomorrow.

For your information, using the 30 seconds video I've not been able to detect any problem, and the repeating script has been working without hanging for 24 hours (until I stopped it to test again with new firmware). I don't know if this makes sense to you (that the problem has only arised starting and stopping short videos repeatedly).

Thank you for your effort! I'll reply tomorrow with my results.

Best regards!

[popcornmix]

The video you linked was hevc (according to filename), so not supported by omxplayer.
The bug occurred at start/stop of video, so was more likely to be caught by a short repeating video.

After catching the issue I was able to make the conflicting thread in firmware trigger 100x more frequently, which meant I would see a hang after minutes rather than hours. With the fix in place it has survived overnight on a couple of boards, so I believe the fix is good.

[jordiblanchcarles]

Hello, yesterday I couldn't reply, but my last test has now been running for 2 days without problem, so I'll close this issue because it seems to be solved. Thank you very much for your effort!!

PD: Yes, the video file name shows "hvec", but it is a H264 video, so it played well with omxplayer.

[popcornmix]

Cool. The fix in the test firmware is now available in rpi-update firmware (and will be in the next stable apt firmware)

[colloqi]

👍

[jordiblanchcarles]

Hello again, I'm sorry, but I'm afraid the problem is not totally solved.

This time I've been trying to play several videos one after the other repeatedly and omxplayer is hanging after some time, it looks like the problem is similar to the first one that you solved in this issue.

Once again, these are short (10 seconds) FullHD H264 videos, and after some time playing repeatedly (one after the other) then omxplayer seems to hang.

To reveal the issue, I run an endless loop script with 2 videos:

while true; do
	omxplayer -g video1.mp4
	omxplayer -g video2.mp4
done

I've tried both: manually updating the .dat and .elf files you supplied in this issue, and using rpi-udate to update the firmware, and in both cases after some time omxplayer is "hanging".

When omxplayer is called with -g parameter, then I can see that the log file is constantly growing when the omxplayer has already "hanged" with lines like this ones:

16:42:51 T:1530609455   DEBUG: Normal M:2576927146 (A:10154667 V:10080000) P:0 A:-2566.77 V:-2566.85/T:0.20 (1,1,0,0) A:0% V:0% (-2567.01,6.07)
16:42:51 T:1530629743   DEBUG: Normal M:2576947435 (A:10154667 V:10080000) P:0 A:-2566.79 V:-2566.87/T:0.20 (1,1,0,0) A:0% V:0% (-2567.03,6.07)
16:42:51 T:1530650032   DEBUG: Normal M:2576967723 (A:10154667 V:10080000) P:0 A:-2566.81 V:-2566.89/T:0.20 (1,1,0,0) A:0% V:0% (-2567.05,6.07)
16:42:51 T:1530670607   DEBUG: Normal M:2576988015 (A:10154667 V:10080000) P:0 A:-2566.83 V:-2566.91/T:0.20 (1,1,0,0) A:0% V:0% (-2567.07,6.07)
16:42:52 T:1530690965   DEBUG: Normal M:2577008653 (A:10154667 V:10080000) P:0 A:-2566.85 V:-2566.93/T:0.20 (1,1,0,0) A:0% V:0% (-2567.09,6.07)
16:42:52 T:1530711265   DEBUG: Normal M:2577028953 (A:10154667 V:10080000) P:0 A:-2566.87 V:-2566.95/T:0.20 (1,1,0,0) A:0% V:0% (-2567.11,6.07)
16:42:52 T:1530731560   DEBUG: Normal M:2577049247 (A:10154667 V:10080000) P:0 A:-2566.89 V:-2566.97/T:0.20 (1,1,0,0) A:0% V:0% (-2567.13,6.07)
16:42:52 T:1530751853   DEBUG: Normal M:2577069540 (A:10154667 V:10080000) P:0 A:-2566.91 V:-2566.99/T:0.20 (1,1,0,0) A:0% V:0% (-2567.15,6.07)
16:42:52 T:1530772427   DEBUG: Normal M:2577089836 (A:10154667 V:10080000) P:0 A:-2566.94 V:-2567.01/T:0.20 (1,1,0,0) A:0% V:0% (-2567.17,6.07)
16:42:52 T:1530792727   DEBUG: Normal M:2577110415 (A:10154667 V:10080000) P:0 A:-2566.96 V:-2567.03/T:0.20 (1,1,0,0) A:0% V:0% (-2567.19,6.07)
16:42:52 T:1530813029   DEBUG: Normal M:2577130718 (A:10154667 V:10080000) P:0 A:-2566.98 V:-2567.05/T:0.20 (1,1,0,0) A:0% V:0% (-2567.21,6.07)
16:42:52 T:1530833318   DEBUG: Normal M:2577151007 (A:10154667 V:10080000) P:0 A:-2567.00 V:-2567.07/T:0.20 (1,1,0,0) A:0% V:0% (-2567.23,6.07)

After killing omxplayer and trying to start another omxplayer instance, the new omxplayer log file starts to grow indefinitely with recurring outputs like:

16:50:00 T:1959111831   DEBUG: Normal M:244606745 (A:0 V:4233333) P:0 A:-244.61 V:-240.37/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959132127   DEBUG: Normal M:244627040 (A:0 V:4233333) P:0 A:-244.63 V:-240.39/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959152426   DEBUG: Normal M:244647340 (A:0 V:4233333) P:0 A:-244.65 V:-240.41/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959172710   DEBUG: Normal M:244667624 (A:0 V:4233333) P:0 A:-244.67 V:-240.43/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959193202   DEBUG: Normal M:244687926 (A:0 V:4233333) P:0 A:-244.69 V:-240.45/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959213501   DEBUG: Normal M:244708424 (A:0 V:4233333) P:0 A:-244.71 V:-240.48/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959233793   DEBUG: Normal M:244728717 (A:0 V:4233333) P:0 A:-244.73 V:-240.50/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959254086   DEBUG: Normal M:244749009 (A:0 V:4233333) P:0 A:-244.75 V:-240.52/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959274375   DEBUG: Normal M:244769298 (A:0 V:4233333) P:0 A:-244.77 V:-240.54/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959294848   DEBUG: Normal M:244789583 (A:0 V:4233333) P:0 A:-244.79 V:-240.56/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959315144   DEBUG: Normal M:244810070 (A:0 V:4233333) P:0 A:-244.81 V:-240.58/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959335435   DEBUG: Normal M:244830361 (A:0 V:4233333) P:0 A:-244.83 V:-240.60/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959355729   DEBUG: Normal M:244850655 (A:0 V:4233333) P:0 A:-244.85 V:-240.62/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959376014   DEBUG: Normal M:244870939 (A:0 V:4233333) P:0 A:-244.87 V:-240.64/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)
16:50:00 T:1959396510   DEBUG: Normal M:244891239 (A:0 V:4233333) P:0 A:-244.89 V:-240.66/T:0.20 (0,1,1,0) A:0% V:99% (0.00,0.00)

and nothing but rebooting seems to make everything work again.

As it happened last time, using a RPi 3B+ board everything works perfectly, so it seems a RPi 4B related problem.

Could you please take another look at this issue? Thank you!

[popcornmix]

Does it matter what the contents of the two videos are?
I assume if they are copies of the same video (e.g. the 10s big buck bunny) then it doesn't fail?

Download links for 2 suitable videos would be useful (unless it can be made to fail with the original test video).

[jordiblanchcarles]

These are the videos I've used:
video1.mp4
video2.mp4

I've started again to test but now with 2 exact copies of the same video (video1.mp4 == video3.mp4), I'll give feedback as soon as it fails... or not...

Now I have another RPi 4B at hand, so I'll also try with 2 different videos later (or any other test you would like me to try...).

[jordiblanchcarles]

Ok, last test with 2 identical videos but with different names has already failed in less than 1 hour... I've used video1.mp4 and a second copy of the same file with a different name (video1c.mp4 in this case), so repeating video1.mp4 - video1c.mp4 - video1.mp4 - video1c.mp4 - video1.mp4 - video1c.mp4 ... and so on is failing... I don't understand why this would be different from repeating a single video file, but that's what I get...

Now I'm using a brand new RPi 4B also with a recently installed Raspbian, fully updated and with new .dat and .elf files you posted in this issue. This new RPi 4B is repeating the same test again, 2 identical files (video1.mp4 and it's copy).
The "old" RPi 4B is using 2 different files that I've never used before: video3.mp4 and video4.mp4 and is also looping through them to see if the test fails.

I'll post my results as soon as I get them.

[jordiblanchcarles]

Hello again,

I think I'm having a hardware failure in my old RPi 4B because the same tests with my new RPi 4B are always working properly (no matter which videos are looping), and the old RPi 4B is always failing sooner or later. I've reinstalled Raspbian to a new SD card, upgraded it and copied your new firmware files and the old RPi 4B board is always failing, but my new RPi 4B with exactly the same configuration board is not failing.

So my conclusion is that there must be some kind of hardware failure in my "old" RPi 4B board that is causing these issues while playing videos with omxplayer.

I'll close again the issue.

[samshum2]

I think I have found the issue. Can you test updated firmware:
https://drive.google.com/uc?id=1KDPcrIUhlv7peINnl0sJ_MS3ZgXlL1zb&export=download

and let me know if it helps?

Sorry , colud you show the upgurad step?

[jordiblanchcarles]

Hello @samshum2,

these firmware upgrades were already included some time ago in Raspbian stable release, so upgrading your Raspbian to latest should solve any problem related to this issue.

Regards.

[Norc89]

Hi,
I'm using latest version of Buster. And video hangs after 20-24h. Whats weird is that always freeze on the same frame.

Video is 23s in loop. If i stop player and start playing again video is playing. Only in background stay freezed image for some time.

Is there still anybody that is working on this project ?

[popcornmix]

Is there still anybody that is working on this project ?

This repo is no longer active and omxplayer isn't part of latest bullseye images.
In theory someone could fork this repo and continue to update it, but I've not heard of anyone interested.

VLC is the recommended alternative.