Skip Problem

[sub]

After much cutting lengths and trying - it appears that any file less than 4 Gigabytes is now being reported accurately - that's why I can't upload
Over 4Gb and the reported length is massively over estimated - 1 hour 33 mins reported as 17 hours on one cut - the old 4gb limit rearing its head? :eek:

Can you see if this fixes this problem with misreported duration on large files?

[mvallevand]

Sub, I am still baffled why I have always had good skips on the PC (and NMT) long or short. Here is a two hour > 4GB recording that is fine with the previous version of TSReader2 What is the actual problem that I am not having? Maybe I am missing something for my NMT client users.

Code:

long
012-03-06 17:25:20.042    [DEBUG][1]    User is trying to skip.
2012-03-06 17:25:20.042    [DEBUG][1]    Current position is: 3560.64038085938
2012-03-06 17:25:20.042    [DEBUG][1]    Asking for position: 7160.640625
2012-03-06 17:25:20.328    [DEBUG][1]    After skipping position reports as: 7160.94677734375

short
2012-03-06 17:25:12.897    [DEBUG][1]    User is trying to skip.
2012-03-06 17:25:12.897    [DEBUG][1]    Current position is: 3493.47290039063
2012-03-06 17:25:12.897    [DEBUG][1]    Asking for position: 3553.47290039063
2012-03-06 17:25:13.543    [DEBUG][1]    After skipping position reports as: 3554.17578125

Martin

[sub]

Sub, I am still baffled why I have always had good skips on the PC (and NMT) long or short. Here is a two hour > 4GB recording that is fine with the previous version of TSReader2 What is the actual problem that I am not having? Maybe I am missing something for my NMT client users.

Code:

long
012-03-06 17:25:20.042    [DEBUG][1]    User is trying to skip.
2012-03-06 17:25:20.042    [DEBUG][1]    Current position is: 3560.64038085938
2012-03-06 17:25:20.042    [DEBUG][1]    Asking for position: 7160.640625
2012-03-06 17:25:20.328    [DEBUG][1]    After skipping position reports as: 7160.94677734375

short
2012-03-06 17:25:12.897    [DEBUG][1]    User is trying to skip.
2012-03-06 17:25:12.897    [DEBUG][1]    Current position is: 3493.47290039063
2012-03-06 17:25:12.897    [DEBUG][1]    Asking for position: 3553.47290039063
2012-03-06 17:25:13.543    [DEBUG][1]    After skipping position reports as: 3554.17578125

The previous version of TSReader2 was fine if the timing.info was present. Lao Pan's problem was only occurring because he didnt have the timing.info and there was a overflow flaw when manually trying to determine the duration on large files manually.

[mvallevand]

The previous version of TSReader2 was fine if the timing.info was present. Lao Pan's problem was only occurring because he didnt have the timing.info and there was a overflow flaw when manually trying to determine the duration on large files manually.

Ok, thanks and even with this patch something is really messed up on the NMT now when Timing.Info is not present you seem to report "Video Duration: 76086.8899" as the duration a lot and I have to exit/resume to get it calculated correctly.

Actually that duration seems to be set from one file but carry over to another. many others are just reporting crazy durations.

Martin

[Lao Pan]

Patch installed - Time-line reporting all file lengths accurately both large and small, with timing info and more importantly without. (I've always assumed that after processing with videoredo, the time-line should not have the glitches etc. of the original .ts stream that requires the timing info)

Also in a few minutes of testing skipping speed has improved - maybe 1 second for sound + 1 second extra for video catchup max (probably less) also skip lengths seem within 2 seconds of what was called on the remote. Most excellent and may be of help for the Comskip users. (I gave up a couple of years ago - UK TV is deliberately Ad detection unfriendly)

Thanks Sub - Jobs a goodun - I think you should be awarded a *+

[johnsonx42]

While analyzing a recording and associated logs tonight, trying to figure out why NPVR and Comskip can't seem to agree about the timeline of my recordings, I discovered that NDigitalHost is taking 20 seconds PER STREAM to stop a recording graph.

Logs attached, but here's a highlight:

Code:

2012-03-06 18:30:00.092    [DEBUG][7]    allocating recording target filename: F:\Recordings\The Simpsons\The Simpsons_20120306_18301900.ts
2012-03-06 18:30:00.092    [DEBUG][7]    About to start recording (154497 on 1522): F:\Recordings\The Simpsons\The Simpsons_20120306_18301900.ts...
2012-03-06 18:30:00.092    [DEBUG][7]    Asking NDigitalHost to start: F:\Recordings\The Simpsons\The Simpsons_20120306_18301900.ts
2012-03-06 18:30:01.311    [DEBUG][7]    Temp at 3/6/2012 6:30:11 PM
2012-03-06 18:30:01.311    [DEBUG][7]    Started recording (154497:6:F:\Recordings\The Simpsons\The Simpsons_20120306_18301900.ts)
2012-03-06 18:30:01.374    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "F:\Recordings\The Simpsons\The Simpsons_20120306_18301900.ts" 11 154497 1522
2012-03-06 18:30:01.389    [DEBUG][7]     - deleting extra recording: F:\Recordings\The Simpsons\The Simpsons.S17E11.We're on the Road to D'Ohwhere.ts (3/3/2012 2:30:00 AM)
2012-03-06 18:30:01.553    [DEBUG][7]     -removing: F:\Recordings\The Simpsons\The Simpsons.S17E11.We're on the Road to D'Ohwhere.edl
2012-03-06 19:00:00.028    [DEBUG][7]    Stopping recording (154497 on 1522). Past end time of recording. 6
2012-03-06 19:00:00.083    [DEBUG][7]    StopStream
2012-03-06 19:00:20.606    [DEBUG][7]    No C:\Users\Public\NPVR\Scripts\PostProcessing.bat
2012-03-06 19:00:20.614    [DEBUG][7]    allocating recording target filename: F:\Recordings\How I Met Your Mother\How I Met Your Mother_20120306_19001930.ts
2012-03-06 19:00:20.614    [DEBUG][7]    About to start recording (154512 on 1522): F:\Recordings\How I Met Your Mother\How I Met Your Mother_20120306_19001930.ts...
2012-03-06 19:00:20.614    [DEBUG][7]    Asking NDigitalHost to start: F:\Recordings\How I Met Your Mother\How I Met Your Mother_20120306_19001930.ts
2012-03-06 19:00:21.793    [DEBUG][7]    Temp at 3/6/2012 7:00:31 PM

Note that NRecord waited 20 seconds to get a response to the StopStream request at 19:00:00.083, and started the next recording 20 seconds late. Also, maybe this is just cosmetic, but notice the last line: "Temp at 3/6/2012 7:00:31 PM"... why is the given time 10 seconds later than the actual time? All the "Temp at..." lines are like that, 10 seconds in the future. Maybe I just don't understand what those lines mean.

Here's the matching NDigitalHost log section:

Code:

2012-03-06 18:30:00.092    [INFO][5]    DigitalRecorder.StartStream(F:\Recordings\The Simpsons\The Simpsons_20120306_18301900.ts)
2012-03-06 18:30:00.092    [INFO][5]    Creating BDA graph
2012-03-06 18:30:00.131    [DEBUG][5]    Using tuner Hauppauge WinTV 885 BDA Tuner/Demod (1)
2012-03-06 18:30:00.155    [DEBUG][5]    About to auto detect capture filter
2012-03-06 18:30:00.155    [DEBUG][5]    Got capture filter: 'Hauppauge WinTV 885 TS Capture'
2012-03-06 18:30:00.155    [DEBUG][5]    Added capture filter
2012-03-06 18:30:00.155    [DEBUG][5]    Connected Tuner to Capture
2012-03-06 18:30:00.178    [DEBUG][5]    EIT collection disabled
2012-03-06 18:30:00.178    [DEBUG][5]    Graph filter list:
2012-03-06 18:30:00.178    [DEBUG][5]     - MPEG-2 Sections and Tables
2012-03-06 18:30:00.178    [DEBUG][5]     - BDA MPEG2 Transport Information Filter
2012-03-06 18:30:00.178    [DEBUG][5]     - MPEG-2 Demultiplexer
2012-03-06 18:30:00.178    [DEBUG][5]     - NPVR TS Mon
2012-03-06 18:30:00.178    [DEBUG][5]     - Capture
2012-03-06 18:30:00.178    [DEBUG][5]     - Tuner
2012-03-06 18:30:00.178    [DEBUG][5]     - Network Provider
2012-03-06 18:30:00.178    [INFO][5]    About to start BDA graph
2012-03-06 18:30:00.178    [DEBUG][5]    Starting graph...
2012-03-06 18:30:00.272    [DEBUG][5]    About to tune BDA graph:
<tuning>
  <type>ATSC</type>
  <locator>
    <physical_channel>13</physical_channel>
  </locator>
  <service_id>4</service_id>
  <tsid>301</tsid>
  <service_type>1</service_type>
</tuning>

2012-03-06 18:30:01.288    [DEBUG][5]    Calling LockChannel()
2012-03-06 18:30:01.303    [DEBUG][5]    locked=1, present=1, strength=-6000, quality=92   (took 15ms to check)
2012-03-06 18:30:01.303    [INFO][5]    DigitalRecorder.StartStream() allocated handle: 0x6
2012-03-06 18:30:01.303    [DEBUG][5]    Temp at 3/6/2012 6:30:11 PM
2012-03-06 19:00:00.083    [INFO][5]    DigitalRecorder.StopStream() handle: 6
2012-03-06 19:00:20.090    [INFO][5]    No more streams active. Stopping device.
2012-03-06 19:00:20.090    [DEBUG][5]    About to request async graph stop
2012-03-06 19:00:20.090    [DEBUG][11]    Graph stopping... (async)
2012-03-06 19:00:20.090    [DEBUG][11]    Graph reports state 'Stopped'
2012-03-06 19:00:20.090    [DEBUG][11]    Graph stopped (async)
2012-03-06 19:00:20.090    [DEBUG][5]    Async stop completed successfully
2012-03-06 19:00:20.090    [DEBUG][5]    Removing filter  MPEG-2 Sections and Tables
2012-03-06 19:00:20.090    [DEBUG][5]    Removing filter  BDA MPEG2 Transport Information Filter
2012-03-06 19:00:20.090    [DEBUG][5]    Removing filter  MPEG-2 Demultiplexer
2012-03-06 19:00:20.090    [DEBUG][5]    Removing filter  NPVR TS Mon
2012-03-06 19:00:20.098    [DEBUG][5]    Removing filter  Capture
2012-03-06 19:00:20.098    [DEBUG][5]    Removing filter  Tuner
2012-03-06 19:00:20.098    [DEBUG][5]    Removing filter  Network Provider
2012-03-06 19:00:20.614    [INFO][5]    DigitalRecorder.StartStream(F:\Recordings\How I Met Your Mother\How I Met Your Mother_20120306_19001930.ts)
2012-03-06 19:00:20.614    [INFO][5]    Creating BDA graph

That pretty much mirrors what NRecord's log showed - a 20 second delay between deciding to stop the graph and actually stopping it, but no other problem is apparent.
There were some instances tonight where I had 2 recordings on the same device, and each stream took 20 seconds to stop so that the following recordings started 40 seconds late.

[johnsonx42]

The above is definitely new with the skipping patches, which I first installed on 2/27 just after 10:00pm. I found NDigitalHost logs for immediately before and immediately after.

One of the last graph stops before the skipping patches:

Code:

2012-02-27 20:00:00.108    [INFO][5]    DigitalRecorder.StopStream() handle: 1F
2012-02-27 20:00:00.738    [INFO][5]    DigitalRecorder.StopStream() handle: 20
2012-02-27 20:00:00.738    [INFO][5]    No more streams active. Stopping device.
2012-02-27 20:00:00.738    [DEBUG][5]    About to request async graph stop
2012-02-27 20:00:00.740    [DEBUG][24]    Graph stopping... (async)
2012-02-27 20:00:00.745    [DEBUG][24]    Graph reports state 'Stopped'
2012-02-27 20:00:00.745    [DEBUG][24]    Graph stopped (async)
2012-02-27 20:00:00.745    [DEBUG][5]    Async stop completed successfully
2012-02-27 20:00:00.745    [DEBUG][5]    Removing filter  MPEG-2 Sections and Tables
2012-02-27 20:00:00.746    [DEBUG][5]    Removing filter  BDA MPEG2 Transport Information Filter
2012-02-27 20:00:00.746    [DEBUG][5]    Removing filter  MPEG-2 Demultiplexer
2012-02-27 20:00:00.746    [DEBUG][5]    Removing filter  NPVR TS Mon
2012-02-27 20:00:00.748    [DEBUG][5]    Removing filter  Capture
2012-02-27 20:00:00.749    [DEBUG][5]    Removing filter  Tuner
2012-02-27 20:00:00.750    [DEBUG][5]    Removing filter  Network Provider

(barely .65 seconds to stop two streams and stop the graph)

The very first graph stop after the initial skip patches:

Code:

2012-02-27 23:30:00.157    [INFO][16]    DigitalRecorder.StopStream() handle: 1
2012-02-27 23:30:20.173    [INFO][16]    No more streams active. Stopping device.
2012-02-27 23:30:20.175    [DEBUG][16]    About to request async graph stop
2012-02-27 23:30:20.183    [DEBUG][19]    Graph stopping... (async)
2012-02-27 23:30:20.190    [DEBUG][19]    Graph reports state 'Stopped'
2012-02-27 23:30:20.190    [DEBUG][19]    Graph stopped (async)
2012-02-27 23:30:20.190    [DEBUG][16]    Async stop completed successfully
2012-02-27 23:30:20.193    [DEBUG][16]    Removing filter  MPEG-2 Sections and Tables
2012-02-27 23:30:20.221    [DEBUG][16]    Removing filter  BDA MPEG2 Transport Information Filter
2012-02-27 23:30:20.235    [DEBUG][16]    Removing filter  MPEG-2 Demultiplexer
2012-02-27 23:30:20.258    [DEBUG][16]    Removing filter  NPVR TS Mon
2012-02-27 23:30:20.260    [DEBUG][16]    Removing filter  Capture
2012-02-27 23:30:20.261    [DEBUG][16]    Removing filter  Tuner
2012-02-27 23:30:20.271    [DEBUG][16]    Removing filter  Network Provider

(20 seconds to stop one stream)

[sub]

Johnsonx42, can you see if this gets rid of the 20 second delay you're seeing?

[sub]

Ok, thanks and even with this patch something is really messed up on the NMT now when Timing.Info is not present you seem to report "Video Duration: 76086.8899" as the duration a lot and I have to exit/resume to get it calculated correctly.

Actually that duration seems to be set from one file but carry over to another. many others are just reporting crazy durations.

Nothing should have changed on the NMT. It uses entirely separate code to report the duration, which looks at various things in the .ts file, and none of that code is changed.

[sub]

Ok, thanks and even with this patch something is really messed up on the NMT now when Timing.Info is not present you seem to report "Video Duration: 76086.8899" as the duration a lot and I have to exit/resume to get it calculated correctly.

If you can post some logs showing this, I'll see if I can work out why.