PDA

View Full Version : Help with emulation mode.



mvallevand
2007-12-16, 06:49 AM
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=246550&postcount=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
2007-12-16, 07:15 PM
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
2007-12-16, 07:38 PM
OK, I'll install this patch and hope to have some logging for you asap, Martin.

mvallevand
2007-12-16, 07:48 PM
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
2007-12-16, 10:28 PM
I have installed the patch and will try for an error situation.

mvallevand
2007-12-16, 11:31 PM
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
2007-12-16, 11:56 PM
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
2007-12-17, 12:23 AM
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
2007-12-17, 12:29 AM
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
2007-12-17, 12:59 AM
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

mvallevand
2007-12-17, 03:45 AM
I have uploaded another alpha dongle and debug mvpmc that tries and prevents the situation that sub's increased logging indicated. I'm not sure if it fixes any other remote death problems, but I can no longer recreate the situation I discussed earlier in this thread.

Martin

jksmurf
2007-12-19, 01:28 PM
Martin

Do you still need logs produced with sub's test PVRX2 and the new 16th Dec dongle?

k.

mvallevand
2007-12-19, 01:39 PM
Yes, please, if you have a dead remote I would. The problem I was addressing was not something I ever saw in your logs.

Martin

Arnes
2007-12-19, 08:18 PM
Yes, please, if you have a dead remote I would.

I have sometimes a dead remote: Nothing happens when I issue commands and after some seconds suddenly they are executed all at once. I would help out with logs as well. I've read http://forums.gbpvr.com/showpost.php?p=186682&postcount=37
and have a few questions.

Is the mvpmc linked in that post still needed? I have the 2007-12-16 release.
How do I copy that file to the mvp? I only use GBPVR to boot the mvp. Do I have to install a DHCP/TFTP combo for that? I'm running vista.
What "are all my other startup options" for mvpmc? May I use what the ps command lists on the mvp? (-c 192.168.0.1 --vlc 192.168.0.1 --emulate ?)


I've especially observed the effect, while playing files recorded with my AverMedia M778 card. Popping up the status (blue button) often, or seeking when it's still open is almost a guarantee for blocking the remote for a while.

Files recorded with my other card (Hauppauge PVR 350) do much better.. and obviously it's on top of the recording source list ;).

Arne

mvallevand
2007-12-19, 10:28 PM
TFTP is only used to load the dongle, once it is loaded the mvp is simply a linux machine on your network. When you run the debug mvpmc to help in testing I ask that you run it directly from a share rather than flash, it definitely doesn't need a tftp or a poweroff.

You command line is fine and you can certainly copy it from ps or alternatively what I do is type cat /etc/dongle.config to display the command line. Either way saves a bit of typing.

It is interesting that you find files captured from one source behave differently I suspect that it is just coincendence or too small a sample size, but it is possible that when you have two tuners on the go extra stress is on the server causing the delays and I will watch for this.

One other thing to point out, don't use the Go OK more than once to queue up commands, if there isn't a change after the first try, it's not going to help it can only make things worse.

Martin

Arnes
2007-12-20, 01:04 AM
TFTP is only used to load the dongle, once it is loaded the mvp is simply a linux machine on your network. When you run the debug mvpmc to help in testing I ask that you run it directly from a share rather than flash, it definitely doesn't need a tftp or a poweroff.

Sorry, I haven't seen the wood for the trees. :-) Off course it's easy to load something from a share when the OS on the MVP is running.

So I have here one mpg file from the AverMedia and all I have to do is open up OSD and then seek a few times. I've switched GBPVR to debug level logging, then - funny enough - I have to try more, but finally the the mvpmc log reads something like:

18:31:06 Ping stuck avoid Keystroke 0 2 901

I have attached the logs. The mvp is rdated and is 7 hours and one second before local time and server - about 1:45 AM now.


It is interesting that you find files captured from one source behave differently I suspect that it is just coincendence or too small a sample size, but it is possible that when you have two tuners on the go extra stress is on the server causing the delays and I will watch for this.

Off course this recording was done while recording another show and probably playing one of the two time shifted. But by the time I did this test there was no additional load and the machine is new and quite well equipped (2GB RAM, 2.4GHz Core 2 Duo, very fast Raid-0 disks).

If any additional tests may help, I'm willing to do more, but first have to sleep and work.

Arne

mvallevand
2007-12-20, 04:15 AM
Arnes, I'm going to need you to use the PVRX2.exe that sub has posted on this thirty. It looks like it took thirty seconds for the heartbeat response to what mvpmc sent at 31:00 and it that same time. This is a different from the problem I was having, and I now think that either mvpmc or GBPVR is having trouble when the separate mvpmc media stream and hearbeat threads send the (9) and (8) commands too close together.

Martin

Arnes
2007-12-20, 08:27 PM
Arnes, I'm going to need you to use the PVRX2.exe that sub has posted on this thirty. It looks like it took thirty seconds for the heartbeat response to what mvpmc sent at 31:00 and it that same time. This is a different from the problem I was having, and I now think that either mvpmc or GBPVR is having trouble when the separate mvpmc media stream and hearbeat threads send the (9) and (8) commands too close together.

Sorry Martin,

I tried for an hour, but I can only reproduce the problem when setting the GBPVR logging to error level. On debug there is no way here to block the remote with the PVRX2 version sub posted here.

Arne

mvallevand
2007-12-20, 11:17 PM
Arne, don't say sorry, it is kind of why this problem is so hard to diagnose, I think it's more a timing issue then a specific bug in code and I'm trying to figure a way around it. I know that last alpha didn't get it right, it actually causes too many slow downs and I don't really think it avoids the problem.

My gut feeling is that somewhere along the way there is a collision when mvpmc sends a heartbeat every five seconds, a stream progress indicator which can be four times a second, and the remote key which happens randomly all out on the same socket from 3 separate treads and then read by gbpvr on (I think) one thread.

Martin

mvallevand
2007-12-21, 05:50 AM
I really didn't like the performance of the last alpha dongle especially during live tv. This new dongle just locks outboad rfb socket traffic to potentially slow the flow to GBPVR a little bit if GBPVR can't keep up. Let's see if this helps?

Martin

jksmurf
2007-12-22, 06:11 AM
Martin,

I was going to do another test for you, but wanted to check something

Does the mvpmc file from http://www.mvpmc.org/~mvallevand/mvpmc.zip need to be d/l again following each new dongle release? I remember I had an old version last time, this (mvpmc) one is dated 16 Dec, but the Alpha Dongle (http://www.mvpmc.org/~mvallevand/) is dated 20 Dec (File Datestamp, not the filename which is 21st)

k.

mvallevand
2007-12-22, 06:18 AM
K you are right, I have now updated mvpmc too.

Martin

jksmurf
2007-12-22, 07:07 AM
K you are right, I have now updated mvpmc too. Martin

Here you go, using sub's PVRX2.exe test file above, mvpmc just uploaded today, 21/12 dongle, datestamps done, putty log attached.

I had a couple of instances of non-reactive remote last night, and a couple at the START of this test, but generally the test was pretty good. Probably nothing in the logs for you to troubleshoot! Always like that during a test. Seriously though, sometimes it (the remote) just seem doesn't respond.

I did a few Go OK's, some scrolling around, some looking at some movies, in out of Plugins, FF, Skip, etc.

k.

Turas
2007-12-22, 11:01 AM
today i started with tests again, using pvrx2-logging version and newest alpha-dongle.

soon after startup, when scrolling in tvguied - i ran into a completely stuck remote.

looking at the logs i found that i had some problems with mlupdate (ml2 is the only plugin i've currently enabled). mlupdate produced a huge amount of logging at the time the remote got stuck. at that time mlupdate had been configured to use the internal-updater which probably uses resources of pvrx2?. so the remote probably has been "stuck" because of pvrx2 being busy with plugin-logging... (btw: i already switched to external-update and solved other problems with the plugin for next tests i will do!)

i think i can remember a previous post where sub said, that a reason for pvrx2 not sending the requested data / response in time could be, that the responsible pvrx2-thread is not getting the needed cpu time... in the case today this seems to be exactly the reason. therefore on the mvp/mvpmc-side nothing could have been done to avoid the "stuck" remote.

@sub: is there a way to prevent plugins from "stealing" too much cpu-time from the mvp-gui-handling? e.g. running the mvp-gui-handling in a separate thread - maybe even with a higher (configurable) priority? (don't know if this is already done, or if it's possible at all...)

br turas
---

Turas
2007-12-22, 12:05 PM
some further results.
(still have to fix problems with ml-updater...)

-) mvpmc really stable, no single remote problem occured.

-) no problems with livetv and switching channels

-) ff/rewind sometimes get stuck on play-video (go/ff-go/rewind) seem to be a bit more stable concerning that.

-) rewind, when playing back a show currently being recorded, always got stuck. when you invoke osd in such situation, it indicates you are at the end of the recording which is not true. can be solved by pressing play sometimes.

-) when having problems with ff/rewind, it happens that the upper part of osd (showing the progress) is not displayed at all. solved only after stopping / playback again.

some thoughts about handling ff/rewind and channel-changing (should go into another thread probably)
=> would it be possible to make ff/ rewind "less fluently" by displaying not so many pics and doing kind of "mini-skips" instead. maybe even make it configurable or increasing the "pic-skip-rate" with each press of ff/rewind (= making it a bit faster with every key-press)?

as far as i remember the hauppauge-dongle is doing the ff/rewind a bit faster
(not saying that the hauppauge is at any rate better!!! already realized the value of mvpmc... :))

=> could some key of the remote be used for switching back and forward between the current and previous tv-channel?
(e.g.
- watching channel 1,
- selecting channel 10 manually with "10/ok"
- pressing the remote-button switches to channel 1 again
- pressing the remote-button again switches to channel 10 again
-...)

logs attached.
br turas
---

mvallevand
2007-12-22, 12:13 PM
Here you go, using sub's PVRX2.exe test file above, mvpmc just uploaded today, 21/12 dongle, datestamps done, putty log attached.

I had a couple of instances of non-reactive remote last night, and a couple at the START of this test, but generally the test was pretty good. Probably nothing in the logs for you to troubleshoot! Always like that during a test. Seriously though, sometimes it (the remote) just seem doesn't respond.

I did a few Go OK's, some scrolling around, some looking at some movies, in out of Plugins, FF, Skip, etc.

k.

k, it looks like your gbpvr verbose server side logging got turned off again at 14:55:13 with one of your converter3 errors which is before any problems occurred. I think xrecord is either turning logging off itself or corrupting memory which leads to other delays.

I have no doubt that gbpvr's responses to mvpmc get blocked somehow. The only good thing is that I hsve yet to see a log that indicates mvpmc is dieing during the unresponsive period. My only fear is this is more a network or o.s. issue with tcp and QoS that sub or I can't control.

Martin

mvallevand
2007-12-22, 03:28 PM
some further results.
(still have to fix problems with ml-updater...)

For the this first test you also hit the remote key too early after startup.



-) mvpmc really stable, no single remote problem occured.

-) no problems with livetv and switching channels


Since you AutoStart two servers, you were running the server that did not have server side logging on. Unlike Arne I find that with reduced logging I get improved performance and unfortunately it is a much harder to debuf




-) ff/rewind sometimes get stuck on play-video (go/ff-go/rewind) seem to be a bit more stable concerning that.



Go FF is just 2x play so it should only stick because of bandwidth. Go Rewind is just rewind.




-) rewind, when playing back a show currently being recorded, always got stuck. when you invoke osd in such situation, it indicates you are at the end of the recording which is not true. can be solved by pressing play sometimes.

-) when having problems with ff/rewind, it happens that the upper part of osd (showing the progress) is not displayed at all. solved only after stopping / playback again.



These look like server side issues.




some thoughts about handling ff/rewind and channel-changing (should go into another thread probably)
=> would it be possible to make ff/ rewind "less fluently" by displaying not so many pics and doing kind of "mini-skips" instead. maybe even make it configurable or increasing the "pic-skip-rate" with each press of ff/rewind (= making it a bit faster with every key-press)?



Do you mean the short skip option on the Misc screen?



as far as i remember the hauppauge-dongle is doing the ff/rewind a bit faster
(not saying that the hauppauge is at any rate better!!! already realized the value of mvpmc... :))


There's no question that Hauppauge does this much better. When I first started this the mvpmc demux didn't even handle the special GOP mpegs that were being sent and I still can't figure out how to avoid the black screen that happens on and off. I find that the Hauppauge server does a better job too, but I think most GBPVR users use short skip anyway




=> could some key of the remote be used for switching back and forward between the current and previous tv-channel?
(e.g.
- watching channel 1,
- selecting channel 10 manually with "10/ok"
- pressing the remote-button switches to channel 1 again
- pressing the remote-button again switches to channel 10 again
-...)



The new remotes have a previous channel key.

Thanks, and note in one of your logs MVP-PVRX2.exe-3.log at 12:06 there is what I consider a classic timeout with a screen update and heartbeat both dead on the gui stream but there is no client log to help. What's becoming apparent is the timeout is not random, it is thirty seconds.

Martin

Turas
2007-12-22, 03:42 PM
For the this first test you also hit the remote key too early after startup.


i'll remember that one. is there a message appearing on telnet-log to indicate that remote can be used?



Since you AutoStart two servers, you were running the server that did not have server side logging on. Unlike Arne I find that with reduced logging I get improved performance and unfortunately it is a much harder to debuf


corrected that one already



Do you mean the short skip option on the Misc screen?


no. short skip uses at least 30seconds between steps and most important it isn't automatically done repeatedly without pressing the button again.
what i mean is just skipping some pics (if possible at all e.g. 1s or 2s, ...) and when you press the button again e.g. doubling the skipping (e.g. 2s or 4s, ...)
that's how my "old vcr" did it and i really liked it ;)



The new remotes have a previous channel key.


ok. but i still have an old one. would be reeeaaly nice if the "empty-key" between "mute" and "full" could be used for that? :cool:

br turas
---

mvallevand
2007-12-22, 04:48 PM
Since I don't know why GBPVR doesn't respond if the the keystroke is early, I just count 8 seconds. It definitely shouldn't be before the first Handle ping.

I don't think the short skip has to be that long people have posted their setting. For PVRX2 on PC I think only short skip is supported, that's why I allowed the GO FF.

The next alpha will have Go ChannelUp set to prev channel.

Martin

Turas
2007-12-22, 05:02 PM
played music for a while using musiclibrary2.
when i tried to stop and return to main menu a hang occured. music stopped but i couldnt go back to mainmenu.

happened about 17:50 - 17:53

br turas
---

mvallevand
2007-12-22, 06:41 PM
played music for a while using musiclibrary2.
when i tried to stop and return to main menu a hang occured. music stopped but i couldnt go back to mainmenu.

happened about 17:50 - 17:53

br turas
---

I think there is a general problem with ML2 and GBPVR in mvpmode when the back or stop is pressed. The usual manifestation for me is a working screensaver that I can't exit but all socket traffic looks good. I passed some logs on to sub at one time to see if he could find anything.

To avoid this I think it is best to hit OK to wake the screensaver and then stop. I know this is easier said then done.

Martin

Turas
2007-12-22, 07:33 PM
...
To avoid this I think it is best to hit OK to wake the screensaver and then stop. I know this is easier said then done.


this said... the screensaver didn't show up at all during playback. thought its maybe because of mvpc-debug version. but obviously it isn't.

br turas
---

mvallevand
2007-12-22, 08:07 PM
this said... the screensaver didn't show up at all during playback. thought its maybe because of mvpc-debug version. but obviously it isn't.

br turas
---

No the ss works fine for me. Are you saying it never works for you?

Martin

Sheik Yerbouti
2007-12-24, 06:39 PM
Hi Martin,

Do you still need logs for the "remote not responding" problem. I'm using your latest dongle, but I'm still having this problem.

mvallevand
2007-12-24, 07:31 PM
Hi Martin,

Do you still need logs for the "remote not responding" problem. I'm using your latest dongle, but I'm still having this problem.

Sure, if you are using sub's patch from this thread, I can see if I can narrow anything down.

Martin

Arnes
2007-12-30, 08:01 PM
Hi,

back from Christmas again..

Martin, are you interested in some kind of network traces using Wireshark ..or are you already sure by the GBPVR traces that the commands properly arrive there?

And if, is there a (concise) description of the protocol?

Arne

mvallevand
2007-12-30, 08:48 PM
Hi,

back from Christmas again..

Martin, are you interested in some kind of network traces using Wireshark ..or are you already sure by the GBPVR traces that the commands properly arrive there?

And if, is there a (concise) description of the protocol?

Arne

Thanks Arne those traces would help a lot they can be my Christmas present. If you do this could you change the time stamp format in column 1 to be clock time and not relative time so I can marry up the three logs. Also these logs can grow pretty large so what I am interested in can be captured with this filter "port 8337 or port 8338 or port 5906 or port 5907".

Additionally before sending them if you could filter on len > 0 and and len <=40 it would help a lot. I am not convinced that GBPVR receives them in the order, I do see occasional TCP Zerowindow indicating the client is busy.

Documentation on the protocol between the client and server (including my undocumented source) is not complete but there is a lot of documentation on the headers that you will see in the traces done by Dominic Morris. Here are to good places to start

http://www.rst38.org.uk/mediamvp/protocol.html
and
http://vdr-mediamvp.cvs.sourceforge.net/*checkout*/vdr-mediamvp/mediamvp/docs/protocol.txt?revision=1.2

FYI, I am especially interested in the progress message and the ping messages comparing when they arrive and when they are in the GBPVR logs as Data read 1 (9) or (8) messages.

Martin

Lindsay
2007-12-31, 04:21 AM
Thanks, guys, for continuing to work on this as I had another instance yesterday.

Happy New Year, Martin, and all.

mvallevand
2007-12-31, 12:51 PM
Thanks, guys, for continuing to work on this as I had another instance yesterday.

Happy New Year, Martin, and all.

Happy New Year to you and everyone too. I guess that's already old news in NZ but wherever we live it's soon one year closer to the end of analog television.

Martin

Arnes
2007-12-31, 02:31 PM
Thanks Arne those traces would help a lot they can be my Christmas present.

Hi,

I did some initial tests for the traces with the dongle.bin from 28.12. and initially was not able to navigate in the recordings list without "hangs" for some seconds. I got a whole lot of tcp communication errors between the mvp and the server. Wireshark traced duplicate ACKs going from the mvp to the server. Sometimes the server requested TCP retransmissions. After some additional tests I guessed restarting the recording service may cause the effect, but could not reproduce.

So I finally setup everything as needed for logging and went on reproducing the problem. The only event I captured was a black screen when starting to play a show (mvpmc.log 7:23:08, MVP-PVRX2.exe-1.log 14:22:55.908). At 14:24:22.822 I hit the power button on the remote. Included in the archive is blackscreen-excerpt.pcap. (The TCP-checksum errors in the log seem to be actually caused by checksum-offloading.)

Now I have to help prepare our new year's eve party, will continue testing next year and wish everyone a happy new year! :)

Arne

mvallevand
2007-12-31, 02:46 PM
Thanks a lot Arne. This is absolutely the "hitting the remote key too early" problem and I will look at the traces when I get home. I am fairly certain this is not an mvpmc problem.

Happy New Year.

Martin

mvallevand
2008-01-02, 11:12 PM
Arne I loaded your pcap file but the time doesn't match either log. It is 0800 and the others are 1400

Martin

Arnes
2008-01-03, 12:05 AM
Arne I loaded your pcap file but the time doesn't match either log. It is 0800 and the others are 1400

Martin

Hi Martin,

no Problem, Wireshark seems to display according to the configured timezone. If you see 0800 that's ok: you live at GMT-5, I'm at GMT+1.

Arne

mvallevand
2008-01-03, 04:58 AM
Thanks. This is different then other issues but there were a couple of things that mvpmc can't handle which gives me something to look into. GBPVR seems to be duplicating the open file requests even adding an inadvertent screen update so something is up. There is one instance starting at 14:20:51 but the more serious one starts at 14:22:55 with two separate calls to mvpmc to open a file possibly causing the logic to go crazy. You can see the media socket is wanting attention in the pcap file at seq # 152, but from that point on mvpmc isn't issuing a read on the media socket and eventually GBPVR gives up

The good news is the remote control socket never goes dead and every key press is going through. I haven't really look too much at errors coming from the media server but I will do that next. I think this is a GBPVR bug but I might be able to work around it.

Martin