timing.info too short, timeline inaccurate

[johnsonx42]

I've been noticing problems with comskip jump points again. The first commercial break in each show would be pretty close, and they'd go more and more off as the show went on; it'd always jump out late, and jump back in late. I've been trying to compensate for it by adjusting <ComskipStartOffset> and <ComskipEndOffset> with limited satisfaction, because the error gets larger and larger so no one Offset setting can fix it.

However I recently watched some shows through XBMC Videos and the comskip jumps were so perfect they were like professional edits, and it got me thinking about why it was going wrong in NPVR again after it had been pretty good for awhile.

I watched American Beauty last night, a 1080i recording that was 2:30 beginning to end (recorded from 1:30am to 4:00am). I noticed thought that when I play it in NextPVR with it's embedded Timing.Info, the timeline shows 2:29:36 total, 24 seconds short of what it should have been. I expect the total to be only a second or two off, it seems odd it would be off by that much. Towards the end of the movie, the comskip jumps were skipping large portions of the scenes after the commercial, and I'd have to rewind back a bit to catch the whole scene.

I looked carefully at the very last skip point:
Where it jumped to: 2:20:02
Where it should have jumped: 2:19:40
That difference is about 22 seconds, which is very close to the discrepency between the Timing.Info duration and the correct duration. The .edl file shows the last jump should have been at 2:20:01.

So the question is, why is the Timing.Info producing a timeline that's ~24 seconds too short? The last entry in the Timing.Info is 8976344,10833832384, and the entire .ts file is 10,835,006,256 bytes, so the Timing.Info does appear to account for all of the file except for the final second of data. But the timestamps at the end of the file should be close to 9000000.

Timing.info and .edl file attached.

I've also attached an NPVR.log of the following actions:
Start playback of American Beauty.
Skip 139 minutes.
Let it play until it completes the last comskip jump (where it jumps to ~2:20:02)
skip back 30 seconds (3x10 short skip), let it play until it gets to where it should have jumped (~2:19:41), pause, exit playback.

(no, this is not unique to this movie. All my recordings are like this... this is just the one I chose to analyze)

[mvallevand]

It's similar to odd Timing.Info I have received from BrettB, look how little data there is at the beginning in those first 5 seconds. Try my writeTime utility to see if it does anything differently/

Martin

[sub]

I'm out for the next hour, but I'll take a look at this when I get back.

[sub]

I'm scratching my head about how this would be possible, but have attempted a couple of things in this patch. It'll write a final timing.info line when the stream is closed. It also uses a different, higher resolution, Windows API for getting the current time.

Can you check whether new (digital) recordings made with this patch still have this problem?

[johnsonx42]

ok, I'll put it in and see what happens. Right now I'm running Martin's writetime against the American Beauty recording. It's going to take awhile because I had to do it over the network, but I'll post it when it's done.

unfortunately there are continuous recordings running tonight until 11:30pm by which time I SHOULD have gone to bed, so I may not get a chance to put this in until tomorrow.

[johnsonx42]

here's the timing.info created by Martin's writeTime utility. As I expected, the timestamp at the end of the file is 8995820, about 20 seconds longer. Still a touch short, but much closer. Watching the recording with this timing.info, the final comskip jump is off by about 2 seconds. Close enough.

[johnsonx42]

initial results with the patch seem no better. My first test was a 30 minute show, and the timeline with the original Timing.Info shows 29:54. Regenerating the timing.info with writeTime produces a timeline of 29:59 (typo corrected). This is proportionally the same discrepancy that exists on the 2.5 hour American Beauty recording.

I do see that NPVR does now write a final timestamp as the file closes, exactly as writeTime does, so it shows the patch is present and working.

I've attached a zip with both the original (NPVR generated) and new (writeTime) timing files

and for reference, here's the NDigitalHost log of the recording:

Code:

2013-10-22 14:30:00.180    [INFO][5]    DigitalRecorder.StartStream(C:\Recordings\Who Wants to Be a Millionaire\Who Wants to Be a Millionaire_20131022_14301500.ts)
2013-10-22 14:30:00.180    [INFO][5]    Creating BDA graph
2013-10-22 14:30:00.220    [DEBUG][5]    Using tuner Hauppauge WinTV-7164 BDA ATSC/QAM Tuner (1)
2013-10-22 14:30:00.220    [INFO][5]                [d111520b-511c-49fa-846a165e7be3f3af]-70791033-00000000
2013-10-22 14:30:00.240    [DEBUG][5]    About to auto detect capture filter...
2013-10-22 14:30:00.250    [DEBUG][5]    dw1=70791033 vs 70791033
2013-10-22 14:30:00.250    [DEBUG][5]    Got capture filter: 'Hauppauge WinTV-7164 BDA Digital Capture'
2013-10-22 14:30:00.250    [INFO][5]    medium:     [d111520b-511c-49fa-846a165e7be3f3af]-70791033-00000000
2013-10-22 14:30:00.250    [DEBUG][5]    Added capture filter
2013-10-22 14:30:00.250    [DEBUG][5]    Connected Tuner to Capture
2013-10-22 14:30:00.250    [DEBUG][5]    Activating time machine
2013-10-22 14:30:00.250    [DEBUG][5]    Time machine activated...
2013-10-22 14:30:00.270    [DEBUG][5]    EIT collection disabled
2013-10-22 14:30:00.270    [DEBUG][5]    Graph filter list:
2013-10-22 14:30:00.270    [DEBUG][5]     - MPEG-2 Sections and Tables
2013-10-22 14:30:00.270    [DEBUG][5]     - BDA MPEG2 Transport Information Filter
2013-10-22 14:30:00.270    [DEBUG][5]     - MPEG-2 Demultiplexer
2013-10-22 14:30:00.270    [DEBUG][5]     - NPVR TS Mon
2013-10-22 14:30:00.270    [DEBUG][5]     - Capture
2013-10-22 14:30:00.270    [DEBUG][5]     - Tuner
2013-10-22 14:30:00.270    [DEBUG][5]     - Network Provider
2013-10-22 14:30:00.270    [INFO][5]    About to start BDA graph
2013-10-22 14:30:00.270    [DEBUG][5]    Starting graph...
2013-10-22 14:30:00.290    [DEBUG][5]    About to tune BDA graph:
<tuning>
  <type>QAM</type>
  <locator>
    <physical_channel>87</physical_channel>
  </locator>
  <service_id>301</service_id>
  <tsid>1</tsid>
  <service_type>1</service_type>
</tuning>

2013-10-22 14:30:00.290    [INFO][5]    Setting locator to BDA_MOD_256QAM

2013-10-22 14:30:00.290    [INFO][5]    Tuning to frequency 87
2013-10-22 14:30:00.300    [DEBUG][5]    About to try setting tuner modulation
2013-10-22 14:30:00.300    [DEBUG][5]    Got tuner output pin
2013-10-22 14:30:00.300    [DEBUG][5]    Got IKsPropertySet interface
2013-10-22 14:30:00.300    [DEBUG][5]    KSPROPSETID_BdaDigitalDemodulator is NOT supported!!!
2013-10-22 14:30:00.300    [ERROR][5]    PropSet Set() failed (80070492)
2013-10-22 14:30:00.300    [DEBUG][5]    Resetting metadata
2013-10-22 14:30:00.300    [DEBUG][5]    About to submit tuning request
2013-10-22 14:30:00.840    [DEBUG][5]    Resetting metadata
2013-10-22 14:30:00.840    [DEBUG][5]    whoosh whoosh
2013-10-22 14:30:00.840    [DEBUG][5]    Calling LockChannel()
2013-10-22 14:30:00.880    [DEBUG][5]    locked=1, present=1, strength=0, quality=100   (took 31ms to check)
2013-10-22 14:30:00.880    [DEBUG][5]    File size is 0
2013-10-22 14:30:00.880    [INFO][5]    DigitalRecorder.StartStream() allocated handle: 0x2
2013-10-22 14:30:00.880    [DEBUG][5]    Temp at 10/22/2013 2:30:10 PM
2013-10-22 15:00:00.514    [INFO][5]    DigitalRecorder.StopStream() handle: 2
2013-10-22 15:00:00.914    [INFO][5]    No more streams active. Stopping device.
2013-10-22 15:00:00.914    [DEBUG][5]    About to request async graph stop
2013-10-22 15:00:00.914    [DEBUG][8]    Graph stopping... (async)
2013-10-22 15:00:01.124    [DEBUG][8]    Graph reports state 'Stopped'
2013-10-22 15:00:01.124    [DEBUG][8]    Graph stopped (async)
2013-10-22 15:00:01.124    [DEBUG][5]    Async stop completed successfully
2013-10-22 15:00:01.124    [DEBUG][5]    Removing filter  MPEG-2 Sections and Tables
2013-10-22 15:00:01.124    [DEBUG][5]    Removing filter  BDA MPEG2 Transport Information Filter
2013-10-22 15:00:01.124    [DEBUG][5]    Removing filter  MPEG-2 Demultiplexer
2013-10-22 15:00:01.124    [DEBUG][5]    Removing filter  NPVR TS Mon
2013-10-22 15:00:01.124    [DEBUG][5]    Removing filter  Capture
2013-10-22 15:00:01.134    [DEBUG][5]    Removing filter  Tuner
2013-10-22 15:00:01.134    [DEBUG][5]    Removing filter  Network Provider

[johnsonx42]

Now a 1 hour test recording has completed, the timeline shows 59:48. It seems the generated timing.info is consistently 6 seconds short per 30 minutes of show.

I looked through all current recordings, and found that both digital and analog recordings have this problem.

I looked back through my older recordings, and found that anything recorded up to July 28th of this year does not have this problem. The next recording on August 5th, and all recordings after it, have the short timeline.

[sub]

initial results with the patch seem no better. My first test was a 30 minute show, and the timeline with the original Timing.Info shows 29:54. Regenerating the timing.info with writeTime produces a timeline of 29:29. This is proportionally the same discrepancy that exists on the 2.5 hour American Beauty recording.

Do you really see 29:29? or do you mean 29:59?

I can imagine it possibly being 5 seconds out in the duration, although I'd expect the difference to be a lot smaller than that. I definitely would not expect to see a difference like 29:29 vs 29:54, ie 25 seconds.

[johnsonx42]

Hmm... early august coincides exactly with building a new HTPC and installing 3.0.2 with all patches at the time. The late July recordings would have been done with 3.0.1 and the old PC. I wonder if this might actually be a hardware timer problem on the new board?