Skipping issue on PCH

[Sheik Yerbouti]

Chris it doesn't look like you increased the pre-resume delay? Maybe start with 750 and move up from there.

Martin

Martin, I've changed it to 750 and later to 1000, but npvr is recording. I set the number of mvp servers to 0 and changed it back to one, but I don't know if that's enough to make it use the new preresumedelay, how can I check this?
Anyway, it's not working for me at all. I can reproduce the resume problem quite easy with some files, just start a recording, skip 15 minutes, stop, and choose resume. Next I see the current time at 00:00:00 (and sometimes a negative start time), although it jumped to the right position. Does the preresumedelay have any effect on this behaviour (I have no idea what's it's for)?
Like I said, I've started recording more in HD, is it related to this?

Chris

[mvallevand]

You need to restart the record service to launch a new server. And yes HD files might need more time to prebuffer before that first seek is acted upon.

Martin

[bgowland]

In the terms of the PCH agressive but certainly not crazy or extreme. I am simply explainly I see the most problem with the demux after this behaviour It takes about 2 seconds (or more) do do a seek given the delayed response of the network so that is 3, 1, 3, 2, 1, 1, 1 basically hitting the screen as soon as their is something perceptible that you don't like. With all of this there is still background buffering and streaming still going on that you aren't even aware of, so those ones are close to zero. I could likely tweak the demux buffer to reduce the risk, but there would be stuttering.

OK, I was just working on the principle that everything would be completely synchronous, i.e., either skip requests would be queued and processed in strict order (allowing each operation to correctly 'settle') or that multiple rapid requests might be discarded if a previous request was in-progress.

Asked and answered already, the demux get stuck in the file and I force mvpmcx2 to stop so you can safely restart at the same point it got stuck

Apologies for being a bit slow on the uptake - still relatively new to the PCH and how it works.

So basically when you mention the 'demux' you're talking the PCH side of things as I assume mvpmcx2 is pulling the raw .ts file and it (the PCH) is responsible for demuxing - correct? In that case, the question is indeed answered but it's not very satisfying - don't get me wrong, if this is a PCH bug then I'm not blaming you - it's just slightly frustrating that this can happen with single skip request and there doesn't appear to be any good explanation as to what causes the demux getting stuck. Oh well.

I have some code to silently resume behind the scenes that should be triggered I was hoping to see why it didn't work.

If this could be made to work then it would go a long way to improving the situation.

BTW, I upped the PreResumeDelay to 2000 to see if that helps after a drop back to Recordings. If it does then it will also go a long way to improving things (especially when it comes to my wife).

Thanks for looking at this.

Cheers,
Brian

[mvallevand]

OK, I was just working on the principle that everything would be completely synchronous, i.e., either skip requests would be queued and processed in strict order (allowing each operation to correctly 'settle') or that multiple rapid requests might be discarded if a previous request was in-progress.

I can't wait for them to settle. The PCH does this and it can cause many seconds of blank screen,

So basically when you mention the 'demux' you're talking the PCH side of things as I assume mvpmcx2 is pulling the raw .ts file and it (the PCH) is responsible for demuxing - correct?

There's a software demux in front of some DMA'd buffered queues on the Sigma processor.

in that case, the question is indeed answered but it's not very satisfying - don't get me wrong, if this is a PCH bug then I'm not blaming you - it's just slightly frustrating that this can happen with single skip request and there doesn't appear to be any good explanation as to what causes the demux getting stuck. Oh well.

I had to code the seek logic into the soft demux, it might be my bug so you might have to "blame" me, I might not control DMA perfectly, but I am guessing on a lot of the stuff I do.

If this could be made to work then it would go a long way to improving the situation./QUOTE]

I added the silent resume for a problem file Sheik Yerbouti sent me that duplicated this scenario well. I should be able to use it to tell if I have broken it.

[QUOTE]BTW, I upped the PreResumeDelay to 2000 to see if that helps after a drop back to Recordings. If it does then it will also go a long way to improving things (especially when it comes to my wife).

If it doesn't resume send the logs.

Martin

[bgowland]

I had to code the seek logic into the soft demux, it might be my bug so you might have to "blame" me,

lol - OK, I'll hold on to that thought.

If it doesn't resume send the logs.

I had one drop back to recordings last night - another episode of Glee at a similar time into the playback this time ~47mins with the previous one I sent the logs for being ~46mins. It always seems to happen further into playback of a recording - weird.

Anyway, I digress - I was able to immediately resume back to the exact point (the person on the advert was saying the same sentence as when I'd pressed skip that caused the drop). The problem now seems to be (back to my original post) the OSD timeline showed 0:0:0. Is the npvr NMT/MVP server responsible for delivering the correct time or is that an mvpmcx2 issue?

I'll keep tracking this and provide logs for anything else I see - I don't have the logs for the one I mention above but will grab them tonight if I see anything worth reporting.

Cheers,
Brian

[Sheik Yerbouti]

I believe Brian is seeing the exact same behavioiur as me. After resuming the timeline shows 00:00:00, but it does go to the right spot. I've got some logs that include timing.info and putty.log. I've set the prereumedelay to 2000. BTW, it doesn't occur on alle files, but I can reproduce it with this one every time. I start the file, skip 15 minutes, stop, resume and than I see the wrong timeline.

Chris

[mvallevand]

Chris, I still don't see enough prebuffer (you maybe are at 2000 now?).

The web streaming starts at

2011-09-15 20:46:09.735 [DEBUG][4] Got Web Request (192.168.1.67): /stream

and the seek is still too soon.

2011-09-15 20:46:09.486 [DEBUG][3] Sending seek request to MVP/NMT. current position = 905, duration = 1557

Martin

[mvallevand]

No, I dont think anything has changed. Resuming has always initiated playback, if a PCH/MVP then sleep for a short period, then seeked to the resume spot.

The duration of that sleep can be tweaked with the /Settings/General/PreResumeDelay. The default was 500ms.

Sub, is there anyway you could keep the GUI stream open (or ideally both) and send the seek with a non-blocking timer after the delay period? It looks all the GUI thread traffic is gueuing up on on the network during the pause as the NMT player is sending it back to the server. I actually am not having problems with this but I am not seeing this extremely blocked traffic in bgowland or Sheik Yerbouti's logs.

Code:

2011-09-16 00:39:36.987    [DEBUG][7]    Request completed. 200000 bytes sent


2011-09-16 00:39:41.705    [DEBUG][3]    PlaybackPositionHelper.GetPlaybackPosition(C:\movies\Cold Case\Cold Case_20110915_23000000.ts)
2011-09-16 00:39:41.705    [DEBUG][3]    Sending 'Play' Request
2011-09-16 00:39:41.705    [DEBUG][3]    Sending seek request to MVP/NMT. current position = 303, duration = 1055
2011-09-16 00:39:41.746    [DEBUG][7]    Received: STREAM_SEEK
2011-09-16 00:39:41.746    [DEBUG][7]    RollingFile.Position returning 1000000
2011-09-16 00:39:41.746    [DEBUG][7]    Stream Length: 2474438328
2011-09-16 00:39:41.746    [DEBUG][7]    Stream Duration: 1055.41
2011-09-16 00:39:41.746    [DEBUG][7]    requestedPositionInSeconds: 303
2011-09-16 00:39:41.746    [DEBUG][7]    Set position to:710391993
2011-09-16 00:39:41.746    [DEBUG][7]    Received request to seek to pos:710391993
2011-09-16 00:39:41.746    [DEBUG][7]    RollingFile.Seek(710391993)
2011-09-16 00:39:41.746    [DEBUG][7]    RollingFile.Position returning 710391993
2011-09-16 00:39:42.705    [DEBUG][3]    ShowDetailsPopup.Dispose()
2011-09-16 00:39:42.705    [DEBUG][3]    UiStatic.Dispose()
2011-09-16 00:39:42.705    [DEBUG][3]    OnKeyDown() complete
2011-09-16 00:39:42.705    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.705    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.705    [DEBUG][3]    MVP data read: 1   (3)
2011-09-16 00:39:42.705    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.705    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.705    [DEBUG][3]    MVP data read: 1   (7)
2011-09-16 00:39:42.705    [DEBUG][3]    Got ACK
2011-09-16 00:39:42.705    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.705    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.705    [DEBUG][3]    MVP data read: 1   (3)
2011-09-16 00:39:42.705    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.705    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.705    [DEBUG][3]    MVP data read: 1   (7)
2011-09-16 00:39:42.705    [DEBUG][3]    Got ACK
2011-09-16 00:39:42.705    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.705    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.705    [DEBUG][3]    MVP data read: 1   (3)
2011-09-16 00:39:42.705    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.705    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.705    [DEBUG][3]    MVP data read: 1   (7)
2011-09-16 00:39:42.705    [DEBUG][3]    Got ACK
2011-09-16 00:39:42.705    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.705    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.706    [DEBUG][3]    MVP data read: 1   (9)
2011-09-16 00:39:42.706    [DEBUG][3]    Raw PTS received:43544
2011-09-16 00:39:42.706    [DEBUG][3]    Reported PTS now:0  time: 0
2011-09-16 00:39:42.706    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.706    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.706    [DEBUG][3]    MVP data read: 1   (9)
2011-09-16 00:39:42.706    [DEBUG][3]    Raw PTS received:90090
2011-09-16 00:39:42.706    [DEBUG][3]    Reported PTS now:46546  time: 1.03435555555556
2011-09-16 00:39:42.706    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.706    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.706    [DEBUG][3]    MVP data read: 1   (9)
2011-09-16 00:39:42.706    [DEBUG][3]    Raw PTS received:135135
2011-09-16 00:39:42.706    [DEBUG][3]    Reported PTS now:91591  time: 2.03535555555556
2011-09-16 00:39:42.706    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.706    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.706    [DEBUG][3]    MVP data read: 1   (7)
2011-09-16 00:39:42.706    [DEBUG][3]    Got ACK
2011-09-16 00:39:42.706    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.706    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.706    [DEBUG][3]    MVP data read: 1   (9)
2011-09-16 00:39:42.706    [DEBUG][3]    Raw PTS received:169670
2011-09-16 00:39:42.706    [DEBUG][3]    Reported PTS now:126126  time: 2.8028
2011-09-16 00:39:42.706    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.706    [DEBUG][3]    MVP waiting for data
2011-09-16 00:39:42.706    [DEBUG][3]    MVP data read: 1   (7)
2011-09-16 00:39:42.706    [DEBUG][3]    Got ACK
2011-09-16 00:39:42.965    [DEBUG][3]    MVP request processed
2011-09-16 00:39:42.965    [DEBUG][3]    MVP waiting for data
..finally responding to the seek
2011-09-16 00:39:42.965    [DEBUG][3]    MVP data read: 1   (9)
2011-09-16 00:39:42.965    [DEBUG][3]    Raw PTS received:13656143
2011-09-16 00:39:42.965    [DEBUG][3]    Reported PTS now:13612599  time: 302.5022

Martin

[sub]

Sub, is there anyway you could keep the GUI stream open (or ideally both) and send the seek with a non-blocking timer after the delay period?

I haven't really been following the thread (been really busy with other stuff last few days). You're still talking about the skip that happens when resuming ah?

[Sheik Yerbouti]

I've changed the preresumedelay to 4000, it's working now, although I did see a negative start time after resuming. I'm curious too about the source of this timeline.

Chris