[mythtv-users] Please Wait .... and then no video

[Chuck Filson]

I have run into a problem that may be related to vdpau or 0.22 playback ( or 
both ). All recordings from PVR-150 and HDHR recorders playback correctly 
over a several hour period. That is several different recordings played one 
after the other. 

Then when the next recording is selected for playback there is no video. 
The 'Please Wait' screen shows up and the audio starts, but there is never 
any of the video. Controls such as volume and skip forward and back are still 
working as well as esc to exit the playback. But I am left watching 'Please 
Wait'.

Once this has happened, most recordings will not play and result in the same 
problem. However if enough recordings are tried, eventually one will play. 
Going back to one of the failed recordings still fails to play. The 
recordings most likely to play when this occurs are from the HDHR, but not 
always.

The only way to fix this problem is to stop and then restart mythfrontend. A 
machine reboot is not required.

I am currently running VDPAU 'High Quality' profile with NVIDIA 190.42.drivers 
on a Geforce 9500GT with 1 mb memory and the following frontend version on a 
separate frontend machine ( this hardware was running 0.21 without VDPAU 
previously with no problems ).

$ mythfrontend --version
Please include all output in bug reports.
MythTV Version   : 22909
MythTV Branch    : branches/release-0-22-fixes
Network Protocol : 50
Library API      : 0.22.20091023-1
QT Version       : 4.5.2
Options compiled in:
 linux release using_oss using_alsa using_arts using_jack using_backend 
using_directfb using_frontend using_hdhomerun using_ivtv using_lirc 
using_mheg using_opengl_video using_opengl_vsync using_qtwebkit using_v4l 
using_x11 using_xrandr using_xv using_xvmc using_bindings_perl 
using_bindings_python using_opengl using_vdpau using_ffmpeg_threads 
using_mheg

There is no indication of any errors in the backend log, only the fact that 
playback was started with the following backend log excerpt:

2009-11-26 01:28:06.525 MainServer::ANN Playback
2009-11-26 01:28:06.527 adding: characodon as a client (events: 0)
2009-11-26 01:28:06.529 MainServer::HandleAnnounce FileTransfer
2009-11-26 01:28:06.532 adding: characodon as a remote file transfer

The frontend log with -v playback for the sartup and then the problem period 
follows:

2009-11-25 21:47:11.100 mythfrontend version: branches/release-0-22-fixes 
[22909] www.mythtv.org
2009-11-25 21:47:11.100 Using runtime prefix = /usr/local
2009-11-25 21:47:11.100 Using configuration directory = /home/chuck/.mythtv
2009-11-25 21:47:12.056 Empty LocalHostName.
2009-11-25 21:47:12.056 Using localhost value of characodon
2009-11-25 21:47:12.272 New DB connection, total: 1
2009-11-25 21:47:12.388 Connected to database 'mythconverg' at host: 
192.168.0.3
2009-11-25 21:47:12.388 Closing DB connection named 'DBManager0'
2009-11-25 21:47:12.435 ScreenSaverX11Private: XScreenSaver support enabled
2009-11-25 21:47:12.436 DPMS is disabled.
2009-11-25 21:47:12.476 Primary screen: 0.
2009-11-25 21:47:12.478 Connected to database 'mythconverg' at host: 
192.168.0.3
2009-11-25 21:47:12.480 Using screen 0, 1920x1080 at 0,0
2009-11-25 21:47:12.546 MythUI Image Cache size set to 20971520 bytes
2009-11-25 21:47:12.546 user: 500 effective user: 500 before privileged thread
2009-11-25 21:47:12.546 user: 500 effective user: 500 after privileged thread
2009-11-25 21:47:12.546 Enabled verbose msgs:  important general playback
2009-11-25 21:47:12.546 user: 500 effective user: 500 run_priv_thread
2009-11-25 21:47:12.641 Primary screen: 0.
2009-11-25 21:47:12.643 Using screen 0, 1920x1080 at 0,0
2009-11-25 21:47:12.716 Using theme base resolution of 1280x720
2009-11-25 21:47:12.806 LIRC: Successfully initialized '/dev/lircd' 
using '/home/chuck/.mythtv/lircrc' config
2009-11-25 21:47:13.504 Using the Qt painter
2009-11-25 21:47:14.148 Loaded base theme 
from /usr/local/share/mythtv/themes/Mythbuntu/base.xml
2009-11-25 21:47:14.186 Loaded base theme 
from /usr/local/share/mythtv/themes/default-wide/base.xml
2009-11-25 21:47:14.220 Loaded base theme 
from /usr/local/share/mythtv/themes/default/base.xml
2009-11-25 21:47:14.221 Unable to load window 'backgroundwindow' from base
2009-11-25 21:47:14.230 Current MythTV Schema Version (DBSchemaVer): 1244
2009-11-25 21:47:17.188 Desktop video mode: 1920x1080 60.0024 Hz
2009-11-25 21:47:17.225 max_width: 1920 max_height: 1080
2009-11-25 21:47:17.615 Registering Internal as a media playback plugin.
2009-11-25 21:47:17.715 Registering WebBrowser as a media playback plugin.
2009-11-25 21:47:19.626 Current MythMusic Schema Version (MusicDBSchemaVer): 
1017
2009-11-25 21:47:19.745 MMUnix::AddDevice() Error: failed to stat /dev/bdi, 
			eno: No such file or directory (2)
2009-11-25 21:47:19.748 MMUnix::AddDevice() Error: failed to stat /dev/power, 
			eno: No such file or directory (2)
2009-11-25 21:47:19.752 MonitorRegisterExtensions(0x40, 
mp3,mp2,ogg,oga,flac,wma,wav,ac3,oma,omg,atp,ra,dts,aac,m4a,aa3,tta,mka,aiff,swa,wv)
2009-11-25 21:47:19.946 Current MythVideo Schema Version 
(mythvideo.DBSchemaVer): 1028
2009-11-25 21:47:20.260 Starting update of ENVCAN
2009-11-25 21:47:20.271 Loading window theme 
from /usr/local/share/mythtv/themes/Mythbuntu/menu-ui.xml
2009-11-25 21:47:20.631 Loading menu theme 
from /usr/local/share/mythtv/themes/defaultmenu//mainmenu.xml
2009-11-25 21:47:20.634 Found mainmenu.xml for theme 'Mythbuntu'
2009-11-25 21:47:23.225 MythContext: Connecting to backend server: 
192.168.0.3:6543 (try 1 of 1)
2009-11-25 21:47:23.226 Using protocol version 50
2009-11-25 21:47:23.330 Warning! Time difference between the master backend 
and this system is 54 seconds.
2009-11-25 
21:47:23.568 'nice /usr/local/share/mythtv/mythweather/scripts/ca_envcan/envcan.pl -u 
SI -d /home/chuck/.mythtv/MythWeather/ENVCAN on-24' has exited
2009-11-25 22:02:20.261 Starting update of ENVCAN
2009-11-25 22:02:20.262 ENVCAN recently updated, skipping.
2009-11-25 22:14:48.550 ScreenSaverX11Private: Calling 
xscreensaver-command -deactivate
2009-11-25 22:14:50.849 Loading menu theme 
from /usr/local/share/mythtv/themes/defaultmenu//library.xml
2009-11-25 22:14:53.659 New DB connection, total: 2
2009-11-25 22:14:53.661 Connected to database 'mythconverg' at host: 
192.168.0.3
2009-11-25 22:14:53.664 Loading window theme 
from /usr/local/share/mythtv/themes/Mythbuntu/recordings-ui.xml
2009-11-25 22:14:54.453 MythContext: Connecting to backend server: 
192.168.0.3:6543 (try 1 of 1)
2009-11-25 22:14:54.466 Using protocol version 50
2009-11-25 22:14:55.143 MythContext: Connecting to backend server: 
192.168.0.3:6543 (try 1 of 1)
2009-11-25 22:14:55.144 Using protocol version 50
2009-11-25 22:14:59.515 
Saved: '/home/chuck/.mythtv/remotecache/2071_20091125215900.mpg.png'
2009-11-25 22:14:59.520 Preview: previewThreadDone took 5ms
2009-11-25 22:14:59.528 
Saved: '/home/chuck/.mythtv/remotecache/2041_20091125220000.mpg.png'
2009-11-25 22:14:59.533 Preview: previewThreadDone took 5ms

SNIP

2009-11-26 00:55:33.238 TV: StartTV() -- begin
2009-11-26 00:55:33.238 TV: ctor
2009-11-26 00:55:33.307 TV: DrawUnusedRects() -- begin
2009-11-26 00:55:33.307 TV: DrawUnusedRects() -- end
2009-11-26 00:55:33.307 TV: DrawUnusedRects() -- begin
2009-11-26 00:55:33.307 TV: DrawUnusedRects() -- end
2009-11-26 00:55:33.365 TV: tv->Playback() -- begin
2009-11-26 00:55:33.380 TV: tv->Playback() -- end
2009-11-26 00:55:33.380 TV: StartTV -- process events begin
2009-11-26 00:55:33.401 TV: HandleStateChange(0) -- begin
2009-11-26 00:55:33.401 TV: Attempting to change from None to Watching 
WatchingPreRecorded
2009-11-26 00:55:33.402 
RingBuf(myth://192.168.0.3:6543/1603_20091120075800.mpg): 
OpenFile(myth://192.168.0.3:6543/1603_20091120075800.mpg, 12)
2009-11-26 00:55:33.456 
RingBuf(myth://192.168.0.3:6543/1603_20091120075800.mpg): 
CalcReadAheadThresh(0 KB)
			 -> threshhold(64 KB) min read(0 KB) blk size(32 KB)
2009-11-26 00:55:33.506 TV: StartPlayer(0, Watching WatchingPreRecorded, 
main) -- begin
2009-11-26 00:55:34.061 AFD: Stream #0, has id 0x1e0 codec id MPEG2VIDEO, type 
Video, bitrate 6000000 at 0x9f63c900
2009-11-26 00:55:34.064 VDP: Accepting: cmp(> 0 0) dec(vdpau) cpus(1) 
rend(vdpau) osd(vdpau) osdfade(disabled) 
deint(vdpauadvanceddoublerate,vdpauadvanced) filt()
2009-11-26 00:55:34.065 VDP: LoadBestPreferences(2048x2048, 0)
2009-11-26 00:55:34.065 VDP: LoadBestPreferences(2048x2048, 60)
2009-11-26 00:55:34.065 VDP: LoadBestPreferences(720x480, 60)
2009-11-26 00:55:34.068 VDP: Accepting: cmp(> 0 0) dec(vdpau) cpus(1) 
rend(vdpau) osd(vdpau) osdfade(disabled) 
deint(vdpauadvanceddoublerate,vdpauadvanced) filt()
2009-11-26 00:55:34.069 VDP: LoadBestPreferences(2048x2048, 0)
2009-11-26 00:55:34.069 VDP: LoadBestPreferences(2048x2048, 60)
2009-11-26 00:55:34.069 VDP: LoadBestPreferences(720x480, 60)
2009-11-26 00:55:34.072 VDP: Accepting: cmp(> 0 0) dec(vdpau) cpus(1) 
rend(vdpau) osd(vdpau) osdfade(disabled) 
deint(vdpauadvanceddoublerate,vdpauadvanced) filt()
2009-11-26 00:55:34.072 VDP: LoadBestPreferences(2048x2048, 0)
2009-11-26 00:55:34.072 VDP: LoadBestPreferences(2048x2048, 60)
2009-11-26 00:55:34.072 VDP: LoadBestPreferences(720x480, 60)
2009-11-26 00:55:34.073 Using 1 CPUs for decoding
2009-11-26 00:55:34.073 AFD: InitVideoCodec() 0x9f63cac0 id(MPEG2VIDEO) type 
(Video).
2009-11-26 00:55:34.074 detectInterlace(Detect Scan, Interlaced Scan, 29.97, 
480) ->Interlaced Scan
2009-11-26 00:55:34.074 AFD: Using vdpau for video decoding
2009-11-26 00:55:34.074 AFD: Looking for decoder for MPEG2VIDEO
2009-11-26 00:55:34.074 AFD: Opened codec 0x9f63cac0, id(MPEG2VIDEO) 
type(Video)
2009-11-26 00:55:34.074 AFD: Stream #1, has id 0x1c0 codec id MP2, type Audio, 
bitrate 384000 at 0x9f63ce70
2009-11-26 00:55:34.074 AFD: codec MP2 has 2 channels
2009-11-26 00:55:34.074 AFD: Looking for decoder for MP2
2009-11-26 00:55:34.074 AFD: Opened codec 0x9f63d040, id(MP2) type(Audio)
2009-11-26 00:55:34.074 
RingBuf(myth://192.168.0.3:6543/1603_20091120075800.mpg): 
CalcReadAheadThresh(0 KB)
			 -> threshhold(64 KB) min read(0 KB) blk size(32 KB)
2009-11-26 00:55:34.076 Opening audio device 'default'. ch 2(2) sr 48000
2009-11-26 00:55:34.076 Opening ALSA audio device 'default'.
2009-11-26 00:55:34.079 Mixer unable to find control Master 1
2009-11-26 00:55:34.080 mixer unable to find control Master 1
2009-11-26 00:55:34.080 Mixer unable to find control Master 1
2009-11-26 00:55:34.080 mixer unable to find control Master 1
2009-11-26 00:55:34.080 Dec: Trying to select track (w/lang)
2009-11-26 00:55:34.080 Dec: Selecting first track
2009-11-26 00:55:34.080 Dec: Selected track #1 in the Unknown language(0)
2009-11-26 00:55:34.080 Dec: Resyncing position map. posmapStarted = 0 
livetv(0) watchingRec(0)
2009-11-26 00:55:34.134 Position map filled from DB to: 61005
2009-11-26 00:55:34.135 Dec: SyncPositionMap prerecorded, from DB: 4073 
entries
2009-11-26 00:55:34.135 Dec: SyncPositionMap, new totframes: 61005, new 
length: 2035, posMap size: 4073
2009-11-26 00:55:34.135 AFD: Position map found
2009-11-26 00:55:34.135 AFD: Successfully opened decoder for 
file: "myth://192.168.0.3:6543/1603_20091120075800.mpg". novideo(0)
2009-11-26 00:55:34.142 VideoOutput: Allowed renderers: vdpau
2009-11-26 00:55:34.142 VideoOutput: Allowed renderers (filt: vdpau): vdpau
2009-11-26 00:55:34.148 VDP: Accepting: cmp(> 0 0) dec(vdpau) cpus(1) 
rend(vdpau) osd(vdpau) osdfade(disabled) 
deint(vdpauadvanceddoublerate,vdpauadvanced) filt()
2009-11-26 00:55:34.148 VDP: LoadBestPreferences(2048x2048, 0)
2009-11-26 00:55:34.148 VDP: LoadBestPreferences(2048x2048, 60)
2009-11-26 00:55:34.148 VDP: LoadBestPreferences(720x480, 60)
2009-11-26 00:55:34.148 VideoOutput: Preferred renderer: vdpau
2009-11-26 00:55:34.148 VideoOutput: Trying video renderer: 'vdpau'
2009-11-26 00:55:34.177 VDP: Accepting: cmp(> 0 0) dec(vdpau) cpus(1) 
rend(vdpau) osd(vdpau) osdfade(disabled) 
deint(vdpauadvanceddoublerate,vdpauadvanced) filt()
2009-11-26 00:55:34.177 VDP: LoadBestPreferences(2048x2048, 0)
2009-11-26 00:55:34.177 VDP: LoadBestPreferences(2048x2048, 60)
2009-11-26 00:55:34.191 VideoOutWindow::SetPIPState. pip_state: 0]
2009-11-26 00:55:34.191 Display Rect  left: 0, top: 0, width: 1920, height: 
1080, aspect: 1.33333
2009-11-26 00:55:34.191 Video Rect    left: 0, top: 0, width: 720, height: 
480, aspect: 1.33333
2009-11-26 00:55:34.192 VDP: LoadBestPreferences(720x480, 60)
2009-11-26 00:55:34.192 Display Rect  left: 0, top: 0, width: 1920, height: 
1080, aspect: 1.33333
2009-11-26 00:55:34.192 Video Rect    left: 0, top: 0, width: 720, height: 
480, aspect: 1.33333
2009-11-26 00:55:34.192 VDP: SetVideoRenderer(vdpau)
2009-11-26 00:55:34.192 VDP: SetVideoRender(vdpau) == GetVideoRenderer()
2009-11-26 00:55:34.194 VidOutVDPAU: VDPAU Colorkey: 0x20202 (depth 24)
2009-11-26 00:55:34.195 VideoOutput: Pixel dimensions: Screen 1920x1080, 
window 1920x1080
2009-11-26 00:55:34.195 VideoOutput: Actual display dimensions: 827x465 mm  
Aspect: 1.77849
2009-11-26 00:55:34.195 VideoOutput: Estimated window dimensions: 827x465 mm  
Aspect: 1.77849
2009-11-26 00:55:34.306 Display Rect  left: 240, top: 0, width: 1440, height: 
1080, aspect: 1.77778
2009-11-26 00:55:34.306 Video Rect    left: 0, top: 0, width: 720, height: 
480, aspect: 1.33333
2009-11-26 00:55:34.306 VidOutVDPAU: Created VDPAU context (GPU decode)
2009-11-26 00:55:34.308 VDPAU: Created OSD (1920x1080)
2009-11-26 00:55:34.313 Over/underscan. V: 0, H: 0
2009-11-26 00:55:34.313 Display Rect  left: 240, top: 0, width: 1440, height: 
1080, aspect: 1.77778
2009-11-26 00:55:34.313 Video Rect    left: 0, top: 0, width: 720, height: 
480, aspect: 1.33333
2009-11-26 00:55:34.313 VDP: LoadBestPreferences(720x480, 29.97)
2009-11-26 00:55:34.313 NVP(4): Forcing decode extra audio option on (Video 
method requires it).
2009-11-26 00:55:34.313 NVP(4): LoadFilters(''..) -> 0x0
2009-11-26 00:55:34.314 OSD Theme Dimensions W: 640 H: 480
2009-11-26 00:55:34.583 playCtx: StartDecoderThread(): took 442 ms to start 
player.
2009-11-26 00:55:34.583 TV: StartPlayer(0, Watching WatchingPreRecorded, 
main) -- end ok
2009-11-26 00:55:34.584 NVP(4): ClearAfterSeek(1)
2009-11-26 00:55:34.584 VidOutVDPAU: ClearAfterSeek()
2009-11-26 00:55:34.584 VidOutVDPAU: DiscardFrames(0)
2009-11-26 00:55:34.584 VideoBuffers::DiscardFrames(0): AAAAAAAAAAAAAAAAA
2009-11-26 00:55:34.584 VideoBuffers::DiscardFrames(0): AAAAAAAAAAAAAAAAA -- 
done
2009-11-26 00:55:34.584 VidOutVDPAU: DiscardFrames() 3: AAAAAAAAAAAAAAAAA -- 
done()
2009-11-26 00:55:34.584 TV: Changing from None to Watching WatchingPreRecorded
2009-11-26 00:55:34.585 The realtime priority setting is not enabled.
2009-11-26 00:55:34.585 VDP: GetFilteredDeint() : 
vdpau -> 'vdpauadvanceddoublerate'
2009-11-26 00:55:34.586 TV: HandleStateChange(0) -- end
2009-11-26 00:55:34.586 DRMVideoSync: Could not open device /dev/dri/card0, No 
such file or directory
2009-11-26 00:55:34.586 RTCVideoSync: Could not set RTC frequency, Permission 
denied.
2009-11-26 00:55:34.586 Set video sync frame interval to 33366
2009-11-26 00:55:34.587 Using audio as timebase
2009-11-26 00:55:34.587 Video timing method: USleep with busy wait
2009-11-26 00:55:34.587 Refresh rate: 16666, frame interval: 33366
2009-11-26 00:55:34.587 NVP(4): Waiting for prebuffer..  0 AAAAAAAAAAAAAAAAA
2009-11-26 00:55:34.596 VDPAU: Created VDPAU decoder (2 ref frames)
2009-11-26 00:55:34.598 Detect Letterbox: The source is not a supported frame 
format (was 11)
2009-11-26 00:55:34.607 ScreenSaverX11Private: ResetTimer -- begin
2009-11-26 00:55:34.608 ScreenSaverX11Private: StopTimer
2009-11-26 00:55:34.608 ScreenSaverX11Private: StartTimer
2009-11-26 00:55:34.608 ScreenSaverX11Private: ResetTimer -- end
2009-11-26 00:55:34.718 VDPAU: Using 4 output surfaces (max 4)
'video_output' mean = '33360.22', std. dev. = '94.09', fps = '29.98'
2009-11-26 00:55:40.391 TV: SetActive(0,w/o OSD) 0 -> 0 -- begin
2009-11-26 00:55:40.391 TV: SetActive(0,w/o OSD) 0 -> 0 -- end
2009-11-26 00:55:40.431 TV: HandleStateChange(0) -- begin
2009-11-26 00:55:40.431 TV: Attempting to change from Watching 
WatchingPreRecorded to None
2009-11-26 00:55:40.431 TV: StopStuff() for player ctx 0 -- begin
2009-11-26 00:55:40.432 TV: SetActive(0,w/o OSD) 0 -> 0 -- begin
2009-11-26 00:55:40.432 TV: SetActive(0,w/o OSD) 0 -> 0 -- end
2009-11-26 00:55:40.432 TV: StopStuff(): stopping ring buffer
2009-11-26 00:55:40.434 TV: StopStuff(): stopping player
2009-11-26 00:55:40.434 TV: StopStuff() -- end
2009-11-26 00:55:40.434 TV: Changing from Watching WatchingPreRecorded to None
2009-11-26 00:55:40.434 TV: HandleStateChange(0) -- end
2009-11-26 00:55:40.434 TV: StartTV -- process events end
2009-11-26 00:55:40.434 TV: StartTV -- process events 2 begin
2009-11-26 00:55:40.434 ScreenSaverX11Private: StopTimer
2009-11-26 00:55:40.434 TV: StartTV -- process events 2 end
2009-11-26 00:55:40.434 TV::~TV() -- begin
2009-11-26 00:55:40.439 NVP(4): Exited decoder loop.
2009-11-26 00:55:40.456 VidOutVDPAU: DiscardFrames(1)
2009-11-26 00:55:40.456 VideoBuffers::DiscardFrames(1): AULDDAUUDUUUUUUuu
2009-11-26 00:55:40.456 VideoBuffers::DiscardFrames(): AAADDAAADAAAAAAAA -- 
done()
2009-11-26 00:55:40.457 VideoBuffers::DiscardFrames(1): AAADDAAADAAAAAAAA -- 
done
2009-11-26 00:55:40.457 VidOutVDPAU: DiscardFrames() 3: AAADDAAADAAAAAAAA -- 
done()
2009-11-26 00:55:40.489 TV::~TV() -- lock
2009-11-26 00:55:40.517 TV::~TV() -- end
2009-11-26 00:55:40.517 TV: StartTV -- end

Hopefully someone will see an error that I am missing.

Chuck Filson