[mythtv] [mythtv-commits] mythtv commit: r22955 - in trunk by danielk

[Jerry Rubinow]

On Tue, Jan 19, 2010 at 2:43 PM, Jerry Rubinow <jerrymr at gmail.com> wrote:

> On Tue, Jan 19, 2010 at 2:33 PM, Jim Stichnoth <stichnot at gmail.com> wrote:
>
>> On Tue, Jan 19, 2010 at 11:08 AM, Jerry Rubinow <jerrymr at gmail.com>
>> wrote:
>> > On Thu, Dec 10, 2009 at 5:06 PM, Jim Stichnoth <stichnot at gmail.com>
>> wrote:
>> >>
>> >> On Mon, Dec 7, 2009 at 11:00 AM, Jim Stichnoth <stichnot at gmail.com>
>> wrote:
>> >> > On Mon, Dec 7, 2009 at 4:50 AM, Daniel Kristjansson
>> >> > <danielk at cuymedia.net> wrote:
>> >> >> This problem has been reported to me, but I was unable to reproduce
>> >> >> with my current setup and current trunk. The initial commit had a
>> >> >> loop, but I thought had already fixed it. If this still occurs with
>> >> >> trunk can you try something for me?
>> >> >>
>> >> >> In RemoteSendEvent() replace gContext->IsMasterBackend()
>> >> >> with gContext->IsBackend(), that shouldn't cause any problems
>> >> >> and might fix the problem.
>> >> >
>> >> > This appears to fix the problem on my system.  Filesize updates are
>> >> > now being made once every 2-10 seconds, rather than every 20-30ms.  I
>> >> > tested r22962 with and without this one-line change.
>> >> >
>> >> > I'll report back if I see any more related problems, for example when
>> >> > I get a chance to test Live TV, and also the problem I noted with
>> >> > zero-length recordings.
>> >>
>> >> This problem popped up again for me yesterday, running r22969.  At
>> >> 3:34pm, an HD-PVR recording started on the slave backend and completed
>> >> at 5:01pm.  The logs on the slave backend (-v important,general) show
>> >> nothing remarkable during the recording or at any later time.  On the
>> >> master backend (-v important,general), problems started showing up at
>> >> 4:46pm, beginning with messages like this repeated every 10 seconds:
>> >>
>> >> 2009-12-09 16:46:17.111 MythSocket(a00ce60:60): writeStringList:
>> >> Error, No data  written on writeBlock (937 errors)
>> >> 2009-12-09 16:46:27.120 MythSocket(a00ce60:60): writeStringList:
>> >> Error, No data  written on writeBlock (937 errors)
>> >> 2009-12-09 16:46:37.130 MythSocket(a00ce60:60): writeStringList:
>> >> Error, No data  written on writeBlock (937 errors)
>> >>
>> >> These messages stopped around 5:01pm when the slave backend recording
>> >> completed, but started up again at 6:45pm when a frontend started
>> >> watching a recording.  At 8:00pm when more recordings and commflagging
>> >> started, additional kinds of errors appeared, for example:
>> >>
>> >> 2009-12-09 20:00:49.212 MainServer, Warning: Unknown socket closing
>> >> MythSocket(0xffffffffa9c1c880)
>> >> 2009-12-09 20:00:49.220 MythSocket(ffffffffa9c1c298:-1):
>> >> writeStringList: Error, socket went unconnected.
>> >>                        We wrote 0 of 21 bytes with 1 errors
>> >>
>> >> All these errors continued until all recording and playback finished
>> >> around 11:40pm, briefly popped up at 4am when I restarted the slave
>> >> backend, and disappeared altogether right after that when I restarted
>> >> the master backend.  Usually the messages were 1 or 2 seconds apart in
>> >> the log instead of 10 seconds.
>> >>
>> >> The frontends were affected during this storm.  Symptoms included not
>> >> being able to bring up the Watch Recordings screen, failure to start
>> >> playing a program when Watch Recordings finally came up, and one
>> >> instance of playback suddenly stopping mid-program.
>> >>
>> >> One other thing might be worth mentioning.  In looking through the
>> >> logs, I realized that I also ran a couple of lossless transcode jobs
>> >> on the master backend, one from 3:37pm to 3:42pm and another from to
>> >> 8:16pm to 8:18pm.  It seems unlikely to be related, but just in
>> >> case...
>> >>
>> >> I'd like to help get to the bottom of this.  Are there extra -v
>> >> arguments I should add to the backends or frontends that would shed
>> >> more light?  Any code modifications to try out?
>> >>
>> >
>> >
>> >
>> > On Thu, Dec 10, 2009 at 5:06 PM, Jim Stichnoth <stichnot at gmail.com
>> > wrote:
>> >>
>> >> On Mon, Dec 7, 2009 at 11:00 AM, Jim Stichnoth <stichnot at gmail.com>
>> wrote:
>> >> > On Mon, Dec 7, 2009 at 4:50 AM, Daniel Kristjansson
>> >> > <danielk at cuymedia.net> wrote:
>> >> >> This problem has been reported to me, but I was unable to reproduce
>> >> >> with my current setup and current trunk. The initial commit had a
>> >> >> loop, but I thought had already fixed it. If this still occurs with
>> >> >> trunk can you try something for me?
>> >> >>
>> >> >> In RemoteSendEvent() replace gContext->IsMasterBackend()
>> >> >> with gContext->IsBackend(), that shouldn't cause any problems
>> >> >> and might fix the problem.
>> >> >
>> >> > This appears to fix the problem on my system.  Filesize updates are
>> >> > now being made once every 2-10 seconds, rather than every 20-30ms.  I
>> >> > tested r22962 with and without this one-line change.
>> >> >
>> >> > I'll report back if I see any more related problems, for example when
>> >> > I get a chance to test Live TV, and also the problem I noted with
>> >> > zero-length recordings.
>> >>
>> >> This problem popped up again for me yesterday, running r22969.  At
>> >> 3:34pm, an HD-PVR recording started on the slave backend and completed
>> >> at 5:01pm.  The logs on the slave backend (-v important,general) show
>> >> nothing remarkable during the recording or at any later time.  On the
>> >> master backend (-v important,general), problems started showing up at
>> >> 4:46pm, beginning with messages like this repeated every 10 seconds:
>> >>
>> >> 2009-12-09 16:46:17.111 MythSocket(a00ce60:60): writeStringList:
>> >> Error, No data  written on writeBlock (937 errors)
>> >> 2009-12-09 16:46:27.120 MythSocket(a00ce60:60): writeStringList:
>> >> Error, No data  written on writeBlock (937 errors)
>> >> 2009-12-09 16:46:37.130 MythSocket(a00ce60:60): writeStringList:
>> >> Error, No data  written on writeBlock (937 errors)
>> >>
>> >> These messages stopped around 5:01pm when the slave backend recording
>> >> completed, but started up again at 6:45pm when a frontend started
>> >> watching a recording.  At 8:00pm when more recordings and commflagging
>> >> started, additional kinds of errors appeared, for example:
>> >>
>> >> 2009-12-09 20:00:49.212 MainServer, Warning: Unknown socket closing
>> >> MythSocket(0xffffffffa9c1c880)
>> >> 2009-12-09 20:00:49.220 MythSocket(ffffffffa9c1c298:-1):
>> >> writeStringList: Error, socket went unconnected.
>> >>                        We wrote 0 of 21 bytes with 1 errors
>> >>
>> >> All these errors continued until all recording and playback finished
>> >> around 11:40pm, briefly popped up at 4am when I restarted the slave
>> >> backend, and disappeared altogether right after that when I restarted
>> >> the master backend.  Usually the messages were 1 or 2 seconds apart in
>> >> the log instead of 10 seconds.
>> >>
>> >> The frontends were affected during this storm.  Symptoms included not
>> >> being able to bring up the Watch Recordings screen, failure to start
>> >> playing a program when Watch Recordings finally came up, and one
>> >> instance of playback suddenly stopping mid-program.
>> >>
>> >> One other thing might be worth mentioning.  In looking through the
>> >> logs, I realized that I also ran a couple of lossless transcode jobs
>> >> on the master backend, one from 3:37pm to 3:42pm and another from to
>> >> 8:16pm to 8:18pm.  It seems unlikely to be related, but just in
>> >> case...
>> >>
>> >> I'd like to help get to the bottom of this.  Are there extra -v
>> >> arguments I should add to the backends or frontends that would shed
>> >> more light?  Any code modifications to try out?
>> >>
>> >> Jim
>> >
>> > Jim,
>> > Did this issue ever get resolved for you?  I think I'm experiencing the
>> same
>> > thing.  I have an HD-PVR and an HDHomeRun and see everything you
>> describe in
>> > your message as far as Myth behavior at the user level and what is
>> reported
>> > in the logs.  I'm running the current .22-fixes and my WAF is in the
>> toilet
>> > because of corrupted recordings, which seem to occur at the same times
>> the
>> > log is reporting the errors you list.
>> > -Jerry
>>
>> The issue seems to be resolved, but I can't say exactly which of
>> Daniel's checkins fixed it.  To complicate matters, I'm running trunk
>> and I don't have a good sense for which changes got backported to
>> 0.22-fixes -- perhaps none since there were protocol changes.
>>
>> Jim
>>
>
> Daniel, can you or one of the other devs say whether the relevant change
> got backported to fixes?  I'm guessing not, since I'm seeing the problem,
> but it would be good to know for sure before committing myself to switching
> from fixes to trunk.  If not, is there any chance it could be backported?
>

I ended up updating to the mythbuntu trunk build tonight: Myth version
23211, Network protocol 56, library api 0.23.20100119-1.  Unfortunately the
problems were still there.  After tweaking a bunch of things, I think I
figured out what the problem was and made it go away.

Here's what I observed.

- recording on both HDHR tuners (but not the HD-PVR, taking it out of
equation), the FE suffers from delays, refusal to play in-progress
recordings, and the backend recording has missing frames.  Occasionally
mythfrontend would crash on exiting from playback.
- reading about the sql and socket problems in the quoted messages, I
switched the logging from "important, general, record, channel" (mythbuntu
default) to "important, database, socket, network".  With nothing recording,
playback progressed at a crawl.  Perhaps five second delays between each
frame advance/jump.
- I eliminated logging options until I found that it was "socket" which was
causing the delays.  There were many many socket messages in the log.
- thinking maybe the logging was overwhelming things, I removed all logging
except "important".  This seems to improve things considerably.  Immensely,
even.  I'm now able to record on all three inputs at once, I can playback
shows while they're recording.  No glitches in the recorded files.

Is it to be expected for logging to cause so many problems?  Is this a
regression or a sign something non-myth-related is wrong on my system?  The
recordings are on a different drive than the system/database.  System drive
is ext4.  Recordings drive is jfs.  Both drives using dma (udma6 and udma5,
respectively).

Occasionally mythfrontend will still unexpectedly exit, sometimes just from
switching menus.  But this is likely unrelated to the other issue.

-Jerry
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mythtv.org/pipermail/mythtv-dev/attachments/20100119/dbb55878/attachment-0001.htm>