omxplayer occasionally terminates incorrectly at the end of a track

[KenT2]

omxplayer -v gives:
Build date: Mon, 16 Dec 2013 22:06:42 +0100
Version : b34143c [master]

omxplayer occasionally terminates incorrectly at the end of a track. This occurs for the 4 videos tested and at random. Sometimes after tens of iterations sometimetimes after thousands.

Using the script below and also an instrumented version of Pi Presents (which uses noahs pexpect to interface with omxplayer) I have observed three different symptoms. All seem to occur with a timestamp that is near the end of a track:

a. TIMEOUT - The stats output produced by the -s option stops during a track so there is no have a nice day, the last line is often truncated. Following this the omxplayer and omxplayer.bin processes terminate naturally.

example of last line of output:

M:12348800 V: 1.53s 0k/ 4800k A: 1.12 6.14s/ 2.00s Cv: 0k Ca: 8k
M:12524561 V:

b. ABORT - omxplayer.bin appears to abort before outputting have a nice day. The abort is reported by omxplayer. Following this the omxplayer and omxplayer.bin processes terminate naturally.

examples of error report:
/usr/bin/omxplayer: line 56: 3756 Aborted LD_LIBRARY_PATH="$OMXPLAYER_LIBS${LD_LIBRARY_PATH:+:$LD_LIBRARY_PATH}" $OMXPLAYER_BIN "$@"

c. HANG - have a nice day is output, following this the omxplayer and omxplayer.bin processes do not terminate naturally. Seems to occur only on a short video (1sec.mp4)

The script used to demonstrate these is:

!/bin/sh

while :
do
omxplayer -s -g -olocal 5sec.mp4 1>>log.log 2>>error.log
if [ -s error.log ]
then
break
fi
done

just place it in an empty directory, put videos to be played in the same directory, make it executable and run it with ./omx.sh. Wait until videos stop playing then look at the logs for the last iteration.

I am currently testing a version of Pi Presents which has workarounds for the three symptoms.

I have uploaded a zip file to www.museumoftechnology.org.uk/ken/omxplayer1.zip
It contains the script, 2 very short test videos - 1sec.mp4 and 5sec.mp4,and some example runs.
The other two videos I have used xthresh.mp4 and suits-short.mkv can be obtained from https://github.com/KenT2/pipresents-next-examples/tree/master/pp_home/media

Tell me where to get an omxplayer.bin and I'll soak test any fixes.

[KenT2]

Looks like this might be related to Issue #12

[KenT2]

Since my first post I have been running Pi Presents, incorporating pexpect as the interface to omxplayer, for 40 hours using a loop of four tracks.

This gave 52 failures of omxplayer in about 9600 track plays. After 40 hours I gave up because all failures of omxplayer had been successfully detected and dealt with.

From analysis of the data I have detected only 2 failure conditions which appear slightly different to the ones I reported earlier. It could be my previous analysis was incorrect.

ABORT - occured 41 times
'have a nice day is not sent'
instead omxplayer reports:

/usr/bin/omxplayer: line 56: 29984 Aborted LD_LIBRARY_PATH="$OMXPLAYER_LIBS${LD_LIBRARY_PATH:+:$LD_LIBRARY_PATH}" $OMXPLAYER_BIN "$@"

and then pexpect detects an eof
omxplayer.bin and omxplayer then terminates. The number after line 56: varies.

HANG1 - occured 11 times
omxplayer stops sending stats data. 'have a nice day' is not output. omxplayer and omxplayer.bin do not terminate and have to be killed.

I have put the Pi Presents with the workarounds that I used for the test in

https://github.com/KenT2/pipresents-next

[andyjagoe]

Hi @KenT2

Thanks for your work on this. I've run into similar problems using pexpect and now run it all with subprocess. There are many things you lose in doing it this way I realize...and I still run a watchdog timer to kill omxplayer if it runs for longer than the duration of the video...but it works.

[KenT2]

Hi @andyjagoe

I wasn't sure whether it was omxplayer, pexpect, or Pi Presents that was causing the problem so I wrote the little script to isolate omxplayer. (Assuming my script has not introduced other problems, my linux knowledge is very much at the trial and error stage.)

The way I now do the interface in Pi Presents has a couple of very short timeouts for omxplayer not responding. This does not need the software to know the duration of the track.

[jehutting]

@KenT2 I ran your script with the 1 sec movie. I also see that omxplayer is randomly hanging, just like you described.

The 1sec movie shows perfectly what @johnspackman runs into: sometimes the screen stays black and omxplayer doesn't stop at all. The number of runs to bump into the problem varies.

I found in the omxplayer.log file the following lines.

xxx ERROR: COMXCoreComponent::SetStateForComponent - OMX.broadcom.clock failed with omx_err(0x80001000) state=3
xxx ERROR: OMXClock::StateExecute m_omx_clock.SetStateForComponent

I changed the logging so it shows which component has trouble setting its state, but the line just below the error told it already :-)

The error is OMX_ErrorInsufficientResources. Whatever that may be... it is beyond my Openmax knowledge.

Nevertheless, omxplayer starts running and sends (movie) data to the OMX (core) components. The stats output (-s option) shows the caching of the data, but also the stop of it; audio cache 'Ca:' isn't decreased anymore.
Simply, when the audio OMX component isn't running (and freeing its input buffers) omxplayer OMXPlayerAudio::Decode() hangs around until it get space to go on with the decoding.

Somehow/somewhere (audio buffering?) the clock gets actually started?!

DEBUG: Normal s:-198483 (A:64000 V:680000) P:0 A:0.26 V:0.88/T:0.20 (0,0,1,1) A:1% V:2% (0.00,2.00)
DEBUG: Normal s:-176944 (A:96000 V:600000) P:0 A:0.27 V:0.78/T:0.20 (0,0,1,1) A:1% V:2% (0.00,2.00)
DEBUG: Normal s:-154683 (A:160000 V:760000) P:0 A:0.31 V:0.91/T:0.20 (0,0,1,1) A:1% V:2% (0.38,2.00)

I put a printf statement in every OMXClock function, but I'm missing the call to set/start the media time (=clock).

I would expect the OMX components to catch up; the clock is ticking and the PTS where the OMX components are waiting for, passes by. Apparently they don't.

By the way, my gpu_mem_512=256 (from /boot/config.txt).

[KenT2]

@jehutting
Thanks for looking into this for us. There is information on OMX_ErrorInsufficientResources in issue #63

[jehutting]

@KenT2 Thanks. Will look at it.
Tried @popcornmix OMXClock m_omx_clock.Deinitialize(true); commit but omx.sh still 'hangs' on the same ERROR.

[KenT2]

@jehutting has provided a fix which I have tested without any falures

[SleepyBrett]

I'm seeing issues with omxplayer_0.3.5git20140318d37454c_armhf.deb that are probably related. I'll come back to a machine thats playing one video after another and the screen will be black. A quick search of processes show all three omxplayer related processes running.

What data can I collect to help you narrow down this issue?

[andyjagoe]

I've been running three test systems 24 hours a day and have had more success with the @jehutting release than recent builds. I'm not sure these problems are related to dbus...and I've started wondering if some of these problems are related to problems with the USB driver. Are the videos you're playing on a USB flash drive? And when these problems occur are you also heavily writing to the USB drive and/or heavily using WiFi via USB? I've started using jdb's fiq_fsm usb driver rewrite in branch=next and my systems have been much more stable ever since: http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=70437&sid=2fc7e5f390dfa969ab94c5cc0789772f

[johnspackman]

I'm running v0.3.5 (Build date: Sun, 09 Mar 2014 18:17:45 +0000 Version : 9b0793f [master]) version and noticed a dramatic improvement over previous versions, but just checked the stats the player collects and it's started to creep back in that my watchdog timer will have to kill off omxplayer even though the video has actually ended. In fact, it seems to be getting more frequent!

Here's my version history for this particular machine:
9th March: installed 0.3.5
24th Feb: installed 0.3.4
9th Feb: installed jehutting git20140209-b3427cf

My stats are below:

Date	Num Kills	Num Playbacks	notes
2014-03-20	5	2072
2014-03-19	5	1419
2014-03-18	3	1491
2014-03-17	3	1507
2014-03-14	5	1505
2014-03-13	4	2095
2014-03-12	7	1505	installed 0.3.5 three days ago
2014-03-07	1	1508
2014-03-06	1	2097
2014-02-27	1	2096
2014-02-24	1	1508	installed 0.3.4
2014-02-10	30	1110	installed jehutting git20140209-b3427cf)
2014-02-09	34	1110
2014-02-08	34	1110
2014-02-07	52	1398
2014-02-06	46	1706
2014-02-05	42	1109
2014-02-04	42	1108
2014-02-03	33	1110
2014-02-02	27	1109
2014-02-01	42	1109

[SleepyBrett]

I've been playing the videos off the SD Card itself.

[KenT2]

re-opened as its become a live topic again.

[Ruffio]

@KenT2 is this still an issue? If not, please close the issue. Thanks.

[jehutting]

Can you @KenT2 reply on Ruffio's request?

[KenT2]

Sorry missed the previous request, I have converted PI Presents to use dbus rather than pexpect so will close