[mythtv] Streaming Prebuffering Pause

Tue Feb 15 04:32:52 UTC 2005

Ok, I've been watching verbose output till my eyes are bleeding, and I
have a couple things to add / clarifiy:

1. With XvMC the lockups ONLY occur on my frontend when the OSD is
fading out after a FFW / RW / etc.

2. Without XvMC the lockups occur when FFW/RW.

I have a pile of -v debug, but here's the one thing that jumped out:

2005-02-14 20:45:26.498 Timed out waiting for free video buffers.

Because the audio is showing "Paused" at this point, it doesn't appear
to be an audio problem. I did try the patch suggested in another
thread with no help.

I'm not able to get the data I wanted from GDB, call it inexperience,
so unfortunately, the best I have is from -v playback from
mythfrontend.

It doesn't appear to be a network or backend problem, that I can tell.
I had mythbackend -v all and the logging simply stops. Once the
frontend is killed, it shows the frontend disconnecting, so it doesn't
appear the backend locked.

Anyway, here's the logs:

[mythtv at frontend1 ~]$ mythfrontend -v playback,osd,file,network
2005-02-14 21:25:20.849 mythfrontend version: 0.17.20050130-1 www.mythtv.org
2005-02-14 21:25:20.849 Enabled verbose msgs : important general
playback osd file network
2005-02-14 21:25:21.092 Switching to square mode (Iulius)
2005-02-14 21:25:21.379 Registering Internal as a media playback plugin.
2005-02-14 21:25:21.415 Registering MythDVD DVD Media Handler as a media handler
2005-02-14 21:25:21.524 generating cache image for:
/usr/local/share/mythtv/themes/default/blank.png
2005-02-14 21:25:26.545 All Programs
2005-02-14 21:25:27.118 Connecting to backend server:
192.168.2.222:6543 (try 1 of 50)
2005-02-14 21:25:27.119 write->10 21      MYTH_PROTO_VERSION 14:
2005-02-14 21:25:27.126 Using protocol version 14
2005-02-14 21:25:27.126 write->10 24      ANN Playback frontend1 0:
2005-02-14 21:25:27.178 write->10 21      QUERY_RECORDINGS Play:
2005-02-14 21:25:27.468 write->13 24      ANN Playback frontend1 0:
2005-02-14 21:25:27.481 write->14 74      ANN FileTransfer
frontend1[]:[]/2081_...
2005-02-14 21:25:28.069 write->13 45      QUERY_FILETRANSFER
47[]:[]REQUEST_BLO...
2005-02-14 21:25:28.076 Read(): reqd=0, rcvd=0, rept=0, error=0
2005-02-14 21:25:28.076 write->13 30      QUERY_FILETRANSFER 47[]:[]DONE:
2005-02-14 21:25:28.083 write->10 632     QUERY_GENPIXMAP[]:[]CSI:
Miami[]:[]Id...
2005-02-14 21:25:30.945 write->13 24      ANN Playback frontend1 0:
2005-02-14 21:25:31.379 write->14 74      ANN FileTransfer
frontend1[]:[]/2081_...
2005-02-14 21:25:31.388 write->13 49      QUERY_FILETRANSFER
47[]:[]REQUEST_BLO...
2005-02-14 21:25:31.413 Read(): reqd=28257, rcvd=28257, rept=28257, error=0
2005-02-14 21:25:31.413 write->13 30      QUERY_FILETRANSFER 47[]:[]DONE:
2005-02-14 21:25:31.843 write->13 24      ANN Playback frontend1 0:
2005-02-14 21:25:31.907 write->14 74      ANN FileTransfer
frontend1[]:[]/1015_...
2005-02-14 21:25:31.942 write->13 49      QUERY_FILETRANSFER
47[]:[]REQUEST_BLO...
2005-02-14 21:25:31.960 Read(): reqd=32601, rcvd=32601, rept=32601, error=0
2005-02-14 21:25:31.960 write->13 30      QUERY_FILETRANSFER 47[]:[]DONE:
2005-02-14 21:25:31.977 24      ANN Playback frontend1 1
2005-02-14 21:25:33.110 write->13 24      ANN Playback frontend1 0:
2005-02-14 21:25:33.128 write->14 74      ANN FileTransfer
frontend1[]:[]/2094_...
2005-02-14 21:25:33.137 write->13 49      QUERY_FILETRANSFER
47[]:[]REQUEST_BLO...
2005-02-14 21:25:33.145 Read(): reqd=25410, rcvd=25410, rept=25410, error=0
2005-02-14 21:25:33.145 write->13 30      QUERY_FILETRANSFER 47[]:[]DONE:
2005-02-14 21:25:34.174 write->13 24      ANN Playback frontend1 0:
2005-02-14 21:25:34.206 write->14 74      ANN FileTransfer
frontend1[]:[]/2081_...
2005-02-14 21:25:34.235 write->13 49      QUERY_FILETRANSFER
47[]:[]REQUEST_BLO...
2005-02-14 21:25:34.243 Read(): reqd=18855, rcvd=18855, rept=18855, error=0
2005-02-14 21:25:34.243 write->13 30      QUERY_FILETRANSFER 47[]:[]DONE:
2005-02-14 21:25:36.171 write->13 24      ANN Playback frontend1 0:
2005-02-14 21:25:36.470 write->14 74      ANN FileTransfer
frontend1[]:[]/1005_...
2005-02-14 21:25:36.577 write->13 49      QUERY_FILETRANSFER
47[]:[]REQUEST_BLO...
2005-02-14 21:25:36.585 Read(): reqd=25498, rcvd=25498, rept=25498, error=0
2005-02-14 21:25:36.585 write->13 30      QUERY_FILETRANSFER 47[]:[]DONE:
2005-02-14 21:25:36.801 write->10 598     QUERY_CHECKFILE[]:[]CSI:
Crime Scene ...
2005-02-14 21:25:36.942 AVFD
2005-02-14 21:25:36.942 AVFD: Opening Stream #0: codec id 2
2005-02-14 21:25:36.944 Using libmpeg2 for video decoding
2005-02-14 21:25:36.945 detectInterlace(Detect Scan, Detect Scan,
29.97, 480) ->Interlaced Scan
2005-02-14 21:25:36.945 Interlaced: Interlaced Scan  video_height: 480
 fps: 29.97
2005-02-14 21:25:36.945 AVFD: Looking for decoder for 2
2005-02-14 21:25:36.945 AVFD
2005-02-14 21:25:36.945 AVFD: Opening Stream #1: codec id 86016
2005-02-14 21:25:36.945 AVFD: Looking for decoder for 86016
2005-02-14 21:25:36.947 Estimated bitrate = 16384
2005-02-14 21:25:37.218 Position map filled from DB to: 7184
2005-02-14 21:25:37.218 SyncPositionMap prerecorded, from DB: 7185 entries
2005-02-14 21:25:37.219 Position map found
2005-02-14 21:25:37.224 Opening audio device '/dev/adsp'.
2005-02-14 21:25:37.225 Opening OSS audio device '/dev/adsp'.
2005-02-14 21:25:37.236 Over/underscan. V: 0, H: 0, XOff: 0, YOff: 0
2005-02-14 21:25:37.241 Using XV port 145
2005-02-14 21:25:37.245 Image size. dispxoff 111, dispyoff: 0,
dispwoff: 666, disphoff: 508
2005-02-14 21:25:37.245 Image size. imgx 0, imgy: 0, imgw: 720, imgh: 480
2005-02-14 21:25:37.656 Realtime priority would require SUID as root.
2005-02-14 21:25:37.657 Changing from None to WatchingPreRecorded
2005-02-14 21:25:37.667 Using deinterlace method bobdeint
2005-02-14 21:25:37.768 nVidiaVideoSync: VBlank ioctl did not work,
unimplemented in this driver?
2005-02-14 21:25:37.768 DRMVideoSync: Could not open device
/dev/dri/card0, No such file or directory
2005-02-14 21:25:37.768 Using audio as timebase
2005-02-14 21:25:37.768 Video timing method: RTC
2005-02-14 21:25:37.768 Refresh rate: 16663, frame interval: 33366
2005-02-14 21:25:37.769 waiting for prebuffer...
'video_output' mean = '33528.13', std. dev. = '1778.35', fps = '29.83'
'video_output' mean = '33360.60', std. dev. = '384.26', fps = '29.98'
'video_output' mean = '33354.05', std. dev. = '359.64', fps = '29.98'
'video_output' mean = '33363.73', std. dev. = '368.82', fps = '29.97'
'video_output' mean = '33360.67', std. dev. = '369.68', fps = '29.98'
'video_output' mean = '33363.49', std. dev. = '365.59', fps = '29.97'

<at this point, the video freezes, and the "prebuffer" messages go by
at 99 lines a second (figuratively)

2005-02-14 21:25:59.056 waiting for prebuffer...
2005-02-14 21:26:01.695 prebuffering pause
2005-02-14 21:26:01.695 waiting for prebuffer...
2005-02-14 21:26:01.707 prebuffering pause
2005-02-14 21:26:01.707 waiting for prebuffer...
2005-02-14 21:26:01.718 prebuffering pause
2005-02-14 21:26:01.718 waiting for prebuffer...
2005-02-14 21:26:01.729 prebuffering pause
2005-02-14 21:26:01.729 waiting for prebuffer...
2005-02-14 21:26:01.740 prebuffering pause

<ad nausem>

If any of the devs can tell me either additional tests to run,
features to flip off/on, etc, I will HAPPILY provide it.

Here's the snippet of code we seem to be running into, or at least
that's reporting:

NuppelVideoPlayer.cpp

if (!videoOutput->EnoughFreeFrames() && !unsafe)
        {
            //cout << "waiting for video buffer to drain.\n";
            setPrebuffering(false);
            if (!videoOutput->availableVideoBuffersWait()->wait(10))
            {
                if (++videobuf_retries >= 200)
                {
                    VERBOSE(VB_IMPORTANT, "Timed out waiting for free
video buffers.");
                    if (videosync==NULL && tryingVideoSync)
                    {
                        VERBOSE(VB_IMPORTANT, "Attempting video sync
thread restart");
                        //pthread_create(&output_video, NULL,
kickoffOutputVideoLoop, this);
                    }
                    videobuf_retries = 0;
                }
                return false;
            }

On Mon, 14 Feb 2005 12:05:02 -0500, Bruce C. Dillahunty
<bdillahu at peachbush.com> wrote:
> Brian Foddy wrote:
> > On Sunday 13 February 2005 09:11 pm, Blammo [doh] wrote:
> >
> >>Still happening here.. Had to shut off XvMC to get it to resolve.
> >>Never happened under 0.16
> >>
> 
> Me to... nvidia setup... pause with XvMC enabled hangs the frontend...
> really acts like things that update the OSD hang the frontend.
> 
> Bruce
> 
> _______________________________________________
> mythtv-dev mailing list
> mythtv-dev at mythtv.org
> http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-dev
>