White flash at the end of playback with some videos

[devsterj]

Hi,

I noticed variations of the same problem have been reported before, many of them closed issues (#250 / #455 / #508).

However, even with the latest omxplayer (compiled from source [latest commit 7f3faf6] or apt-get install'ed from the RPI Stretch repo [20170330~134343-2]), I get a short <1sec white flash at the end of playback with a few video files. I've tried updating all packages/kernel/firmware (as of Nov 4/2018) with apt-get and I can confirm the flash occurs on Raspberry Pi B, 2B and 3B.

Here's an example of a video that produces the white flash at the end (~60MB):
https://drive.google.com/file/d/1UGz6FWUn8YZvubf0kcgVXghrLK7yWgn0/view?usp=sharing

If I --loop the file, the flash happens only once right before the video is played for the second time.

If I force deinterlacing using the --deinterlace parameter, the flash does not occur — but the video files are not interlaced, so forcing deinterlacing is redundant. Omxplayer logs of the same video file played with and without --deinterlace show COMXVideo::SubmitEOS happening slightly earlier when deinterlacing is used (and the flash does not happen).

I also noticed the flash does not happen if I set the --video_fifo value very high (e.g. 80 when the file itself is 60MB).

I'm not really fluent in c++, but if there's anything I can do (besides coding) to assist in solving the problem, let me know.

Thanks to all the devs for an otherwise sweet piece of software!

NOTE: I'm using the HDMI output and I've tested two different LG displays. Here's my config.txt:

hdmi_drive=2
hdmi_ignore_cec=0
hdmi_ignore_edid_audio=1
hdmi_ignore_cec_init=1
hdmi_force_hotplug=1
hdmi_group=1
hdmi_mode=16
disable_overscan=1
sdtv_mode=2
framebuffer_depth=32
framebuffer_ignore_alpha=1
avoid_warnings=1
disable_splash=1
gpu_mem=256
dtparam=audio=on

[jehutting]

Have you tried the debian package mentioned at # 508? Be sure to have a SD backup before installing it.

[devsterj]

Ah, I missed the link when I first read the comments in # 508.

I managed to install the Debian package, but I had to create the following symlinks before the program would run: (apparently these were renamed at some point after your package creation)

cd /opt/vc/lib
sudo ln -s libbrcmEGL.so libEGL.so
sudo ln -s libbrcmGLESv2.so libGLESv2.so
sudo ln -s libbrcmWFC.so libWFC.so

I can confirm that the flash does not occur anymore. That's great, but now omxplayer is missing almost 2 years of commits (inc. ffmpeg dependency updates, alsa/dbus stuff etc).

Moreover, I'm using omxplayer in a way that requires some source tweaking and I cannot get your source package to compile. To be more specific, I've implemented something similar to #538 (start-paused parameter) to minimize omxplayer video loading times by running two processes (one playing, another one pre-loading in the background and then waiting to be started via d-bus when the first one exits). I did make sure my tweaks are not the cause of the white flashes though (all tests run with original non-modified source).

Is there a way to get your flash-fix changes to work with the latest sources?

[jehutting]

Your symbolic links are indeed necessary for Stretch whereas at the time I made the modifications (&PR) Jessie was around.

The modifications are in my loop branch which I updated once as mentioned in one of the aforementioned issues.

The specifc modifications can be found here.

Just take the four files and do a manual compare-and-merge action.

[devsterj]

I merged your changes locally to the latest master version and got rid of the flash problem, but the changes introduced a new problem -- the playback can no longer be resumed if the video is paused either via keyboard or dbus. A 'p' keypress does nothing and a dbus command just times out without response. Any ideas on how to fix that?

Thanks for your help.

[devsterj]

Ah, I noticed the pause/resume error does not happen with all videos, I'm experiencing it with the video linked in my first post. I noticed the output of omxplayer -i for the video is:

Input #0, mov,mp4,m4a,3gp,3g2,mj2, from '<...video file...>':
Metadata:
major_brand : mp42
minor_version : 0
compatible_brands: mp42mp41
creation_time : 2017-09-21T14:28:07.000000Z
Duration: 00:00:16.00, start: 0.000000, bitrate: 29854 kb/s
Stream #0:0(eng): Video: h264 (Main) (avc1 / 0x31637661), yuv420p(tv, bt709), 1920x1080, 29847 kb/s, 25 fps, 25 tbr, 25k tbn, 50 tbc (default)
Metadata:
creation_time : 2017-09-21T14:28:07.000000Z
handler_name : Alias Data Handler
encoder : AVC Coding
have a nice day ;)

Nothing about the 16:9 aspect ratio. I'm wondering if this could be related to ffmpeg. I'll try recompiling omxplayer (inc. your changes) with the latest ffmpeg.

[devsterj]

No difference with ffmpeg (4.1.git [d96ae9d]), only the handler_name -field in omxplayer -i output changed from "Alias Data Handler" to "?Mainconcept Video Media Handler". The pause/resume issue persists with videos which originally had the white flash problem and some videos that originally didn't.

Any thoughts on what's going on here with the pause/resume failing with some files?

[devsterj]

I removed the LockDecoder() and UnLockDecoder() lines (which the loop-fix merge added) from the AddPacket functions in OMXPlayerAudio.cpp & OMXPlayerVideo.cpp, no more freezing on resume after pause. I'll do some more testing, but so far so good.

[devsterj]

After some hours of testing, it seems like now omxplayer randomly doesn't always finish up in time. Apparently there are more issues to tackle with the flash fix...

[jehutting]

Apparently :-)

Can you give more details about "it seems like now omxplayer randomly doesn't always finish up in time"? What exactly do you see (or not see)? Logging showing the issue?

[devsterj]

When the LockDecoder() and UnLockDecoder() lines that your fix adds are removed from the AddPacket functions in OMXPlayerAudio.cpp and OMXPlayerVideo.cpp, the resume-after-pause -problem disappears.

However, when I do hours of consecutive runs of omxplayer compiled with your fix without those lines, sometimes the same video freezes on the last frame and omxplayer never exits. This seems to happen randomly, sometimes after a couple of consecutive runs, sometimes only after 15 minutes (16 sec video). When the freeze happens, the omxplayer.bin process stays alive way past the 16 second video duration with no frame changes on screen, producing log lines like this:

12:38:45 T:1714235102 DEBUG: Normal M:14145487 (A:0 V:15920000) P:0 A:-14.15 V:1.77/T:0.20 (0,0,1,1) A:0% V:40959% (0.00,0.00)

...and it continues forever (even though it is a 16 second video)...

12:43:10 T:1978685915 DEBUG: Normal M:278597215 (A:0 V:15920000) P:0 A:-278.60 V:-262.68/T:0.20 (0,1,1,0) A:0% V:40959% (0.00,0.00)

..until I hit ctrl+C

12:43:10 T:1978706277 DEBUG: OMXClock::OMXStop
12:43:10 T:1978707219 DEBUG: OMXThread::Run - Exited thread with id 1915745136
12:43:10 T:1978707817 DEBUG: OMXThread::StopThread - Thread stopped
12:43:10 T:1978718254 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.video_scheduler handle 0x71900698
12:43:10 T:1978728517 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.video_decode handle 0x14f6bf8
12:43:10 T:1978729725 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.video_render handle 0x71900588
12:43:10 T:1978731213 DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.clock handle 0x14f4e88

Between the time when the last frame freezes and until I hit ctrl+C, the dbus interface keeps answering playback status queries normally (saying it's still playing) and only "DEBUG: Normal..." entries appear in the logfile, no COMXVideo::SubmitEOS nor OMXPlayerVideo::Decode.

This random problem of omxplayer displaying the last frame and running forever does not seem to happen, if I compile omxplayer without removing the LockDecoder()/UnLockDecoder() AddPacket -lines from your fix. However, then we're back to the problem of not being able to resume after pause with some videos.

Here's what happens when I run omxplayer [7f3faf6] manually merged with your fix (without my LockDecoder/UnLockDecoder removals) and pause after a few secs:

...

14:12:14 T:18446744072442952174 DEBUG: Normal M:4035014 (A:0 V:5880000) P:0 A:-4.04 V:1.84/T:0.20 (0,0,1,1) A:0% V:1% (0.00,0.00)
14:12:14 T:18446744072443022738 INFO: OMXPlayerVideo::Decode dts:5880000 pts:5880000 cur:5880000, size:147658
14:12:14 T:18446744072443025664 DEBUG: Popped message member: Action interface: org.mpris.MediaPlayer2.Player type: 1 path: /org/mpris/MediaPlayer2
14:12:14 T:18446744072443026087 DEBUG: Normal M:4109073 (A:0 V:5920000) P:0 A:-4.11 V:1.81/T:0.20 (0,0,1,1) A:0% V:1% (0.00,0.00)
14:12:14 T:18446744072443026221 DEBUG: Pause -4.11,1.81 (0,0,1,1) 0.20
14:12:14 T:18446744072443026277 DEBUG: OMXClock::OMXSetSpeed(0.00) pause_resume:1
14:12:14 T:18446744072443055688 INFO: OMXPlayerVideo::Decode dts:5920000 pts:5920000 cur:5920000, size:136643
14:12:14 T:18446744072443057852 DEBUG: Normal M:4109325 (A:0 V:6000000) P:1 A:-4.11 V:1.89/T:0.20 (0,0,1,1) A:0% V:3% (0.00,0.00)

After this, nothing else is written in the log and nothing happens when I try to resume the playback with the keyboard or via a dbus command. I just get a timeout error:

'Error org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.'

The paused frame stays on screen and the omxplayer.bin process stays alive doing apparently nothing. I have to kill it to clear the screen and make omxplayer exit.

So, anyone got any ideas on what to try next?

Just to reiterate: I'm trying to get the latest omxplayer version to play videos without the white flash at the end of playback that occurs with some video files (example link in first post). While jehutting's flash fix from May 2016 gets rid of the flash problem, it seems to have some incompatibilities with the latest omxplayer sources, causing resume after pause to fail with some videos.

[jehutting]

Thanks @zeepa for such a detailed report 👍

I had a look at the LockDecoder/UnLockDecoder issue, and those modifications in the AddPacket of the audio and video player is (and was) a bad 'improvement' :-).

When you pause the playing, the Decode of the packets will "stop" when the available (buffer) space gets all used; it goes in (a bloody) loop of waiting for free space. However, upon entering the Decode the decoder is locked and is kept locked while waiting for available space. Now as AddPacket is called from the main thread it finds the decoder locked and waits for the decoder to be unlocked in order to continue. This will never occur and results in OMXPlayer just being locked up.

So, don't add the LockDecoder/UnLockDecoder in the AddPacket, as you already found out.

About the sometimes the same video freezes on the last frame and omxplayer never exits.:
that looks more like #637 and seems to be related to ffmpeg 4.x. Is there a specific reason why you want to go with ffmpeg 4.x?

[jehutting]

Hmmm... without the LockDecoder\UnlockDecoder the m_cached_size writing is not protected (thread safe). When OMXPlayer hangs on the last frame it gets stuck on omxplayer.cpp code

    if(m_omx_reader.IsEof() && !m_omx_pkt)
    {
      // demuxer EOF, but may have not played out data yet
      if ( (m_has_video && m_player_video.GetCached()) ||
           (m_has_audio && m_player_audio.GetCached()) )
      {
        printf("m_player_video.GetCached()=%d\n", m_player_video.GetCached());
        OMXClock::OMXSleep(10);
        continue;
      }

as a result of the m_cached_size having a value < 0.

Maybe the line m_cached_size -= omx_pkt->size; in the Process() locking with Lock/Unlock will help. Will try this out later...

[devsterj]

Ok, thanks for taking the time to investigate. I forgot to mention that the testing was done with ffmpeg 3.3.9 (the Makefile.ffmpeg in the latest omxplayer includes '-b release/3.3' as git parameters when cloning ffmpeg). I tried ffmpeg 4.1 just once to see if the resume-after-pause -problem would go away before I noticed it was related to the LockDecoder/UnLockDecoder -issue.

[jehutting]

Oh boy... the Lock/Unlock add within the LockDecoder/UnlockDecoder wasn't a success either. Got troubles with seeking commands.

So I tried something different, which seems to be OK (be aware that I thought that the last time too :-)).

Revert the previous mods, and try with the attached patches.
omxplayer.master.loop_20181109-0840.wks.zip

[devsterj]

Ok, I'm gonna give it a go. While waiting for your update, I actually tried just adding Lock/Unlock around the m_cached_size -= omx_pkt->size lines in Process() (OMXPlayerAudio&Video) and did consecutive omxplayer runs for over 10 hours successfully without a freeze glitch.

I haven't done any seek-testing though, and moreover, my understanding of the omxplayer code is not solid enough to even figure out what the Lock & Unlock functions actually do, so I'm grateful for your patches! I just started a new test using them.

Btw, did you drop the hdmi_eos/analog_eos changes in your original OMXAudio.cpp modification on purpose or should I still include them? My test is currently running without the OMXAudio.cpp mods.

[jehutting]

The OMXAudio.cpp mods is in my understanding of openmax better as the renderer should signal that the audio stream is fully played, and not the decoder that it has received/processed the EOS.

[devsterj]

Hmm, can you rephrase that? I'm afraid I don't understand the beginning of your answer 😃 Do you recommend including the original OMXAudio.cpp mods in addition to your latest two patches when compiling the latest omxplayer?

After two hours of consecutive omxplayer runs with your latest patches, I've had no problems. So far so good!

[jehutting]

Yes, you should include the OMXAudio.cpp modifications just to be sure that OMXPlayer terminates after the audio stream has been outputted completely.

As you are playing a video only file, so without audio/sound, it doesn't matter for now.

[devsterj]

Ok, thanks for clarifying. Some files I play have audio as well, so I'll keep the OMXAudio.cpp mod.

[devsterj]

After running tests for over 48h with various video and audio files, I'm happy to report that @jehutting 's OMXPlayerVideo/Audio patches (posted above) and the OMXAudio.cpp mods from May 2016 seem to fix all issues discussed.

Testing done with the latest omxplayer as of Nov 9th 2018 [a70e9b4] (inc. ffmpeg 3.3.9) and the latest firmware updated with rpi-update [4.14.79].

[popcornmix]

@jehutting can you submit a PR with the minimal changes that you believe fixes this issue?
I'd like to understand exactly what the failure path is.

[jehutting]

As I described in #455 :
The problem is that the variable ... m_cached_size is decreased (minus pkt->size) directly after a packet is popped from the queue (/cache) whereas it must be after the popped (end) packet is decoded. This causes the EOS packet to be sent (to the m_decoder) BEFORE the end packet: the result is the video/audio stream is EOS-ed BEFORE the end packet is actually shown by the renderer.

The modifications presented there caused the pause/resume problem as zeepa described above.

The new mods solve the flashing issue differently which seems to work well. Thanks @zeepa for testing it out!

Update:
Will update my loop repository branch and create a new PR.
Created new repository branch white-flash and created PR # 660