Mailing List Archive: MythTV: Users

Slave backend disconnections after moving from r22901 to r22949

Index | Next | Previous | View Threaded

stichnot at gmail

Dec 3, 2009, 2:08 PM

Post #1 of 4 (563 views)
Permalink

Slave backend disconnections after moving from r22901 to r22949

I run trunk, and I recently moved from r22901 to r22949.
Subsequently, I couldn't get successful recordings from my slave
backend. After about 5 minutes (perhaps when commflagging reached a
key point), the master backend would think that the slave backend was
disconnected, with lots of messages like this in the log:

2009-12-03 06:04:52.370 MythSocket(ffffffffa99187c8:44):
writeStringList: Error, No data written on writeBlock (936 errors)
2009-12-03 06:04:52.371 MainServer, Warning: Unknown socket closing
MythSocket(0xffffffffa9799018)
2009-12-03 06:04:52.372 MainServer, Warning: Unknown socket closing
MythSocket(0xffffffffa9799018)
2009-12-03 06:04:52.374 MythSocket(ffffffffa9799018:-1):
writeStringList: Error, socket went unconnected.
We wrote 0 of 21 bytes with 1 errors
2009-12-03 06:04:53.372 MythSocket(ffffffffa99187c8:44):
writeStringList: Error, No data written on writeBlock (937 errors)

When this is going on, frontends have problems as well -- playback
stops responding to remote control commands, and the frontend appears
to hang while trying to load the list of recordings.

The slave backend has an HD-PVR which records onto NFS.

Today I reverted to r22901 and recordings are working again. (The DB
schemas are different by one version, 1246 & 1247, I can't wait to
deal with the fallout from that.)

I looked through the commits from r22901-r22949 but nothing jumps out
as obviously responsible for this problem.

I wonder if anyone else has seen this or has any ideas.

Jim
_______________________________________________
mythtv-users mailing list
mythtv-users [at] mythtv
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

gregorio.gervasio at gmail

Dec 3, 2009, 11:30 PM

Post #2 of 4 (521 views)
Permalink

Re: Slave backend disconnections after moving from r22901 to r22949 [In reply to]

>>>>> Jim Stichnoth writes:

j> I run trunk, and I recently moved from r22901 to r22949.
j> Subsequently, I couldn't get successful recordings from my slave
j> backend. After about 5 minutes (perhaps when commflagging reached a
j> key point), the master backend would think that the slave backend was
j> disconnected, with lots of messages like this in the log:

j> 2009-12-03 06:04:52.370 MythSocket(ffffffffa99187c8:44):
j> writeStringList: Error, No data written on writeBlock (936 errors)
j> 2009-12-03 06:04:52.371 MainServer, Warning: Unknown socket closing
j> MythSocket(0xffffffffa9799018)
j> 2009-12-03 06:04:52.372 MainServer, Warning: Unknown socket closing
j> MythSocket(0xffffffffa9799018)
j> 2009-12-03 06:04:52.374 MythSocket(ffffffffa9799018:-1):
j> writeStringList: Error, socket went unconnected.
j> We wrote 0 of 21 bytes with 1 errors
j> 2009-12-03 06:04:53.372 MythSocket(ffffffffa99187c8:44):
j> writeStringList: Error, No data written on writeBlock (937 errors)

j> When this is going on, frontends have problems as well -- playback
j> stops responding to remote control commands, and the frontend appears
j> to hang while trying to load the list of recordings.
[...]

I saw the same thing moving from r22910 to r22949. I also get a
bunch of these messages on frontends while a program is being recorded:

Got UPDATE_PROG_INFO, but the program is unknown to us.

It looks like r22932 is the relevant changeset. The backend seems to
be sending out a lot of UPDATE_PROG_INFO events during recording:

2009-12-03 00:08:02.924 MSqlQuery::exec() "UPDATE recorded SET filesize = '40824764' WHERE chanid = '2703' AND starttime = '2009-12-03T00:08:00' ;"
2009-12-03 00:08:02.924 MythEvent: UPDATE_PROG_INFO
2009-12-03 00:08:04.925 MSqlQuery::exec() "INSERT INTO recordedseek (chanid, starttime, mark, type, offset) VALUES ( '2703' , '2009-12-03T00:08:00' , '720' , '9' , '43398108' );"
2009-12-03 00:08:04.926 MSqlQuery::exec() "UPDATE recorded SET filesize = '44722944' WHERE chanid = '2703' AND starttime = '2009-12-03T00:08:00' ;"
2009-12-03 00:08:04.926 MythEvent: UPDATE_PROG_INFO
2009-12-03 00:08:06.927 MSqlQuery::exec() "INSERT INTO recordedseek (chanid, starttime, mark, type, offset) VALUES ( '2703' , '2009-12-03T00:08:00' , '786' , '9' , '47466616' );"
2009-12-03 00:08:06.927 MSqlQuery::exec() "UPDATE recorded SET filesize = '48264864' WHERE chanid = '2703' AND starttime = '2009-12-03T00:08:00' ;"
2009-12-03 00:08:06.928 MythEvent: UPDATE_PROG_INFO
2009-12-03 00:08:08.928 MSqlQuery::exec() "INSERT INTO recordedseek (chanid, starttime, mark, type, offset) VALUES ( '2703' , '2009-12-03T00:08:00' , '839' , '9' , '50493980' );"
2009-12-03 00:08:08.929 MSqlQuery::exec() "UPDATE recorded SET filesize = '51885744' WHERE chanid = '2703' AND starttime = '2009-12-03T00:08:00' ;"
2009-12-03 00:08:08.929 MythEvent: UPDATE_PROG_INFO

--
Gregorio Gervasio, Jr.
gregorio.gervasio [at] gmail
_______________________________________________
mythtv-users mailing list
mythtv-users [at] mythtv
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

stichnot at gmail

Dec 4, 2009, 4:57 PM

Post #3 of 4 (501 views)
Permalink

Re: Slave backend disconnections after moving from r22901 to r22949 [In reply to]

On Thu, Dec 3, 2009 at 11:30 PM, Gregorio Gervasio, Jr.
<gregorio.gervasio [at] gmail> wrote:
>>>>>> Jim Stichnoth writes:
>
> j> I run trunk, and I recently moved from r22901 to r22949.
> j> Subsequently, I couldn't get successful recordings from my slave
> j> backend. �After about 5 minutes (perhaps when commflagging reached a
> j> key point), the master backend would think that the slave backend was
> j> disconnected, with lots of messages like this in the log:
>
> j> 2009-12-03 06:04:52.370 MythSocket(ffffffffa99187c8:44):
> j> writeStringList: Error, No data written on writeBlock (936 errors)
> j> 2009-12-03 06:04:52.371 MainServer, Warning: Unknown socket closing
> j> MythSocket(0xffffffffa9799018)
> j> 2009-12-03 06:04:52.372 MainServer, Warning: Unknown socket closing
> j> MythSocket(0xffffffffa9799018)
> j> 2009-12-03 06:04:52.374 MythSocket(ffffffffa9799018:-1):
> j> writeStringList: Error, socket went unconnected.
> j> � � � � � � � � � � � � We wrote 0 of 21 bytes with 1 errors
> j> 2009-12-03 06:04:53.372 MythSocket(ffffffffa99187c8:44):
> j> writeStringList: Error, No data written on writeBlock (937 errors)
>
> j> When this is going on, frontends have problems as well -- playback
> j> stops responding to remote control commands, and the frontend appears
> j> to hang while trying to load the list of recordings.
> [...]
>
>
> � � � �I saw the same thing moving from r22910 to r22949. �I also get a
> bunch of these messages on frontends while a program is being recorded:
>
> Got UPDATE_PROG_INFO, but the program is unknown to us.
>
> It looks like r22932 is the relevant changeset. �The backend seems to
> be sending out a lot of UPDATE_PROG_INFO events during recording:
>
> 2009-12-03 00:08:02.924 MSqlQuery::exec() "UPDATE recorded SET filesize = '40824764' WHERE chanid = '2703' AND starttime = '2009-12-03T00:08:00' ;"
> 2009-12-03 00:08:02.924 MythEvent: UPDATE_PROG_INFO
> 2009-12-03 00:08:04.925 MSqlQuery::exec() "INSERT INTO recordedseek (chanid, starttime, mark, type, offset) VALUES ( '2703' , '2009-12-03T00:08:00' , '720' , '9' , '43398108' );"
> 2009-12-03 00:08:04.926 MSqlQuery::exec() "UPDATE recorded SET filesize = '44722944' WHERE chanid = '2703' AND starttime = '2009-12-03T00:08:00' ;"
> 2009-12-03 00:08:04.926 MythEvent: UPDATE_PROG_INFO
> 2009-12-03 00:08:06.927 MSqlQuery::exec() "INSERT INTO recordedseek (chanid, starttime, mark, type, offset) VALUES ( '2703' , '2009-12-03T00:08:00' , '786' , '9' , '47466616' );"
> 2009-12-03 00:08:06.927 MSqlQuery::exec() "UPDATE recorded SET filesize = '48264864' WHERE chanid = '2703' AND starttime = '2009-12-03T00:08:00' ;"
> 2009-12-03 00:08:06.928 MythEvent: UPDATE_PROG_INFO
> 2009-12-03 00:08:08.928 MSqlQuery::exec() "INSERT INTO recordedseek (chanid, starttime, mark, type, offset) VALUES ( '2703' , '2009-12-03T00:08:00' , '839' , '9' , '50493980' );"
> 2009-12-03 00:08:08.929 MSqlQuery::exec() "UPDATE recorded SET filesize = '51885744' WHERE chanid = '2703' AND starttime = '2009-12-03T00:08:00' ;"
> 2009-12-03 00:08:08.929 MythEvent: UPDATE_PROG_INFO
>

I looked at the r22932 changeset. Your logs show an UPDATE_PROG_INFO
once every 2 seconds, which seems basically OK. The code indicates
that once the recording is in progress (after the first 1.5 seconds),
filesize updates are sent out every 30 frames.

On the other hand, my frontend logs have sections like this:

2009-12-02 20:24:55.621 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.625 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.630 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.635 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.636 Set video sync frame interval to 16666
2009-12-02 20:24:55.636 Disabled deinterlacing
2009-12-02 20:24:55.640 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.645 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.650 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.652 Set video sync frame interval to 16666
2009-12-02 20:24:55.652 Disabled deinterlacing
2009-12-02 20:24:55.655 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.660 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.666 Got UPDATE_PROG_INFO, but the program is unknown to us.
2009-12-02 20:24:55.669 Set video sync frame interval to 16666
2009-12-02 20:24:55.669 Disabled deinterlacing

And so on for a long long time, where an UPDATE_PROG_INFO is coming
every 4-5ms. I have no idea what could have caused that.
Unfortunately, it's a production system and the WAF will suffer
mightily if I try to investigate.

Jim
_______________________________________________
mythtv-users mailing list
mythtv-users [at] mythtv
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

stichnot at gmail

Dec 6, 2009, 7:47 AM

Post #4 of 4 (474 views)
Permalink

Re: Slave backend disconnections after moving from r22901 to r22949 [In reply to]

On Fri, Dec 4, 2009 at 4:57 PM, Jim Stichnoth <stichnot [at] gmail> wrote:
> Unfortunately, it's a production system and the WAF will suffer
> mightily if I try to investigate.

(Wife sleeping off headache) == (opportunity for further investigation)

I found two problems so far. First,
MainServer::HandleQueryRecordings() does something strange. If a
particular recording was done on a slave backend and it has a filesize
of zero and the recording has "completed", it calls
ProgramInfo::SetFilesize() with the current filesize, which is of
course 0. SetFilesize() then calls the new Update() function which I
believe sets this into an infinite loop. So if a frontend is trying
to load up the recording list, it may never get a chance to display
the Watch Recordings screen because of all the update loop. A zero
filesize recording comes up sometimes from a failed recording, which
seems to happen especially often on the HD-PVR. I'm not sure why that
call to SetFilesize() is there; it looks like a partial copy from the
case where the file is on the master backend. This is also a
"problem" pre r22932, but a minor one because there was no Update()
call to push things into a loop.

Second, at least for an HD-PVR on a slave backend, the filesize of an
in-progress recording is being updated far more often in r22949 than
in r22901, like every 2-3ms. While this happens, mysqld is clearly
being pushed, consuming ~15% CPU on an E5200. Also, these
UPDATE_PROG_INFO events are being pushed around at a similar
frequency, unless I comment out the Update() call in SetFilesize().
The filesize updates are definitely happening at a reasonable
frequency in r22901; I don't know what happened between r22901 and
r22949 to change that.

Jim
_______________________________________________
mythtv-users mailing list
mythtv-users [at] mythtv
http://mythtv.org/cgi-bin/mailman/listinfo/mythtv-users

Index | Next | Previous | View Threaded

Interested in having your list archived? Contact Gossamer Threads