[mythtv-users] one frontend that hangs frequently
Brian J. Murrell
brian at interlinx.bc.ca
Wed Jan 12 12:30:07 UTC 2011
Hi,
I have two frontends that we use with any consistency in my Myth
network. One works flawlessly the other (named "jenny" in backend log
below) frequently (75% of the time at least) hangs during playback.
When it hangs the following is in the log (from the time playback is
initiated):
2011-01-11 21:49:17.700 TV: Attempting to change from None to WatchingPreRecorded
2011-01-11 21:49:18.181 AFD: Opened codec 0xad42c60, id(MPEG2VIDEO) type(Video)
2011-01-11 21:49:18.181 AFD: codec AC3 has 2 channels
2011-01-11 21:49:18.181 AFD: Opened codec 0xb4bffb0, id(AC3) type(Audio)
2011-01-11 21:49:18.220 AO: Opening audio device 'pulse' ch 2(2) sr 48000 sf signed 16 bit reenc 0
2011-01-11 21:49:18.224 AudioOutput Warning: mmap not available, attempting to fall back to slow writes
2011-01-11 21:49:18.311 AudioPlayer: Enabling Audio
2011-01-11 21:49:19.253 Clearing OpenGL painter cache.
2011-01-11 21:49:19.348 VDPAU: Created 2 output surfaces.
2011-01-11 21:49:19.348 VDPAU: Created VDPAU render device 1280x720
2011-01-11 21:49:19.398 Player(2): Forcing decode extra audio option on (Video method requires it).
2011-01-11 21:49:19.476 Player(2): Video timing method: USleep with busy wait
2011-01-11 21:49:19.478 TV: Changing from None to WatchingPreRecorded
2011-01-11 21:49:19.506 VDPAU: Added 2 output surfaces (total 4, max 4)
2011-01-11 22:00:38.422 TV: ASK_RECORDING 2 0 0 0 hasrec: 0 haslater: 0
2011-01-11 22:01:00.177 TV: ASK_RECORDING 3 0 0 0 hasrec: 0 haslater: 0
2011-01-11 22:01:00.177 TV: ASK_RECORDING 1 0 0 0 hasrec: 0 haslater: 0
2011-01-11 22:01:00.178 TV: ASK_RECORDING 1 0 0 0 hasrec: 0 haslater: 0
2011-01-11 22:01:00.178 TV: ASK_RECORDING 2 0 0 0 hasrec: 0 haslater: 0
2011-01-11 22:01:00.210 TV: ASK_RECORDING 3 0 0 0 hasrec: 0 haslater: 0
2011-01-11 22:01:00.210 TV: ASK_RECORDING 5 0 0 0 hasrec: 0 haslater: 0
2011-01-11 22:01:00.941 TV: ASK_RECORDING 4 20 0 0 hasrec: 0 haslater: 0
2011-01-11 22:01:31.356 Preview: RemotePreviewRun() -- no reply..
2011-01-11 22:01:32.075 Preview: RemotePreviewRun() -- no reply..
2011-01-11 22:11:22.536 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:11:22.549 Player(2): Waited 100ms for video buffers ULUULAAAAAAAAAAAA
2011-01-11 22:11:23.527 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:11:23.536 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:11:23.549 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:11:24.510 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:11:24.515 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:11:24.524 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
[ many repeated occurances ]
2011-01-11 22:12:00.723 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:00.731 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:00.736 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:05.117 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:05.127 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:07.112 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Warning: Taking too long to be allowed to read..
2011-01-11 22:12:08.112 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Warning: Taking too long to be allowed to read..
2011-01-11 22:12:08.581 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:08.703 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:08.711 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:08.720 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:08.823 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:08.832 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:08.845 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:13.028 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:13.037 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:13.050 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:13.157 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:13.172 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:13.181 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:13.284 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:14.926 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Warning: Taking too long to be allowed to read..
2011-01-11 22:12:15.926 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Warning: Taking too long to be allowed to read..
2011-01-11 22:12:16.926 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Warning: Taking too long to be allowed to read..
2011-01-11 22:12:17.926 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Warning: Taking too long to be allowed to read..
2011-01-11 22:12:18.926 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Warning: Taking too long to be allowed to read..
2011-01-11 22:12:19.451 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:19.572 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:19.581 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:23.640 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Warning: Taking too long to be allowed to read..
2011-01-11 22:12:23.918 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:23.927 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:23.932 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:23.940 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:25.914 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Warning: Taking too long to be allowed to read..
2011-01-11 22:12:26.095 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:26.108 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:26.116 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:26.220 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
[ many repeated occurances ]
2011-01-11 22:12:27.772 Player(2): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA
2011-01-11 22:12:27.782 Player(2): Waited 100ms for video buffers ALAAAAAAAAAuLAAAA
2011-01-11 22:12:44.540 MythSocket(ae3e1e8:46): readStringList: Error, timed out after 30000 ms.
2011-01-11 22:12:44.540 Connection to backend server lost
2011-01-11 22:12:44.540 MythCoreContext: Connecting to backend server: 10.75.22.2:6543 (try 1 of 5)
2011-01-11 22:12:44.788 Using protocol version 63
2011-01-11 22:13:35.757 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg): Waited 0.5 seconds for data
to become available... 0 < 32768
2011-01-11 22:13:35.872 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:35.880 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
[ many repeated occurances ]
2011-01-11 22:13:36.137 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:36.147 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:36.257 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg): Waited 1.0 seconds for data
to become available... 0 < 32768
2011-01-11 22:13:36.258 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:36.267 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
[ many repeated occurances ]
2011-01-11 22:13:37.169 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:37.178 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:37.257 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg): Waited 2.0 seconds for data
to become available... 0 < 32768
2011-01-11 22:13:37.280 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:37.289 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
[ many repeated occurances ]
2011-01-11 22:13:37.675 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:37.683 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:37.740 MythSocket(9b1bcf0:63): readStringList: Error, timed out after 7000 ms.
2011-01-11 22:13:37.740 RemoteFile::Read(): No response from control socket.
2011-01-11 22:13:37.740 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Error: RingBuffer::safe_read(RemoteFile* ...): read failed
2011-01-11 22:13:37.800 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:37.809 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
[ many repeated occurances ]
2011-01-11 22:13:39.217 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:39.226 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:39.258 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg): Waited 4.0 seconds for data
to become available... 0 < 32768
2011-01-11 22:13:39.328 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:39.337 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
[ many repeated occurances ]
and it just continues in that pattern with the "Waited ... seconds for
data" increasing up to:
2011-01-11 22:13:51.258 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:51.269 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg): Waited 16.0 seconds for data
to become available... 0 < 32768
2011-01-11 22:13:51.269 RingBuf(myth://10.75.22.2:6543/2936_20101006203000.mpg) Error: Waited 16 seconds for data, aborting.
2011-01-11 22:13:51.360 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
and again, many repeated occurances of "Waited 100ms for video buffers
dAAAADAAAAAAADAAL" until:
2011-01-11 22:13:55.728 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:55.736 Player(2): Waited 100ms for video buffers dAAAADAAAAAAADAAL
2011-01-11 22:13:55.775 Player(2), Error: Waited too long for decoder to fill video buffers. Exiting..
2011-01-11 22:13:55.872 TV: Attempting to change from WatchingPreRecorded to None
2011-01-11 22:14:00.976 Player(2), Error: Failed to stop decoder loop.
2011-01-11 22:14:00.981 VDPAU Painter: Clearing VDPAU painter cache.
2011-01-11 22:14:00.990 MythPainter: 4 images not yet de-allocated.
2011-01-11 22:14:01.011 Trying 1280x720 0.000 Hz
2011-01-11 22:14:01.012 SwitchToGUI: Switched to 1280x720 0.000 Hz
2011-01-12 00:04:09.639 MythSocket(a159430:46): readStringList: Error, timed out after 30000 ms.
2011-01-12 00:04:09.639 Connection to backend server lost
2011-01-12 00:04:09.639 MythCoreContext: Connecting to backend server: 10.75.22.2:6543 (try 1 of 5)
2011-01-12 00:04:16.642 MythSocket(a14cbe0:46): readStringList: Error, timed out after 7000 ms.
2011-01-12 00:04:16.642 Protocol version check failure.
The response to MYTH_PROTO_VERSION was empty.
This happens when the backend is too busy to respond,
or has deadlocked in due to bugs or hardware failure.
2011-01-12 00:04:16.643 Reconnection to backend server failed
2011-01-12 00:04:31.653 MythCoreContext: Connecting to backend server: 10.75.22.2:6543 (try 1 of 5)
2011-01-12 00:04:38.655 MythSocket(ae14d98:46): readStringList: Error, timed out after 7000 ms.
2011-01-12 00:04:38.655 Protocol version check failure.
The response to MYTH_PROTO_VERSION was empty.
This happens when the backend is too busy to respond,
or has deadlocked in due to bugs or hardware failure.
which just continues to repeat.
At approximately the same time as the trouble on the frontend starts,
the backend's log has some interesting activity. I would have loved to
have included it here but it would exceed the list message size limit so
instead it can be read here: http://brian.interlinx.bc.ca/backend.log
Now, it's clear from the backend log that lots is going on. What's
unclear however, given the timing (i.e. the client starts reporting
problems first) is whether the problems on the backend are a result of
the problems on the frontend or a cause of them. If the latter, why are
they reported so much later than the frontend's reporting errors?
Any thoughts as to what is going on here? All machines should be
up-to-date (within a week at least) with 0.24-fixes
Cheers,
b.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part
URL: <http://mythtv.org/pipermail/mythtv-users/attachments/20110112/6604913e/attachment.pgp>
More information about the mythtv-users
mailing list