[mythtv-users] Slave backend disconnections after moving from r22901 to r22949

Jim Stichnoth stichnot at gmail.com
Sat Dec 5 00:57:02 UTC 2009


On Thu, Dec 3, 2009 at 11:30 PM, Gregorio Gervasio, Jr.
<gregorio.gervasio at gmail.com> 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


More information about the mythtv-users mailing list