[mythtv-users] long time to live TV

Marco Nelissen marcone at xs4all.nl
Sun Apr 16 07:04:57 UTC 2006


After all the recent discussions, I've been trying to figure out where the *@$#$
myth spends all its time when it takes forever to go to live TV. Here's what the
log shows from the time I select "Watch TV" to when I actually get a picture:

2006-04-15 19:19:17.222 Connecting to backend server: 127.0.0.1:6543 (try 1 of 5)
2006-04-15 19:19:17.228 Using protocol version 26
2006-04-15 19:19:17.256 TV: Attempting to change from None to WatchingLiveTV
2006-04-15 19:19:17.266 Using protocol version 26
2006-04-15 19:19:20.728 RingBuf(/mnt/store//1021_20060415191917.mpg): Waited 2 seconds for data to become available...
2006-04-15 19:19:20.729 Checking to see if there's a new livetv program to switch to..
0: start_time: 5859.060 duration: -9223372036854.775
stream: start_time: 65100.668 duration: -9223372036854.775 bitrate=0 kb/s
2006-04-15 19:19:20.900 AFD: Opened codec 0x8fb070, id(MPEG2VIDEO) type(Video)
2006-04-15 19:19:20.900 NVP: Disabling Audio, params(-1,-1,-1)
2006-04-15 19:19:20.900 NVP: Disabling Audio, params(0,-1,-1)
2006-04-15 19:19:27.259 TV: Changing from None to WatchingLiveTV
2006-04-15 19:19:27.840 Realtime priority would require SUID as root.
2006-04-15 19:19:28.105 Video timing method: USleep with busy wait
2006-04-15 19:19:29.475 NVP: Prebuffer wait timed out 10 times.
0: start_time: 6890.452 duration: 1.248
1: start_time: 6890.414 duration: 1.247
stream: start_time: 76560.157 duration: 14.282 bitrate=11977 kb/s
2006-04-15 19:19:33.058 NVP: prebuffering pause
2006-04-15 19:19:33.884 NVP: Prebuffer wait timed out 10 times.
2006-04-15 19:19:34.041 AFD: Opened codec 0x8fb070, id(MPEG2VIDEO) type(Video)
2006-04-15 19:19:34.056 AFD: Opened codec 0xcb5b40, id(AC3) type(Audio)
2006-04-15 19:19:34.100 Opening audio device 'default'.
2006-04-15 19:19:34.311 NVP: Enabling Audio                                                          

As you can see, that took a total of 17 seconds. This was right after launching
mythtv, and using the "standard" decoder. If I go back to the main menu and then
go back to live TV, it's a little faster:

2006-04-15 19:19:37.645 TV: Attempting to change from WatchingLiveTV to None
2006-04-15 19:19:38.392 TV: Changing from WatchingLiveTV to None
2006-04-15 19:19:45.204 TV: Attempting to change from None to WatchingLiveTV
2006-04-15 19:19:45.276 Using protocol version 26
2006-04-15 19:19:49.142 RingBuf(/mnt/store//1021_20060415191945.mpg): Waited 2 seconds for data to become available...
2006-04-15 19:19:49.142 Checking to see if there's a new livetv program to switch to..
0: start_time: 5859.060 duration: -9223372036854.775
stream: start_time: 65100.668 duration: -9223372036854.775 bitrate=0 kb/s
2006-04-15 19:19:49.312 AFD: Opened codec 0x8fb070, id(MPEG2VIDEO) type(Video)
2006-04-15 19:19:49.312 NVP: Disabling Audio, params(-1,-1,-1)
2006-04-15 19:19:49.312 NVP: Disabling Audio, params(0,-1,-1)
2006-04-15 19:19:49.563 TV: Changing from None to WatchingLiveTV
2006-04-15 19:19:49.573 Realtime priority would require SUID as root.
2006-04-15 19:19:49.885 Video timing method: USleep with busy wait
0: start_time: 6893.019 duration: 0.420
1: start_time: 6892.983 duration: 0.423
stream: start_time: 76588.701 duration: 5.074 bitrate=14250 kb/s
2006-04-15 19:19:52.555 NVP: prebuffering pause
2006-04-15 19:19:52.745 AFD: Opened codec 0x8fb070, id(MPEG2VIDEO) type(Video)
2006-04-15 19:19:52.746 AFD: Opened codec 0xabdcf0, id(AC3) type(Audio)
2006-04-15 19:19:52.746 Opening audio device 'default'.
2006-04-15 19:19:52.816 NVP: Enabling Audio  

"only" 15 seconds that time...
Again, the above was with the "standard" decoder. With XvMC enabled, it's noticably faster:

2006-04-15 19:24:31.926 Connecting to backend server: 127.0.0.1:6543 (try 1 of 5)
2006-04-15 19:24:31.932 Using protocol version 26
2006-04-15 19:24:31.966 TV: Attempting to change from None to WatchingLiveTV
2006-04-15 19:24:31.973 Using protocol version 26
2006-04-15 19:24:35.302 RingBuf(/mnt/store//1021_20060415192432.mpg): Waited 2 seconds for data to become available...
2006-04-15 19:24:35.302 Checking to see if there's a new livetv program to switch to..
0: start_time: 5859.060 duration: -9223372036854.775
stream: start_time: 65100.668 duration: -9223372036854.775 bitrate=0 kb/s
2006-04-15 19:24:35.608 AFD: Opened codec 0x8681f0, id(MPEG2VIDEO_XVMC) type(Video)
2006-04-15 19:24:35.608 NVP: Disabling Audio, params(-1,-1,-1)
2006-04-15 19:24:35.608 NVP: Disabling Audio, params(0,-1,-1)
2006-04-15 19:24:35.915 TV: Changing from None to WatchingLiveTV
2006-04-15 19:24:35.921 Realtime priority would require SUID as root.
2006-04-15 19:24:36.055 Video timing method: USleep with busy wait
2006-04-15 19:24:36.171 VideoOutputXv Error: ProcessFrameXvMC: Failed to get OSD lock
2006-04-15 19:24:37.749 NVP: prebuffering pause
2006-04-15 19:24:39.417 NVP: prebuffering pause
0: start_time: 6918.785 duration: 0.506
1: start_time: 6918.748 duration: 0.510
stream: start_time: 76874.974 duration: 6.039 bitrate=14408 kb/s
2006-04-15 19:24:40.308 AFD: Opened codec 0x8681f0, id(MPEG2VIDEO_XVMC) type(Video)
2006-04-15 19:24:40.335 AFD: Opened codec 0xcbad10, id(AC3) type(Audio)
2006-04-15 19:24:40.358 Opening audio device 'default'.
2006-04-15 19:24:40.409 NVP: Prebuffer wait timed out 10 times.
2006-04-15 19:24:40.544 NVP: Enabling Audio                                                          

and the second time around it's even faster:

2006-04-15 19:24:49.652 TV: Attempting to change from None to WatchingLiveTV
2006-04-15 19:24:49.657 Using protocol version 26
2006-04-15 19:24:52.847 RingBuf(/mnt/store//1021_20060415192449.mpg): Waited 2 seconds for data to become available...
2006-04-15 19:24:52.847 Checking to see if there's a new livetv program to switch to..
0: start_time: 5859.060 duration: -9223372036854.775
stream: start_time: 65100.668 duration: -9223372036854.775 bitrate=0 kb/s
2006-04-15 19:24:53.024 AFD: Opened codec 0x8681f0, id(MPEG2VIDEO_XVMC) type(Video)
2006-04-15 19:24:53.024 NVP: Disabling Audio, params(-1,-1,-1)
2006-04-15 19:24:53.024 NVP: Disabling Audio, params(0,-1,-1)
2006-04-15 19:24:53.333 TV: Changing from None to WatchingLiveTV
2006-04-15 19:24:53.334 Realtime priority would require SUID as root.
2006-04-15 19:24:53.466 Video timing method: USleep with busy wait
2006-04-15 19:24:53.521 VideoOutputXv Error: ProcessFrameXvMC: Failed to get OSD lock
2006-04-15 19:24:53.744 VideoOutputXv Error: ProcessFrameXvMC: Failed to get OSD lock
2006-04-15 19:24:55.132 NVP: prebuffering pause
0: start_time: 6920.362 duration: 0.386
1: start_time: 6920.323 duration: 0.392
stream: start_time: 76892.478 duration: 4.717 bitrate=14353 kb/s
2006-04-15 19:24:55.701 VideoOutputXv Error: Child     A        was already marked as available.
2006-04-15 19:24:55.701 VideoOutputXv Error: Child     A        was already marked as available.
2006-04-15 19:24:55.871 VideoOutputXv Error: Child     A        was already marked as available.
2006-04-15 19:24:55.872 NVP: prebuffering pause
2006-04-15 19:24:56.088 VideoOutputXv Error: Child     A        was already marked as available.
2006-04-15 19:24:56.088 VideoOutputXv Error: Child     A        was already marked as available.
2006-04-15 19:24:56.088 AFD: Opened codec 0x8681f0, id(MPEG2VIDEO_XVMC) type(Video)
2006-04-15 19:24:56.088 AFD: Opened codec 0xef5cf0, id(AC3) type(Audio)
2006-04-15 19:24:56.088 Opening audio device 'default'.
2006-04-15 19:24:56.117 NVP: Enabling Audio                                                           

So, 6.5 seconds is about the best it can do, apparently. That still seems
quite long considering that "mplayer dvb://" pops up a window with video in
under a second.







More information about the mythtv-users mailing list