Opened 11 years ago

Closed 9 years ago

#6355 closed defect (fixed)

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

Reported by: tomimo@… Owned by:
Priority: minor Milestone: unknown
Component: MythTV - Video Playback Version: head
Severity: medium Keywords: mythfrontend lirc remote control hang rewinding
Cc: Ticket locked: no

Description

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.

Attachments (4)

mythfrontend.log (11.7 KB) - added by tomimo@… 11 years ago.
mythfrontend hang backtrace
frontend.patch (6.4 KB) - added by tomimo@… 11 years ago.
This patch fixes the rewinding hang on mythfrontend
rewinding_bug.patch (4.6 KB) - added by tomimo@… 10 years ago.
Another type of rewinding fix + syncronization test changes for the frontend
hang.log (194.5 KB) - added by tomimo@… 10 years ago.
Latest debug log with mythfrontend -v playback

Download all attachments as: .zip

Change History (16)

Changed 11 years ago by tomimo@…

Attachment: mythfrontend.log added

mythfrontend hang backtrace

comment:1 Changed 11 years ago by 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

comment:2 Changed 11 years ago by 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.

Changed 11 years ago by tomimo@…

Attachment: frontend.patch added

This patch fixes the rewinding hang on mythfrontend

comment:3 Changed 11 years ago by tomimo@…

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

comment:4 Changed 10 years ago by 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 ...

Changed 10 years ago by tomimo@…

Attachment: rewinding_bug.patch added

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

comment:5 Changed 10 years ago by Shane Shrybman

Status: newinfoneeded_new

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?().

comment:6 Changed 10 years ago by danielk

Resolution: invalid
Status: infoneeded_newclosed

no info provided

comment:7 Changed 10 years ago by 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.

Changed 10 years ago by tomimo@…

Attachment: hang.log added

Latest debug log with mythfrontend -v playback

comment:8 Changed 10 years ago by paulh

Resolution: invalid
Status: closednew

comment:9 Changed 10 years ago by Shane Shrybman

Owner: changed from Isaac Richards to Shane Shrybman
Status: newaccepted

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. :)

comment:10 Changed 10 years ago by 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

comment:11 Changed 9 years ago by Shane Shrybman

Owner: Shane Shrybman deleted
Status: acceptednew

comment:12 Changed 9 years ago by robertm

Resolution: fixed
Status: newclosed

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

Note: See TracTickets for help on using tickets.