skipping fouled up again

johnsonx42 · 2010-12-24, 10:09 PM

Sub,

It seems any change you make to the NPVRTSReader to fix the resume issue ends up breaking skipping in one way or another. Skipping is now back to the way it was when you first released 1.5.28, which was also the result of your first effort to patch the resume issue.

Early on in a file skips seem more or less ok, but further into the file the forward skips go too far, and the backwards skips either go back very little or actually jump forward. I've tested several files recorded both before and after installing 1.5.36, it's the same in all of them. In the most explicit test, I start playing a 1 hour HD recording, jump in about 20 minutes with the big skip (which should take 20 1-minute skips but actually requires only 17), then start trying to skip back with the small skip; you can see it continues to advance forward in the file:

Code:
2010-12-24 13:42:05.019    [DEBUG][1]    PlaybackPositionHelper.GetPlaybackPosition(F:\Recordings\Sesame Street\Sesame Street_20101224_12001300.ts)

... bunch of messages about elements and alpha fades...

2010-12-24 13:42:06.498    [DEBUG][1]    Adding system AC3 decoder

2010-12-24 13:42:06.498    [DEBUG][1]    about to load decoder

2010-12-24 13:42:06.508    [DEBUG][1]    added decoder to graph

2010-12-24 13:42:06.508    [DEBUG][1]    adding audio renderer: Default DirectSound Device

2010-12-24 13:42:06.531    [DEBUG][1]    Adding system MPEG1 Layer2 decoder

2010-12-24 13:42:06.531    [DEBUG][1]    about to load decoder

2010-12-24 13:42:06.542    [DEBUG][1]    added decoder to graph

2010-12-24 13:42:06.542    [DEBUG][1]    adding audio renderer: Default DirectSound Device

2010-12-24 13:42:06.568    [DEBUG][1]    Adding system MPEG2 decoder

2010-12-24 13:42:06.568    [DEBUG][1]    Adding EVR renderer

2010-12-24 13:42:06.665    [DEBUG][1]    about to load decoder

2010-12-24 13:42:06.670    [DEBUG][1]    added decoder to graph

2010-12-24 13:42:06.688    [DEBUG][1]    Static Reference clock set to: Default DirectSound Device

2010-12-24 13:42:07.262    [DEBUG][1]    Playback graph running...

2010-12-24 13:42:07.262    [DEBUG][1]    Graph filter list:

2010-12-24 13:42:07.262    [DEBUG][1]     - NPVR CC Dump

2010-12-24 13:42:07.262    [DEBUG][1]     - EVR Renderer

2010-12-24 13:42:07.262    [DEBUG][1]     - NPVR PES Collector (DVBSubs)

2010-12-24 13:42:07.262    [DEBUG][1]     - Default DirectSound Device 0001

2010-12-24 13:42:07.262    [DEBUG][1]     - Default DirectSound Device

2010-12-24 13:42:07.263    [DEBUG][1]     - Line 21 Decoder

2010-12-24 13:42:07.263    [DEBUG][1]     - Microsoft DTV-DVD Audio Decoder

2010-12-24 13:42:07.263    [DEBUG][1]     - AC3Filter

2010-12-24 13:42:07.263    [DEBUG][1]     - ATI MPEG Video Decoder

2010-12-24 13:42:07.263    [DEBUG][1]     - MPEG-2 Demultiplexer

2010-12-24 13:42:07.263    [DEBUG][1]     - NPVR TS Reader

2010-12-24 13:42:07.294    [DEBUG][1]    CheckCache() indicates:F:\Recordings\Sesame Street\folder.jpg is cached

2010-12-24 13:42:07.294    [DEBUG][1]    CheckCache() indicates:F:\Recordings\Sesame Street\folder.jpg is cached

2010-12-24 13:42:07.312    [DEBUG][1]    GetEventCode() returned: 0x000d

2010-12-24 13:42:07.312    [DEBUG][1]    GetEventCode() returned: 0x000e

2010-12-24 13:42:07.312    [DEBUG][1]    GetEventCode() returned: 0x8102

2010-12-24 13:42:07.312    [DEBUG][1]    Aspect ratio now: 16x9

2010-12-24 13:42:07.312    [DEBUG][1]    Resolution is now: 1280x720

2010-12-24 13:42:07.312    [DEBUG][1]    Source Aspect Ratio: 16x9

2010-12-24 13:42:07.312    [DEBUG][1]    Setting display rect: 0.000000,0.125000,1.000000,0.875000

2010-12-24 13:42:07.312    [DEBUG][1]    GetEventCode() returned: 0x8101

2010-12-24 13:42:10.058    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:10.058    [DEBUG][1]    Using timing.info, jumping to time 63.835693 (offset 71522344)

2010-12-24 13:42:10.779    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:10.780    [DEBUG][1]    Using timing.info, jumping to time 125.613388 (offset 141954664)

2010-12-24 13:42:12.004    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:12.004    [DEBUG][1]    Using timing.info, jumping to time 188.508774 (offset 213980096)

2010-12-24 13:42:12.593    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:12.594    [DEBUG][1]    Using timing.info, jumping to time 252.400436 (offset 286592464)

2010-12-24 13:42:13.106    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:13.107    [DEBUG][1]    Using timing.info, jumping to time 316.479218 (offset 360714096)

2010-12-24 13:42:13.635    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:13.636    [DEBUG][1]    Using timing.info, jumping to time 382.146973 (offset 437686560)

2010-12-24 13:42:14.875    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:14.875    [DEBUG][1]    Using timing.info, jumping to time 450.760559 (offset 517174464)

2010-12-24 13:42:15.418    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:15.420    [DEBUG][1]    Using timing.info, jumping to time 521.188599 (offset 599010112)

2010-12-24 13:42:15.829    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:15.830    [DEBUG][1]    Using timing.info, jumping to time 593.866028 (offset 683612744)

2010-12-24 13:42:17.462    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:17.463    [DEBUG][1]    Using timing.info, jumping to time 669.664978 (offset 771485448)

2010-12-24 13:42:18.875    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:18.875    [DEBUG][1]    Using timing.info, jumping to time 747.280762 (offset 859106608)

2010-12-24 13:42:20.236    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:20.237    [DEBUG][1]    Using timing.info, jumping to time 825.006958 (offset 949997840)

2010-12-24 13:42:21.270    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:21.271    [DEBUG][1]    Using timing.info, jumping to time 904.716675 (offset 1042062944)

2010-12-24 13:42:22.616    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:22.617    [DEBUG][1]    Using timing.info, jumping to time 987.135437 (offset 1137565816)

2010-12-24 13:42:23.658    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:23.659    [DEBUG][1]    Using timing.info, jumping to time 1071.436279 (offset 1233823320)

2010-12-24 13:42:24.277    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:24.279    [DEBUG][1]    Using timing.info, jumping to time 1156.740112 (offset 1331254696)

2010-12-24 13:42:25.138    [DEBUG][1]    appcommand: 11 +(lParam: B0000, wParam: 130268)

2010-12-24 13:42:25.139    [DEBUG][1]    Using timing.info, jumping to time 1243.085205 (offset 1431620752)

2010-12-24 13:42:29.446    [DEBUG][1]    appcommand: 50 +(lParam: 10320000, wParam: 130268)

2010-12-24 13:42:29.447    [DEBUG][1]    Using timing.info, jumping to time 1265.619263 (offset 1458535960)

2010-12-24 13:42:31.165    [DEBUG][1]    appcommand: 50 +(lParam: 10320000, wParam: 130268)

2010-12-24 13:42:31.166    [DEBUG][1]    Using timing.info, jumping to time 1286.993408 (offset 1482851880)

2010-12-24 13:42:32.719    [DEBUG][1]    appcommand: 50 +(lParam: 10320000, wParam: 130268)

2010-12-24 13:42:32.720    [DEBUG][1]    Using timing.info, jumping to time 1308.229858 (offset 1507167800)

2010-12-24 13:42:34.092    [DEBUG][1]    appcommand: 50 +(lParam: 10320000, wParam: 130268)

2010-12-24 13:42:34.093    [DEBUG][1]    Using timing.info, jumping to time 1329.799805 (offset 1532322200)

2010-12-24 13:42:35.333    [DEBUG][1]    appcommand: 50 +(lParam: 10320000, wParam: 130268)

2010-12-24 13:42:35.334    [DEBUG][1]    Using timing.info, jumping to time 1351.696655 (offset 1557476600)

2010-12-24 13:42:36.867    [DEBUG][1]    appcommand: 50 +(lParam: 10320000, wParam: 130268)

2010-12-24 13:42:36.868    [DEBUG][1]    Using timing.info, jumping to time 1374.510620 (offset 1583721024)

2010-12-24 13:42:38.095    [DEBUG][1]    appcommand: 50 +(lParam: 10320000, wParam: 130268)

2010-12-24 13:42:38.096    [DEBUG][1]    Using timing.info, jumping to time 1397.207642 (offset 1608959272)

2010-12-24 13:42:39.390    [DEBUG][1]    appcommand: 1 +(lParam: 10000, wParam: 130268)

2010-12-24 13:42:39.390    [DEBUG][1]    PlaybackPositionHelper.StorePlaybackPosition(F:\Recordings\Sesame Street\Sesame Street_20101224_12001300.ts, 1429, 3599)

2010-12-24 13:42:39.533    [DEBUG][1]    Stopping graph@3

The complete log is attached, along with the Timing.Info from that file.

***sub*** · 2010-12-26, 09:27 PM

Can you see if this helps?

petercooperjr · 2010-12-27, 12:47 AM

I have the same issue, and the patch seems to make things work much better.

***sub*** · 2010-12-27, 01:12 AM

petercooperjr Wrote:I have the same issue, and the patch seems to make things work much better.

Great. We'll see what others have to say.

johnsonx42 · 2010-12-27, 07:11 AM

Thanks sub, that seems to fix it. I'd also noticed some comskip jump points were off, now with the patch the comskips are good too.

***sub*** · 2010-12-27, 03:57 PM

Great.

The skips were accurate, but it was a case of misreported current playback location (which is used as a basis for the next skip).

johnsonx42 · 2010-12-27, 05:12 PM

ah, I see... it jumped the right amount from where it thought it was, it just didn't know where it was to start with.

I presume you'll remove all that extra logging the next time you release an Unmanaged.dll update? Watching just one 1-hour show filled all 4 logs last night. Or you might consider adding a "Diagnostic" log level that's disabled by default and put these sorts of extreme detail events in that log level. I've dealt with other products that do that, and it does come in handy sometimes.

***sub*** · 2010-12-27, 05:18 PM

johnsonx42 Wrote:I presume you'll remove all that extra logging the next time you release an Unmanaged.dll update? Watching just one 1-hour show filled all 4 logs last night. Or you might consider adding a "Diagnostic" log level that's disabled by default and put these sorts of extreme detail events in that log level. I've dealt with other products that do that, and it does come in handy sometimes.

I'm not in front of my development PC right now, but what were the message most filling the log? I'll make sure they're removed for the next update.

johnsonx42 · 2010-12-27, 06:14 PM

Code:
2010-12-27 09:45:59.443    [DEBUG][1]    Reader reports offset 3880696000

2010-12-27 09:45:59.453    [DEBUG][1]    Reader reports current time as 3443.687988

2010-12-27 09:45:59.560    [DEBUG][1]    Reader reports offset 3880790000

2010-12-27 09:45:59.562    [DEBUG][1]    Reader reports current time as 3444.547119

2010-12-27 09:45:59.659    [DEBUG][1]    Reader reports offset 3880978000

2010-12-27 09:45:59.661    [DEBUG][1]    Reader reports current time as 3444.547119

2010-12-27 09:45:59.770    [DEBUG][1]    Reader reports offset 3881072000

2010-12-27 09:45:59.772    [DEBUG][1]    Reader reports current time as 3444.547119

2010-12-27 09:45:59.890    [DEBUG][1]    Reader reports offset 3881166000

2010-12-27 09:45:59.894    [DEBUG][1]    Reader reports current time as 3444.547119

2010-12-27 09:45:59.992    [DEBUG][1]    Reader reports offset 3881260000

2010-12-27 09:45:59.998    [DEBUG][1]    Reader reports current time as 3444.547119

2010-12-27 09:46:00.106    [DEBUG][1]    Reader reports offset 3881448000

2010-12-27 09:46:00.107    [DEBUG][1]    Reader reports current time as 3444.547119

2010-12-27 09:46:00.208    [DEBUG][1]    Reader reports offset 3881542000

2010-12-27 09:46:00.210    [DEBUG][1]    Reader reports current time as 3444.547119

2010-12-27 09:46:00.318    [DEBUG][1]    Reader reports offset 3881636000

2010-12-27 09:46:00.319    [DEBUG][1]    Reader reports current time as 3444.547119

2010-12-27 09:46:00.428    [DEBUG][1]    Reader reports offset 3881824000

2010-12-27 09:46:00.431    [DEBUG][1]    Reader reports current time as 3445.468994

2010-12-27 09:46:00.540    [DEBUG][1]    Reader reports offset 3881918000

2010-12-27 09:46:00.542    [DEBUG][1]    Reader reports current time as 3445.468994

2010-12-27 09:46:00.650    [DEBUG][1]    Reader reports offset 3882012000

2010-12-27 09:46:00.651    [DEBUG][1]    Reader reports current time as 3445.468994

2010-12-27 09:46:00.758    [DEBUG][1]    Reader reports offset 3882106000

2010-12-27 09:46:00.759    [DEBUG][1]    Reader reports current time as 3445.468994

2010-12-27 09:46:00.867    [DEBUG][1]    Reader reports offset 3882200000

2010-12-27 09:46:00.868    [DEBUG][1]    Reader reports current time as 3445.468994

2010-12-27 09:46:00.975    [DEBUG][1]    Reader reports offset 3882388000

2010-12-27 09:46:00.977    [DEBUG][1]    Reader reports current time as 3445.468994

2010-12-27 09:46:01.084    [DEBUG][1]    Reader reports offset 3882482000

2010-12-27 09:46:01.087    [DEBUG][1]    Reader reports current time as 3445.468994

2010-12-27 09:46:01.195    [DEBUG][1]    Reader reports offset 3882576000

2010-12-27 09:46:01.199    [DEBUG][1]    Reader reports current time as 3445.468994

2010-12-27 09:46:01.306    [DEBUG][1]    Reader reports offset 3882764000

2010-12-27 09:46:01.309    [DEBUG][1]    Reader reports current time as 3446.391113

2010-12-27 09:46:01.416    [DEBUG][1]    Reader reports offset 3882858000

2010-12-27 09:46:01.419    [DEBUG][1]    Reader reports current time as 3446.391113

2010-12-27 09:46:01.516    [DEBUG][1]    Reader reports offset 3882952000

2010-12-27 09:46:01.519    [DEBUG][1]    Reader reports current time as 3446.391113

2010-12-27 09:46:01.638    [DEBUG][1]    Reader reports offset 3883046000

2010-12-27 09:46:01.641    [DEBUG][1]    Reader reports current time as 3446.391113

2010-12-27 09:46:01.738    [DEBUG][1]    Reader reports offset 3883234000

2010-12-27 09:46:01.741    [DEBUG][1]    Reader reports current time as 3446.391113

2010-12-27 09:46:01.848    [DEBUG][1]    Reader reports offset 3883328000

2010-12-27 09:46:01.851    [DEBUG][1]    Reader reports current time as 3446.391113

2010-12-27 09:46:01.959    [DEBUG][1]    Reader reports offset 3883422000

2010-12-27 09:46:01.963    [DEBUG][1]    Reader reports current time as 3446.391113

2010-12-27 09:46:02.071    [DEBUG][1]    Reader reports offset 3883610000

2010-12-27 09:46:02.074    [DEBUG][1]    Reader reports current time as 3446.391113

2010-12-27 09:46:02.181    [DEBUG][1]    Reader reports offset 3883704000

2010-12-27 09:46:02.184    [DEBUG][1]    Reader reports current time as 3447.281006

2010-12-27 09:46:02.282    [DEBUG][1]    Reader reports offset 3883798000

2010-12-27 09:46:02.285    [DEBUG][1]    Reader reports current time as 3447.281006

2010-12-27 09:46:02.395    [DEBUG][1]    Reader reports offset 3883892000

2010-12-27 09:46:02.401    [DEBUG][1]    Reader reports current time as 3447.281006

2010-12-27 09:46:02.508    [DEBUG][1]    Reader reports offset 3884080000

2010-12-27 09:46:02.511    [DEBUG][1]    Reader reports current time as 3447.281006

2010-12-27 09:46:02.619    [DEBUG][1]    Reader reports offset 3884174000

2010-12-27 09:46:02.622    [DEBUG][1]    Reader reports current time as 3447.281006

2010-12-27 09:46:02.731    [DEBUG][1]    Reader reports offset 3884362000

2010-12-27 09:46:02.735    [DEBUG][1]    Reader reports current time as 3447.281006

***sub*** · 2010-12-27, 06:28 PM

Here is one with the messages removed.

Possibly Related Threads…
Thread		Author	Replies	Views	Last Post
	tsreader4 skipping issues	dlindyds	63	14,905	2021-09-05, 03:23 AM Last Post: rizarefaldi
	Issue with Beast IPTV recording - Skipping + Doesn't record full show abrupt ending	russmehta01	3	3,085	2019-02-26, 09:20 PM Last Post: sub
	Npvr not skipping comskip break points	glb1945	3	1,454	2018-11-18, 01:51 AM Last Post: ga_mueller
	Blocky, skipping recordings on some channels at some times of day - OK rest of time	martinu	2	1,490	2018-06-29, 04:51 PM Last Post: martinu
	4.05 Skipping Issues on Recordings	z06racer66	51	14,355	2018-05-12, 03:53 AM Last Post: sub
	Skipping to the present ends playback	SNielson	0	874	2018-05-07, 12:47 AM Last Post: SNielson
	NextPVR Recordings Skipping parts of show	russmehta01	4	1,801	2018-04-09, 09:06 PM Last Post: NND
	Skipping DRM Channels on Scan	jcole998	8	2,379	2018-02-22, 02:25 PM Last Post: jcole998
	Goal: Watch Recordings in Progress on Apple TV with Commercial skipping	BrianGGG	4	1,670	2018-02-10, 02:27 PM Last Post: BrianGGG
	comskip pauses after skipping	kirschey	5	1,807	2016-07-21, 06:51 AM Last Post: johnsonx42