[mythtv-users] one frontend that hangs frequently
Dave Richardson
mythtv at derdev.com
Wed Jan 12 12:51:42 UTC 2011
On Wed, 12 Jan 2011 07:30:07 -0500, "Brian J. Murrell"
<brian at interlinx.bc.ca> wrote:
> 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.
IANAE, but here are some ideas:
1) Bad network between offending FE and BE (see network errors in BE
log)
- check cables, re-seat FE NIC, run any diagnostics you think of, check
for IP Address overlap/conflict with another box on the network
2) High/spiked BE load interferes with timely MySQL responses
- I have been in a situation with too much commflagging on the BE that
leaves the kit so busy that MySQL responses slow down.
3) High/spiked FE load interferes with timely MySQL handling
- IF you are running other activities or if you have selected too high
a level of VDPAU quality, you will significantly increase load on the FE
- if too high, load (in my experience) can manifest itself as choppy
playback, lurches in menu moves, or fatal timeouts in playback
4) Is your database healthy?
- Low probability that database is corrupt or non-optimized... I think
there's a screen in Mythweb or direct BE scripts you can run to make
sure the DBMS is optimized and error free.
My guess is that you've thought of all this... but sometimes ideas
spark other ideas, so, good luck!
More information about the mythtv-users
mailing list