Help with emulation mode.

[mvallevand]

Sub, I really need some help in looking into a problem with emulation mode where it "feels" like the remote controls dies. Could you have a look at the attached file which is a combination of the relevant (to me) portions of the client and server logs. The original logs are here if that is easier

http://forums.gbpvr.com/showpost.php?p=2...stcount=79

I'm looking at help at in two areas:

1. On the client side, the client sends an (08 00) heartbeat out at 13:58:54 and it looks like GBPVR reacts, I get the data (8) with "Responding to ping" message. Can you tell me if that logged before or after it is sent since mvpmc doesn't actually receive the rfb heartbeat until 13:59:23 which corresponds to the remote wakes up.

2. During that dead time GBPVR received 3 seek commands but it didn't seem to do any action on them until after that heartbeat signal was sent. Do you have any idea what is blocking GBPVR from moving in the mpeg and delaying the send the resulting play (1) commands until 13:59:24?

Martin

[sub]

1. On the client side, the client sends an (0x80 00) heartbeat out at 13:58:54 and it looks like GBPVR reacts, I get the data (8) with "Responding to ping" message. Can you tell me if that logged before or after it is sent since mvpmc doesn't actually receive the rfb heartbeat until 13:59:23 which corresponds to the remote wakes up.

It is logged before responding, but the very next line sends the two bytes (nothing conditional or complex).

I've attached a patch that will log "Responding to ping (before)" and "Responded to ping (after)" to help narrow down the cause.

2. During that dead time GBPVR received 3 seek commands but it didn't seem to do any action on them until after that heartbeat signal was sent. Do you have any idea what is blocking GBPVR from moving in the mpeg and delaying the send the resulting play (1) commands until 13:59:24?

Nothing springs to mind, but if you can reproduce it with the patch to get those extra messages, it might provide some useful clues.

[Sheik Yerbouti]

OK, I'll install this patch and hope to have some logging for you asap, Martin.

[mvallevand]

Sub, that's perfect.

Everyone who is helping look into logging the problem with the remote not responding could you please use this version of the PVRX2. I don't think I can go further without it. You get the added bonus of the mini-guide on the green colour button with this.

Martin

[Lindsay]

I have installed the patch and will try for an error situation.

[mvallevand]

Sub, I can't duplicate the short remote pause issue, but I think I can finally duplicate the other less responsive time out. It is actually easy to duplicate with OSD not set minimum and with aggressive use of the skip/rewind keys. In my attached example after 36 clicks the problems appears.

You can see what I think is the problem starting at 17:46:13.038. What you will notice is all the 200000 byte reads followed at 17:46:40.420 with the rfb stream info. There are actually sent together, I send the (9) progress and then a read on the media stream. Something blocks those from being. Can you think of anything?

The new logging doesn't catch it because it happens while there is OSD and I don't send any heartbeats while the OSD is enabled, just screen refreshes every second. Is that in itself a bad thing?

Martin

[sub]

You can see what I think is the problem starting at 17:46:13.038. What you will notice is all the 200000 byte reads followed at 17:46:40.420 with the rfb stream info. There are actually sent together, I send the (9) progress and then a read on the media stream. Something blocks those from being. Can you think of anything?

There is a few CPU intensive things occurring on thread [6] (RFB) between those two points, so the only thought I really have is that it hasnt managed to get enough CPU cycles to complete that process. ie, something else going on on the machine, so its taken longer than normal to process this step.

The attached patch adds eight more logging messages in between those two points. If you reproduce the problem it and repost the logs, I'll take a closer look at what is happening.

[mvallevand]

Here you go it happened at 19:15:39.074 between these two new messages

About to send incremental update@7
About to send incremental update@8

Martin

[sub]

Unforunately it looks like something funny happening with the .net socket classes, or the underlying Windows sockets. I cant really think of anything that I could do differently between those two points.

Logger.Verbose("About to send incremental update@7");

frameSizeHeaderBuffer = new byte[] { 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x02 };
frameSizeHeaderBuffer[0] = 0;
frameSizeHeaderBuffer[1] = (byte)((compressedFrameSize & 0xff0000) >> 16);
frameSizeHeaderBuffer[2] = (byte)((compressedFrameSize & 0xff00) >> 8);
frameSizeHeaderBuffer[3] = (byte)((compressedFrameSize & 0xff));
clientSocket.Send(frameSizeHeaderBuffer);

Logger.Verbose("About to send incremental update@8");

[mvallevand]

Thanks sub, at least it gives me an area to add extra logging and possibly see what I can do. I do have the socket locked once the rfb update starts so I must have been reading from the socket ok up to this point. I think I will try blocking the progress and socket reads at this point and just play whatever is cached. I'm running bi-directionally on the socket and I don't know if that is good at this point.

Martin