Mythfrontend hangs when rewinding and then returning to playback via LIRC remote control

[tomimo@…]

It seems that this particular ticket (#2434) has not been fixed for good in current SVN-head. Please, see the attached backtrace of mythfrontend. The reason why this hang occurs has been explained in the tickets #2434 and #6354) --> ie. it's a problem with incomplete QWaitCondition synchronization.

I'm still able to hang mythfrontend by first fast forwarding a couple of minutes and then rewinding a short bit. Quite often when I now press OK from remote control to continue normal mode playback the frontend hangs.

[tomimo@…]

mythfrontend hang backtrace

[tomimo@…]

This might explain better how the hang can be accomplished with fast forwarding & rewinding. The NuppelVideoPlayer::PauseVideo?() Called and NuppelVideoPlayer::UnpauseVideo?() Called lines are my additions for clarity.

2009-03-16 00:32:44.702 NVP(4): DoPlay() -- begin
2009-03-16 00:32:44.702 AFD: DoRewind(109331, do discard frames)
2009-03-16 00:32:44.702 Dec: DoRewind(109331 (105966), do discard frames)
2009-03-16 00:32:44.702 Dec: FindPostion(109331, search not adjusted) --> [9116(1630821228),9117(1630976892)]
2009-03-16 00:32:44.703 AFD: SeekReset(109330, 1, do flush, do discard)
2009-03-16 00:32:44.704 AFD: SeekReset() flushing
2009-03-16 00:32:44.704 VideoOutputXv: DiscardFrames(1)
2009-03-16 00:32:44.704 VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAAAAAAAAAAAAUAAAAAA
2009-03-16 00:32:44.704 VideoBuffers::DiscardFrames(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2009-03-16 00:32:44.704 VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2009-03-16 00:32:44.704 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2009-03-16 00:32:44.783 NVP(4): ClearAfterSeek(1)
2009-03-16 00:32:44.783 VideoOutputXv: ClearAfterSeek()
2009-03-16 00:32:44.783 VideoOutputXv: DiscardFrames(0)
2009-03-16 00:32:44.783 VideoBuffers::DiscardFrames(0): AAALaAAAAAAAAAAAAAAAAAAAAAAAAAA
2009-03-16 00:32:44.784 VideoBuffers::DiscardFrames(0): AAALaAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2009-03-16 00:32:44.784 VideoOutputXv: DiscardFrames() 3: AAALaAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2009-03-16 00:32:44.784 NVP(4): DoPlay: rate: 25 speed: 1 skip: 1 => new interval 40000
2009-03-16 00:32:44.784 VDP: LoadBestPreferences(704x576, 25)
2009-03-16 00:32:44.784 Set video sync frame interval to 40000
2009-03-16 00:32:44.784 NVP(4): Stretch Factor 1, allow passthru 
2009-03-16 00:32:44.784 NVP(4): DoPlay() -- setting unpaused
2009-03-16 00:32:44.784 NuppelVideoPlayer::PauseVideo() Called
2009-03-16 00:32:45.519 NVP(4): ClearAfterSeek(0)
2009-03-16 00:32:47.035 Waited too long for video out to pause
2009-03-16 00:32:49.536 Waited too long for video out to pause
2009-03-16 00:32:52.036 Waited too long for video out to pause
2009-03-16 00:32:54.537 Waited too long for video out to pause

[tomimo@…]

Ok, it seems that at least in my case the hang comes from the fact that there is absolutely no synchronization between the LIRC remote controller and for example the following code in:

void NuppelVideoPlayer::StartPlaying()
...
        if (rewindtime > 0 && ffrew_skip == 1)
        {
            rewindtime = CalcRWTime(rewindtime);

            if (rewindtime >= 1)
            {
                QMutexLocker locker(&internalPauseLock);

                PauseVideo(true);
                DoRewind();
                UnpauseVideo(true);
            }
            rewindtime = 0;
        }
...

The deadlock usually happens from the fact that while rewinding and then returning to normal playback, the DoPlay?() call comes BEFORE the StartPlaying?'s PauseVideo?()-call and that's it in this case. Nobody will will send the wakeup-signal afterwards. We have to remember that the remote control callback can come pretty much anytime, so wrapping the DoPlay?()'s couple of last lines with QMutexLocker locker(&internalPauseLock) is not enough because the WHOLE StartPlaying?'s huge while loop has not been locked with that same lock. ---> deadlock might become more rare, but eventually there would be a time when the callback would come before the above showed StartPlaying?'s block resulting again another deadlock.

[tomimo@…]

This patch fixes the rewinding hang on mythfrontend

[tomimo@…]

The attached frontend.patch is the version I'm personally using ATM. It does fix the rewinding hang as well.

[tomimo@…]

I've been playing with this problem and I must say that I have not been able to find a really good way to fix this remote controller & video thread race. I'll add another patch that adds a couple of while loops at the end of DoPlay?() and IsVideoActuallyPaused?() which try to avoid the potential race condition hang.

The very same patch also contains some videothread pause/unpause waitcondition fixes which instead of fixing any bugs seem to cause playback errors with the following error messages in the logs "GetNextFreeFrame?() is getting a busy frame P." I'm very curious about the logic how the pause/unpause changes are able to cause this error ...

[tomimo@…]

Another type of rewinding fix + syncronization test changes for the frontend

[Shane Shrybman]

If someone can attach a -v playback log from current trunk, I'll try and take a look.

It is probably useful to add a VERBOSE message in NuppelVideoPlayer::PauseVideo?() and NuppelVideoPlayer::UnpauseVideo?().

[danielk]

no info provided

[tomimo@…]

Sorry, It seems that I've missed gnome42's offer completely. If gnome42 is still willing to check this out, here is a debug log taken with the SVN21761.

I've added the following debug lines:

Index: libs/libmythtv/NuppelVideoPlayer.cpp
===================================================================
--- libs/libmythtv/NuppelVideoPlayer.cpp	(revision 21761)
+++ libs/libmythtv/NuppelVideoPlayer.cpp	(working copy)
@@ -575,6 +575,9 @@
 
 void NuppelVideoPlayer::PauseVideo(bool wait)
 {
+    VERBOSE(VB_PLAYBACK, LOC_WARN +
+                "NuppelVideoPlayer::PauseVideo() Called!");
+
     QMutexLocker locker(&pauseUnpauseLock);
     video_actually_paused = false;
     pausevideo = true;
@@ -589,10 +592,14 @@
         if ((i % 10) == 9)
             VERBOSE(VB_IMPORTANT, "Waited too long for video out to pause");
     }
+    VERBOSE(VB_PLAYBACK, LOC_WARN +
+                "NuppelVideoPlayer::PauseVideo() End!");
 }
 
 void NuppelVideoPlayer::UnpauseVideo(bool wait)
 {
+    VERBOSE(VB_PLAYBACK, LOC_WARN +
+                "NuppelVideoPlayer::UnpauseVideo() Called!");
     QMutexLocker locker(&pauseUnpauseLock);
     pausevideo = false;
 
@@ -606,6 +613,8 @@
         if ((i % 10) == 9)
             VERBOSE(VB_IMPORTANT, "Waited too long for video out to unpause");
     }
+    VERBOSE(VB_PLAYBACK, LOC_WARN +
+                "NuppelVideoPlayer::UnpauseVideo() End!");
 }
 
 void NuppelVideoPlayer::SetVideoActuallyPaused(bool val)

The key to reproducing this problem seems to be a slightly slow machine (2.8GHz, diskless Amd Athlon) with a lirc based remote controller (Microsoft media remote controller) and the following procedure:

1. Fast forward for 5-10 secs
2. Stop
3. Quickly fast rewind for a few seconds and then immediately hit Play again!

The above procedure seems to hit the a race condition where the pause/unpause order goes completely haywire and therefore the frontend never gets woken up again from pause.

[tomimo@…]

Latest debug log with mythfrontend -v playback

[Shane Shrybman]

Ok, I'll take a look but it may not be for a while. If someone else beats me to it, that's cool too. :)

[jwernerny@…]

I'm seeing this same bug on several machines (all in the 1 GHz range). Contrary to previous reports, it does not require lirc. It can be done simply from a keyboard.

Here is the version info for mythfrontend:

MythTV Version   : 22546M
MythTV Branch    : trunk
Network Protocol : 50
Library API      : 0.22.20091016-1
QT Version       : 4.4.0
Options compiled in:
 linux release using_oss using_alsa using_pulse using_arts using_jack using_backend using_directfb using_dvb using_frontend using_hdhomerun using_hdpvr using_iptv using_ivtv using_joystick_menu using_libfftw3 using_lirc using_mheg using_opengl_video using_opengl_vsync using_qtwebkit using_v4l using_x11 using_xrandr using_xv using_xvmc using_xvmc_vld using_xvmcw using_bindings_perl using_bindings_python using_opengl using_ffmpeg_threads using_live using_mheg
j

[robertm]

Closing as extremely stale and possibly no longer applicable post-MythUI OSD Merge. New ticket if it exists in .24.