[mythtv-users] Live TV playback frustration

Wed Aug 8 13:56:46 UTC 2012

I sent a longer mail a week or so ago, but have had only one response, 
so here is a more concise one.

Frequently I have issues where playback of live TV or playback of in 
progress recordings errors out frequently (Unrecoverable Error 
message).  Commonly in the logs I have a timeout with GetFramesWritten() 
from the backend (see logs below). Looking at the code the 
GetFramesWritten() call seems fairly simple, working out to be just 
returning a number value with no obvious locking or other reason why it 
would take more than 7 seconds to return.  Trying to watch the Olympics 
is getting really frustrating, because this happens more commonly with 
larger recordings.  I have noticed it tends to be under the following 
circumstances:

1. The other non-backend client starts (and sometimes stops) playback of 
any other recording
2. Another unrelated recording is started or finished by the backend
3. Sometimes when a flagging job or something else dies or exits

I am using Mythbuntu 11.04 and the 0.25.1+fixes.20120714.5a51df7 mythtv 
stream, however this problem has been ongoing for some time since 0.24 
or earlier and through all the 0.25 updates I have done. The only unique 
thing about my setup is I have a Solaris machine for storage and the 
database, with the combined backend/frontend and another other client 
frontend being diskless NFS machines off that solaris server.  None of 
the servers show any performance issues and the storage and network 
performance is fine and has no errors.  As best as I can tell I suspect 
this is some sort of locking or contention in the backend which is 
delaying the response to the frontend which then errors out.  As above, 
completed recordings are fine and show no issues, but I have disabled 
streaming from the backend and make the frontends use NFS mounts to 
access the recording files.

Can anyone suggest a course of action or some debugging that may help?

Regards,
   Adrian

Aug  8 22:47:50 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:378 
(StartTV) TV: Entering main playback loop.
Aug  8 22:47:50 pvr mythfrontend[4967]: I CoreContext 
mythrender_vdpau.cpp:587 (CheckOutputSurfaces) VDPAU: Added 2 output 
surfaces (total 4, max 4)
Aug  8 22:56:44 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 11 15 0 0 hasrec: 0 haslater: 0
Aug  8 22:56:44 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 11 15 0 0 hasrec: 0 haslater: 0
Aug  8 22:56:44 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 20 15 0 0 hasrec: 0 haslater: 0
Aug  8 22:56:44 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 20 15 0 0 hasrec: 0 haslater: 0
Aug  8 22:56:44 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 19 15 0 0 hasrec: 0 haslater: 0
Aug  8 22:56:44 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 19 15 0 0 hasrec: 0 haslater: 0
Aug  8 22:56:44 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 12 15 0 0 hasrec: 0 haslater: 0
Aug  8 22:56:44 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 12 15 0 0 hasrec: 0 haslater: 0
Aug  8 22:58:31 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 17 27 0 0 hasrec: 0 haslater: 0
Aug  8 22:58:31 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 17 27 0 0 hasrec: 0 haslater: 0
Aug  8 22:58:31 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 18 27 0 0 hasrec: 0 haslater: 0
Aug  8 22:58:31 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:8793 
(customEvent) TV: ASK_RECORDING 18 27 0 0 hasrec: 0 haslater: 0
Aug  8 23:02:01 pvr mythfrontend[4967]: E CoreContext mythsocket.cpp:534 
(readStringList) MythSocket(7f1bd4613ef0:103): readStringList: Error, 
timed out after 7000 ms.
Aug  8 23:02:01 pvr mythfrontend[4967]: E CoreContext 
remoteencoder.cpp:99 (SendReceiveStringList) 
RemoteEncoder::SendReceiveStringList(): No response.
Aug  8 23:02:01 pvr mythfrontend[4967]: E CoreContext 
remoteencoder.cpp:205 (GetFramesWritten) RemoteEncoder(14): 
GetFramesWritten() -- network error
Aug  8 23:02:01 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:2121 
(HandleStateChange) TV: Attempting to change from WatchingRecording to None
Aug  8 23:02:01 pvr mythfrontend[4967]: I CoreContext 
mythpainter_vdpau.cpp:111 (ClearCache) VDPAU Painter: Clearing VDPAU 
painter cache.
Aug  8 23:02:01 pvr mythfrontend[4967]: W CoreContext mythpainter.cpp:32 
(~MythPainter) MythPainter: 25 images not yet de-allocated.
Aug  8 23:02:01 pvr mythfrontend[4967]: I CoreContext 
audio/audiopulsehandler.cpp:320 (SuspendInternal) Pulse: PulseAudio 
resume OK
Aug  8 23:02:01 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:2360 
(HandleStateChange) TV: Changing from WatchingRecording to None
Aug  8 23:02:01 pvr mythfrontend[4967]: I CoreContext 
mythcorecontext.cpp:371 (ConnectCommandSocket) MythCoreContext: 
Connecting to backend server: 10.31.8.2:6543 (try 1 of 1)
Aug  8 23:02:01 pvr mythfrontend[4967]: I CoreContext 
mythcorecontext.cpp:1178 (CheckProtoVersion) Using protocol version 72
Aug  8 23:02:08 pvr mythfrontend[4967]: E CoreContext mythsocket.cpp:534 
(readStringList) MythSocket(2ed35a0:72): readStringList: Error, timed 
out after 7000 ms.
Aug  8 23:02:08 pvr mythfrontend[4967]: E CoreContext 
remoteencoder.cpp:99 (SendReceiveStringList) 
RemoteEncoder::SendReceiveStringList(): No response.
Aug  8 23:02:08 pvr mythfrontend[4967]: I CoreContext tv_play.cpp:380 
(StartTV) TV: Exiting main playback loop.

On the backend:

Aug  8 22:59:03 pvr mythbackend[12372]: I TVRecEvent tv_rec.cpp:3989 
(TuningNewRecorder) TVRec(17): rec->GetPathname(): 
'/myth/tv/1070_20120808225900.mpg'
Aug  8 22:59:06 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
Aug  8 22:59:06 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 0)
Aug  8 22:59:06 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
Aug  8 22:59:06 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 1)
Aug  8 23:00:06 pvr mythbackend[12372]: I ProcessRequest 
recorderbase.cpp:386 (GetKeyframePositions) 
RecBase(14:/dev/dvb/adapter1/frontend0): 
GetKeyframePositions(363261,9223372036854775807,#1263) out of 32168
Aug  8 23:01:53 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
Aug  8 23:01:53 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 0)
Aug  8 23:01:53 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
Aug  8 23:01:53 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 1)
Aug  8 23:02:01 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
Aug  8 23:02:01 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 0)
Aug  8 23:02:22 pvr mythbackend[12372]: I SystemManager 
system-unix.cpp:618 (Signal) Child PID 5200 killed with Terminated
Aug  8 23:02:22 pvr mythbackend[12372]: E PreviewGenerator 
previewgenerator.cpp:254 (Run) Preview: Encountered problems running 
'/usr/bin/mythpreviewgen --size 0x0 --chanid 1508 --starttime 
20120808184800 --verbose general --loglevel info --syslog local7 
--quiet' (141)
Aug  8 23:02:24 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
Aug  8 23:02:24 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 0)
Aug  8 23:02:24 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
Aug  8 23:02:24 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 1)
Aug  8 23:02:38 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
Aug  8 23:02:38 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 0)
Aug  8 23:02:38 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
Aug  8 23:02:38 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 1)
Aug  8 23:02:54 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Monitor
Aug  8 23:02:54 pvr mythbackend[12372]: I ProcessRequest 
mainserver.cpp:1362 (HandleAnnounce) adding: pvr as a client (events: 0)
Aug  8 23:03:11 pvr mythbackend[12372]: N Expire autoexpire.cpp:263 
(CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB 
w/freq: 4 min
Aug  8 23:03:11 pvr mythbackend[12372]: W ProcessRequest 
mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket 
closing MythSocket(0x7fccb8b83130)
Aug  8 23:03:11 pvr mythbackend[12372]: W ProcessRequest 
mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket 
closing MythSocket(0x7fccb976ab10)
Aug  8 23:03:11 pvr mythbackend[12372]: W ProcessRequest 
mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket 
closing MythSocket(0x7fccacb07790)
Aug  8 23:03:11 pvr mythbackend[12372]: W ProcessRequest 
mainserver.cpp:5801 (connectionClosed) MainServer: Unknown socket 
closing MythSocket(0x7fccad849160)
Aug  8 23:03:11 pvr mythbackend[12372]: E ProcessRequest 
mythsocket.cpp:358 (writeStringList) MythSocket(7fccb8b83130:-1): 
writeStringList: Error, socket went unconnected.#012#011#011#011We wrote 
0 of 14 bytes with 1 errors#012#011#011#011starts with: 6       382750
Aug  8 23:03:11 pvr mythbackend[12372]: E ProcessRequest 
mythsocket.cpp:358 (writeStringList) MythSocket(7fccb976ab10:-1): 
writeStringList: Error, socket went unconnected.#012#011#011#011We wrote 
0 of 994 bytes with 1 errors#012#011#011#011starts with: 986     
Olympics: London 2012[]:[]Day 12 - Session 2[]:[]Day...
Aug  8 23:03:11 pvr mythbackend[12372]: E ProcessRequest 
mythsocket.cpp:358 (writeStringList) MythSocket(7fccacb07790:-1): 
writeStringList: Error, socket went unconnected.#012#011#011#011We wrote 
0 of 10 bytes with 1 errors#012#011#011#011starts with: 2       ok
Aug  8 23:03:11 pvr mythbackend[12372]: E ProcessRequest 
mythsocket.cpp:358 (writeStringList) MythSocket(7fccad849160:-1): 
writeStringList: Error, socket went unconnected.#012#011#011#011We wrote 
0 of 994 bytes with 1 errors#012#011#011#011starts with: 986     
Olympics: London 2012[]:[]Day 12 - Session 2[]:[]Day...