search

popcornmix / omxplayer

omxplayer
GNU General Public License v2.0
1.02k stars 333 forks source link

Pi 4 Resources Issues #782

Open craignattrass opened 4 years ago

craignattrass commented 4 years ago

Hi, I use omxplayer to play short videos in a loop, the videos are on scheduled rotation and switch out 3 or 4 times a day. After some time can be few hours or day or 2 OMXPlayer stops working - If I run with -g I get this In the log I get the following: 01:54:49 T:1319288850 ERROR: COMXCoreComponent::DecoderEventHandler OMX.broadcom.video_decode - OMX_ErrorInsufficientResources, insufficient resources 01:54:49 T:1319301018 DEBUG: Normal M:0 (A:0 V:2000000) P:0 A:0.00 V:2.00/T:0.20 (0,0,1,1) A:0% V:99% (0.00,0.00) 01:54:49 T:1320108851 DEBUG: Previous line repeats 39 times.

There or other occasions where omxplayer seems to keep playing but no changes to the displayed vider (ie it seems hung)

I have tried increasing the gpu_mem option in /boot/config.txt defers the error.

to run omxplayer I use either: /usr/bin/omxplayer --no-osd -b --loop /images/20dc4ce6bf97f21373d.mp4 /usr/bin/omxplayer --no-osd --nodeinterlace -b --loop /images/20dc4ce6bf97f21373d.mp4

I then kill the process and start a new one.

killall -9 omxplayer killall -9 "omxplayer.bin"

Dmesg reports this when errors start: [ 624.897963] ------------[ cut here ]------------ [ 624.897996] WARNING: CPU: 3 PID: 978 at drivers/firmware/raspberrypi.c:63 rpi_firmware_transaction+0x108/0x128 [ 624.898008] Firmware transaction timeout [ 624.898012] Modules linked in: tun sha256_generic libsha256 cfg80211 rfkill 8021q garp stp llc evdev raspberrypi_hwmon snd_bcm2835(C) bcm2835_codec(C) bcm2835_v4l2(C) snd_pcm bcm2835_isp(C) v4l2_mem2mem bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc snd_timer videobuf2_memops videobuf2_v4l2 videobuf2_common videodev snd mc vc_sm_cma(C) rpivid_mem uio_pdrv_genirq uio i2c_dev ip_tables x_tables ipv6 nf_defrag_ipv6 [ 624.898178] CPU: 3 PID: 978 Comm: kworker/3:0 Tainted: G C 5.4.51-v7l+ #1333 [ 624.898186] Hardware name: BCM2711 [ 624.898207] Workqueue: events get_values_poll [raspberrypi_hwmon] [ 624.898216] Backtrace: [ 624.898237] [] (dump_backtrace) from [] (show_stack+0x20/0x24) [ 624.898251] r6:e3762000 r5:00000000 r4:c129c8f8 r3:3590935b [ 624.898269] [] (show_stack) from [] (dump_stack+0xe0/0x124) [ 624.898287] [] (dump_stack) from [] (warn+0xec/0x104) [ 624.898300] r8:0000003f r7:00000009 r6:c0e2a724 r5:00000000 r4:e3763dec r3:3590935b [ 624.898315] [] (warn) from [] (warn_slowpath_fmt+0x84/0xc0) [ 624.898327] r9:c0e2a724 r8:0000003f r7:c08a2dec r6:00000009 r5:c0e2a744 r4:c1204f88 [ 624.898343] [] (warn_slowpath_fmt) from [] (rpi_firmware_transaction+0x108/0x128) [ 624.898355] r9:ef97f2c0 r8:00000000 r7:00000000 r6:ffffff92 r5:ef97f2c0 r4:c1204f88 [ 624.898370] [] (rpi_firmware_transaction) from [] (rpi_firmware_property_list+0xbc/0x174) [ 624.898381] r7:c1204f88 r6:eac02000 r5:00001000 r4:40000006 [ 624.898395] [] (rpi_firmware_property_list) from [] (rpi_firmware_property+0x78/0xf8) [ 624.898407] r10:00000000 r9:ef97f2c0 r8:00030046 r7:e3763ee0 r6:00000010 r5:00000004 [ 624.898415] r4:e37fc980 [ 624.898432] [] (rpi_firmware_property) from [] (get_values_poll+0x4c/0x15c [raspberrypi_hwmon]) [ 624.898444] r10:00000000 r9:000000c0 r8:00000000 r7:effb2600 r6:effaf340 r5:e451a0cc [ 624.898452] r4:c1204f88 [ 624.898472] [] (get_values_poll [raspberrypi_hwmon]) from [] (process_one_work+0x17c/0x4b4) [ 624.898480] r5:e3f73e80 r4:e451a0cc [ 624.898496] [] (process_one_work) from [] (worker_thread+0x54/0x5b4) [ 624.898508] r10:e3f73e80 r9:e3762038 r8:c1203d00 r7:effaf358 r6:00000008 r5:e3f73e94 [ 624.898516] r4:effaf340 [ 624.898531] [] (worker_thread) from [] (kthread+0x13c/0x168) [ 624.898543] r10:e4c11b5c r9:e3ca9e74 r8:c023ea58 r7:e3f73e80 r6:00000000 r5:e4364f40 [ 624.898551] r4:e4c11b40 [ 624.898565] [] (kthread) from [] (ret_from_fork+0x14/0x28) [ 624.898574] Exception stack(0xe3763fb0 to 0xe3763ff8) [ 624.898585] 3fa0: 00000000 00000000 00000000 00000000 [ 624.898596] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 624.898606] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ 624.898619] r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c0244d54 [ 624.898627] r4:e4364f40 r3:c0204648 [ 624.898638] ---[ end trace 4990c4e7fcac7193 ]--- [ 624.898673] hwmon hwmon1: Failed to get throttled (-110) [ 626.017990] cpu cpu0: dev_pm_opp_set_rate: failed to find current OPP for freq 4294967186 (-34) [ 627.057990] raspberrypi-clk soc:firmware:clocks: Failed to change fw-clk-arm frequency: -110 [ 630.257984] cpu cpu0: dev_pm_opp_set_rate: failed to find current OPP for freq 4294967186 (-34)

This is on a Pi 4 - I cannot say when issue started - I am guessing around beginning of the year.

My original development was on Pi3 and Pi4 2GB and had no issues last year, things started to go wrong after March. I have tried upgrading to Pi OS and have same issue.

I am happy to pay for support if someone can fix.

Thanks Craig

popcornmix commented 4 years ago

omxplayer is being deprecated in favour of vlc. It might be worth trying to switch to vlc. Otherwise if you could identify exactly when the problem occurred (if you believe it didn't occur some time in the past) then we may be able to investigate. It's presumably a firmware change (I don't think omxplayer has changed much in the last year). You can test older firmwares with rpi-update (backing up is advisable).

craignattrass commented 4 years ago

Hi, Thank you for the info - I am aware of that however there is no seamless loop in vlc - from what I could see was they are looking at it in v4. I have been trying to find the exact fault time, we have also installed other packages to the system so I cannot consistently say when it started. My original thoughts were a pi 4 4gb issue, but have the issue on the 2gb - however in Jan it was working fine (as far as we can recall) as it works fine from boot for some time, my guess was a gpu memory leak - however I cant find a way to clear / reset it. Will keep looking - I used the omxplayer as Raspberry Pi seemed to have it as the flagship player, it was only after reading your github did I see depreciated. If you could offer a seamless solution on vlc i will happily switch.

Thank you

craignattrass commented 4 years ago

Hi, Would you be able to look at the logs - the first one shows the video playing in a loop - eventually it stops if you try stop and start the video you get error in log 2 If you wait 3 min or restart pi you can play again with the same result If I change the gpu_mem=128 or 256 the issue takes longer to appear.

I really need some help with an expert opinion as I have no other way to play the videos. I am willing to offer payment for consulting if it can be fixed.

Thanks Craig

omxplayer2.log omxplayer1.log

jehutting commented 4 years ago

Had a quick look in omxplayer1.log. Took out what I think is relevant

...
06:16:40 T:272552569   DEBUG: Normal M:16481087 (A:0 V:19920000) P:0 A:-16.48 V:3.44/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:16:40 T:272559692    INFO: CDVDPlayerVideo::Decode dts:19920000 pts:19920000 cur:19920000, size:217
06:16:40 T:272560447    INFO: COMXVideo::SubmitEOS
06:16:40 T:272572826   DEBUG: Normal M:16501343 (A:0 V:19920000) P:0 A:-16.50 V:3.42/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:16:40 T:272593081   DEBUG: Normal M:16521600 (A:0 V:19920000) P:0 A:-16.52 V:3.40/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:16:40 T:272614548   DEBUG: Normal M:16541985 (A:0 V:19920000) P:0 A:-16.54 V:3.38/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)

06:16:43 T:275851175   DEBUG: Normal M:19780358 (A:0 V:19920000) P:0 A:-19.78 V:0.14/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:16:43 T:275871451   DEBUG: Normal M:19800634 (A:0 V:19920000) P:0 A:-19.80 V:0.12/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:16:43 T:275891726   DEBUG: Normal M:19820910 (A:0 V:19920000) P:0 A:-19.82 V:0.10/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:16:43 T:275913690   DEBUG: Normal M:19841105 (A:0 V:19920000) P:0 A:-19.84 V:0.08/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:16:43 T:275934014   DEBUG: Normal M:19863116 (A:0 V:19920000) P:0 A:-19.86 V:0.06/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:16:43 T:275954289   DEBUG: Normal M:19883392 (A:0 V:19920000) P:0 A:-19.88 V:0.04/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:16:43 T:275974565   DEBUG: Normal M:19903668 (A:0 V:19920000) P:0 A:-19.90 V:0.02/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:16:43 T:275994839   DEBUG: Normal M:19923941 (A:0 V:19920000) P:0 A:-19.92 V:-0.00/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:16:43 T:276005008    INFO: COMXVideo::IsEOS
06:16:43 T:276005114   DEBUG: OMXReader::SeekTime(0) - seek ended up on time -2147483648
06:16:43 T:276005171   DEBUG: OMXClock::OMXStop
06:16:43 T:276005513   DEBUG: OMXClock::OMXSetSpeed(0.00) pause_resume:1
06:16:43 T:276006233   DEBUG: OMXClock::OMXMediaTime set config OMX_IndexConfigTimeCurrentVideoReference = 0.00
06:16:43 T:276006696   DEBUG: Seeked 4 0 0
...

06:18:00 T:353172862   DEBUG: Normal M:16369788 (A:0 V:19960000) P:0 A:-16.37 V:3.59/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:00 T:353178521    INFO: CDVDPlayerVideo::Decode dts:19840000 pts:19960000 cur:19960000, size:51504
06:18:00 T:353189345    INFO: CDVDPlayerVideo::Decode dts:19880000 pts:19880000 cur:19880000, size:212
06:18:00 T:353194638   DEBUG: Normal M:16389842 (A:0 V:19920000) P:0 A:-16.39 V:3.53/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:00 T:353214900   DEBUG: Normal M:16411599 (A:0 V:19920000) P:0 A:-16.41 V:3.51/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353235139   DEBUG: Normal M:16431838 (A:0 V:19920000) P:0 A:-16.43 V:3.49/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353255376   DEBUG: Normal M:16452075 (A:0 V:19920000) P:0 A:-16.45 V:3.47/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353275613   DEBUG: Normal M:16472312 (A:0 V:19920000) P:0 A:-16.47 V:3.45/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353290811    INFO: CDVDPlayerVideo::Decode dts:19920000 pts:19920000 cur:19920000, size:217
06:18:01 T:353291603    INFO: COMXVideo::SubmitEOS
06:18:01 T:353297391   DEBUG: Normal M:16492621 (A:0 V:19920000) P:0 A:-16.49 V:3.43/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353317644   DEBUG: Normal M:16514411 (A:0 V:19920000) P:0 A:-16.51 V:3.41/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353337920   DEBUG: Normal M:16534685 (A:0 V:19920000) P:0 A:-16.53 V:3.39/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353358194   DEBUG: Normal M:16554962 (A:0 V:19920000) P:0 A:-16.55 V:3.37/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353378523   DEBUG: Normal M:16575290 (A:0 V:19920000) P:0 A:-16.58 V:3.34/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353400519   DEBUG: Normal M:16595704 (A:0 V:19920000) P:0 A:-16.60 V:3.32/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353420793   DEBUG: Normal M:16617697 (A:0 V:19920000) P:0 A:-16.62 V:3.30/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:01 T:353441079   DEBUG: Normal M:16637984 (A:0 V:19920000) P:0 A:-16.64 V:3.28/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
...
06:18:04 T:356511097   DEBUG: Normal M:19707997 (A:0 V:19920000) P:0 A:-19.71 V:0.21/T:0.20 (0,0,1,1) A:0% V:0% (0.00,0.00)
06:18:04 T:356531371   DEBUG: Normal M:19728272 (A:0 V:19920000) P:0 A:-19.73 V:0.19/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356551650   DEBUG: Normal M:19748551 (A:0 V:19920000) P:0 A:-19.75 V:0.17/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356573611   DEBUG: Normal M:19768819 (A:0 V:19920000) P:0 A:-19.77 V:0.15/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356593913   DEBUG: Normal M:19790795 (A:0 V:19920000) P:0 A:-19.79 V:0.13/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356614190   DEBUG: Normal M:19811072 (A:0 V:19920000) P:0 A:-19.81 V:0.11/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356634467   DEBUG: Normal M:19831348 (A:0 V:19920000) P:0 A:-19.83 V:0.09/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356654744   DEBUG: Normal M:19851625 (A:0 V:19920000) P:0 A:-19.85 V:0.07/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356676672   DEBUG: Normal M:19871887 (A:0 V:19920000) P:0 A:-19.87 V:0.05/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356696949   DEBUG: Normal M:19893812 (A:0 V:19920000) P:0 A:-19.89 V:0.03/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356717221   DEBUG: Normal M:19914085 (A:0 V:19920000) P:0 A:-19.91 V:0.01/T:0.20 (0,0,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356737498   DEBUG: Normal M:19934361 (A:0 V:19920000) P:0 A:-19.93 V:-0.01/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
--------------
SOMEWHERE AROUND HERE , I WOULD EXPECT AN IsEOS LOGGING
--------------
06:18:04 T:356757822   DEBUG: Normal M:19954686 (A:0 V:19920000) P:0 A:-19.95 V:-0.03/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356779880   DEBUG: Normal M:19974967 (A:0 V:19920000) P:0 A:-19.97 V:-0.05/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356800170   DEBUG: Normal M:19997034 (A:0 V:19920000) P:0 A:-20.00 V:-0.08/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356820453   DEBUG: Normal M:20017317 (A:0 V:19920000) P:0 A:-20.02 V:-0.10/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356840735   DEBUG: Normal M:20037600 (A:0 V:19920000) P:0 A:-20.04 V:-0.12/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356861016   DEBUG: Normal M:20057880 (A:0 V:19920000) P:0 A:-20.06 V:-0.14/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356882840   DEBUG: Normal M:20078028 (A:0 V:19920000) P:0 A:-20.08 V:-0.16/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356903121   DEBUG: Normal M:20099850 (A:0 V:19920000) P:0 A:-20.10 V:-0.18/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356923404   DEBUG: Normal M:20120133 (A:0 V:19920000) P:0 A:-20.12 V:-0.20/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356943686   DEBUG: Normal M:20140414 (A:0 V:19920000) P:0 A:-20.14 V:-0.22/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356963963   DEBUG: Normal M:20160692 (A:0 V:19920000) P:0 A:-20.16 V:-0.24/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:356985933   DEBUG: Normal M:20181119 (A:0 V:19920000) P:0 A:-20.18 V:-0.26/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:357006215   DEBUG: Normal M:20203090 (A:0 V:19920000) P:0 A:-20.20 V:-0.28/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:357026497   DEBUG: Normal M:20223372 (A:0 V:19920000) P:0 A:-20.22 V:-0.30/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:357046774   DEBUG: Normal M:20243649 (A:0 V:19920000) P:0 A:-20.24 V:-0.32/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:357067051   DEBUG: Normal M:20263926 (A:0 V:19920000) P:0 A:-20.26 V:-0.34/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)
06:18:04 T:357089007   DEBUG: Normal M:20284198 (A:0 V:19920000) P:0 A:-20.28 V:-0.36/T:0.20 (0,1,1,0) A:0% V:0% (0.00,0.00)

I guess that this missing IsEOS is caused by the OpenMax layer not sending an EOS event. So OMXPlayer doesn't get notified and waits endlessly for it. You will see the last frame giving the impression that OMXPlayer has stopped; but it is just waiting.

Don't know how this can lead to the insufficient resources error.

And well about the OpenMax layer... that layer is no longer supported and will be probably deprecated too.

So for better or worse, we will all end up with vlc.

craignattrass commented 4 years ago

That makes sense, I believe issue is with newer hardware. I have got a work around where I stop omxplayer and display a static image for 2 min giving the system time to reset memory. Seems to work for now but will see after a few days. I will eagerly await vlc version 4 as that should solve the issue. Thank you for the help.