Here's an Odd One - Invalid Phantom Tuning Requests!

[PRBUK]

Here's a really odd bug - or config error in my system (current version of NPvr on Windows 10)!

I am trying to understand why channel changes are slower than expected.  From the logs I can see an erroneous 'phantom' tuning request before the real one!

As a test, I tuned to three channels, each requiring a frequency change.  Each tuning request is preceeded by an attempt to tune to frequency 12556.  This frequency does not exist in my system.

The key information entries from the Logs - Attempting to Tune to "Channel 4 HD" on frequency 11126V

NPVR - NRECORD.Log

Code:

2022-01-02 12:53:23.952    [DEBUG][189]    Got request [xxx]: /service (channel.stream.start)
2022-01-02 12:53:23.952    [DEBUG][189]    method=channel.stream.start
2022-01-02 12:53:23.952    [DEBUG][189]    parameters:
2022-01-02 12:53:23.952    [DEBUG][189]       method: channel.stream.start
2022-01-02 12:53:23.952    [DEBUG][189]       channel_id: 8587
2022-01-02 12:53:23.952    [DEBUG][189]       sid: db55b7c3325049cd99b4b0f08ba6f801
2022-01-02 12:53:23.952    [DEBUG][189]       client_ip: xxx
2022-01-02 12:53:23.952    [DEBUG][189]       user_agent: Kodi/19.3 (Windows NT 10.0.19044.1415; Win64; x64) App_Bitness/64 Version/19.3-(19.3.0)-Git:20211024-49a04cd6a7
2022-01-02 12:53:23.952    [DEBUG][189]       host_callback: ...
2022-01-02 12:53:23.965    [DEBUG][189]    StartStream(8587:Channel 4 HD)
2022-01-02 12:53:23.965    [DEBUG][189]    looking for capture source
2022-01-02 12:53:23.965    [DEBUG][189]    checking: IPTV (http://...)
2022-01-02 12:53:23.965    [DEBUG][189]    enabled and present
2022-01-02 12:53:23.965    [DEBUG][189]    does not have channel
2022-01-02 12:53:23.965    [DEBUG][189]    checking: Digital Devices DVB-S2X Tuner 1 (#0)
2022-01-02 12:53:23.965    [DEBUG][189]    enabled and present
2022-01-02 12:53:23.965    [DEBUG][189]    has channel
2022-01-02 12:53:23.965    [DEBUG][189]    live tv is not possible
2022-01-02 12:53:23.965    [DEBUG][189]    checking: Digital Devices DVB-S2X Tuner 2 (#0)
2022-01-02 12:53:23.965    [DEBUG][189]    enabled and present
2022-01-02 12:53:23.966    [DEBUG][189]    has channel
2022-01-02 12:53:23.966    [DEBUG][189]    live tv is possible
2022-01-02 12:53:23.966    [DEBUG][189]    http://localhost:56977/stream/start?slipseconds=36000&target=LIVE%26C%3A%5CUsers%5CPublic%5CNPVR-Buffer%5Clive-Channel%204%20HD-14.ts
2022-01-02 12:53:23.966    [DEBUG][189]    body:
<tuning>
  <type>DVB-S</type>
  <locator>
    <frequency>11126</frequency>
    <polarity>V</polarity>
    <symbol_rate>22000</symbol_rate>
    <fec>56</fec>
    <diseqc_type>0</diseqc_type>
    <lnb>1</lnb>
    <lowosc>9750</lowosc>
    <highosc>10600</highosc>
    <switch>11700</switch>
    <modulation>QPSK</modulation>
  </locator>
  <service_id>21200</service_id>
  <tsid>2068</tsid>
  <onid>2</onid>
  <service_type>25</service_type>
  <provider>BSkyB</provider>
</tuning>

{{snip}}

2022-01-02 12:53:28.106    [DEBUG][189]    <stream>
  <handle>3</handle>
  <reason></reason>
</stream>

2022-01-02 12:53:28.106    [DEBUG][189]    Live TV handle: 0x160003
2022-01-02 12:53:28.106    [DEBUG][189]    Started live stream for timeshift
2022-01-02 12:53:28.106    [DEBUG][189]    RollingFile.Open(C:\Users\Public\NPVR-Buffer\live-Channel 4 HD-14.ts) ..

So the request was issued at 12:53:23.9 and the stream started at 12:53:28.1

Looking next at the Npvr Device Log (device-Digital Devices DVB-S2X Tuner 2-1.log)

Code:

2022-01-02 12:53:23.967    [INFO][4]    Got POST request: /stream/start?slipseconds=36000&target=LIVE%26C%3A%5CUsers%5CPublic%5CNPVR-Buffer%5Clive-Channel%204%20HD-14.ts
2022-01-02 12:53:23.967    [DEBUG][4]    Starting Stream: LIVE&C:\Users\Public\NPVR-Buffer\live-Channel 4 HD-14.ts
2022-01-02 12:53:23.967    [DEBUG][4]    SlipSeconds: 36000
2022-01-02 12:53:23.967    [DEBUG][4]    Tuning:
<tuning>
  <type>DVB-S</type>
  <locator>
    <frequency>11126</frequency>
    <polarity>V</polarity>
    <symbol_rate>22000</symbol_rate>
    <fec>56</fec>
    <diseqc_type>0</diseqc_type>
    <lnb>1</lnb>
    <lowosc>9750</lowosc>
    <highosc>10600</highosc>
    <switch>11700</switch>
    <modulation>QPSK</modulation>
  </locator>
  <service_id>21200</service_id>
  <tsid>2068</tsid>
  <onid>2</onid>
  <service_type>25</service_type>
  <provider>BSkyB</provider>
</tuning>
2022-01-02 12:53:23.967    [DEBUG][4]    StartStream(): LIVE&C:\Users\Public\NPVR-Buffer\live-Channel 4 HD-14.ts
2022-01-02 12:53:23.976    [DEBUG][4]    CreateTuneRequestDVBS@1
2022-01-02 12:53:23.983    [DEBUG][4]    CreateTuneRequestDVBS@2
2022-01-02 12:53:23.983    [DEBUG][4]    CreateTuneRequestDVBS@3
2022-01-02 12:53:23.983    [DEBUG][4]    CreateTuneRequestDVBS@4
2022-01-02 12:53:23.983    [DEBUG][4]    CreateTuneRequestDVBS@ found tuning space
2022-01-02 12:53:23.983    [DEBUG][4]    CreateTuneRequest successful
2022-01-02 12:53:23.983    [DEBUG][4]    CreateTuneRequestDVBS@exit
2022-01-02 12:53:23.983    [DEBUG][4]    About to submit tuning request
2022-01-02 12:53:23.983    [DEBUG][4]    tuning request submitted (12556000)
2022-01-02 12:53:23.989    [DEBUG][4]    Using tuner: Digital Devices DVB-S2X Tuner 2 (1)
2022-01-02 12:53:23.989    [DEBUG][4]    About to connect...
{{snip}}
2022-01-02 12:53:23.997    [DEBUG][4]    Starting graph...
2022-01-02 12:53:23.998    [DEBUG][4]    Calling LockChannel()
2022-01-02 12:53:27.840    [DEBUG][4]    locked=0, present=0, strength=26970, quality=0   (took 3843ms to check)
2022-01-02 12:53:27.840    [DEBUG][4]    BDA_MOD_NBC_QPSK modulation..
2022-01-02 12:53:27.840    [DEBUG][4]    CreateTuneRequestDVBS@1
2022-01-02 12:53:27.847    [DEBUG][4]    CreateTuneRequestDVBS@2
2022-01-02 12:53:27.848    [DEBUG][4]    CreateTuneRequestDVBS@3
2022-01-02 12:53:27.848    [DEBUG][4]    CreateTuneRequestDVBS@4
2022-01-02 12:53:27.848    [DEBUG][4]    CreateTuneRequestDVBS@ found tuning space
2022-01-02 12:53:27.848    [DEBUG][4]    CreateTuneRequest successful
2022-01-02 12:53:27.848    [DEBUG][4]    CreateTuneRequestDVBS@exit
2022-01-02 12:53:27.848    [DEBUG][4]    About to submit tuning request
2022-01-02 12:53:27.848    [DEBUG][4]    tuning request submitted (11126000)
2022-01-02 12:53:27.862    [DEBUG][4]    Calling LockChannel()
2022-01-02 12:53:28.105    [DEBUG][4]    locked=1, present=1, strength=30250, quality=100   (took 250ms to check)
2022-01-02 12:53:28.105    [DEBUG][4]    StartStream()@exit handle=3
2022-01-02 12:53:28.105    [DEBUG][4]    StartStream succeded. Handle: 3

At 12:53:23.967, the tuning request is  received with the correct tuning parameters.  At 12:53:23.983 is the line "tuning request submitted (12556000)" - the phantom tuning request.  At 12:53:27.840, this request fails after 3843ms and at 12:53:27.848 there is a second (correct) tuning request  "tuning request submitted (11126000)", which locks 250ms later.

These two requests are visible in the Digital Devices Log:

Code:

02/01/2022 12:53:23 DDTuner Device 260:b0000: Acquire Tuner 2
02/01/2022 12:53:23 DDTuner Device 260:b0000: Start Tuner 2
02/01/2022 12:53:27 DDTuner Device 260:b0000: Tune failure Tuner 2
     Version     = 6
     Error       =       00000000
     Standard    =         DVB-S2
     Frequency   =     12,556,000
     Multiplier  =          1,000
     SymbolRate  =     22,500,000
     L-Frequency =  1,256,000,000
     Polarity    =              2
     LNBSource   =           FFFF
     LockStatus  =              1
     Strength    =           73.0 dBµV
     S/N         =            0.0 dB
     Quality     =              0%

02/01/2022 12:53:28 DDTuner Device 260:b0000: Tune success Tuner 2
     Version     = 6
     Error       =       00000000
     Standard    =         DVB-S2
     Frequency   =     11,126,000
     Multiplier  =          1,000
     SymbolRate  =     22,000,000
     L-Frequency =  1,376,000,000
     Polarity    =              2
     LNBSource   =           FFFF
     LockStatus  =              6
     Strength    =           69.7 dBµV
     S/N         =           18.3 dB
     Quality     =            100%
     Offset      =        156,708

I went on to change channels three times (each required a new frequency) and the same tuner was used for each.  The device logs show that each correct request was prefixed by an erroneous "tuning request submitted (12556000)"

Hence each channel change is delayed by 4 seconds!!


Ideas Anyone?  Anyone else seeing the same?

[sub]

The device logs show that each correct request was prefixed by an erroneous "tuning request submitted (12556000)"

This is normal. It's a quirk of the BDA directshow components, that I need to submit tuning request to the Tuning Network Provider, so it knows the type of requests that the Network Provider will be used for, before I can continue hooking up the components. It's not really tuning it, and the delay is actually hooking up the components before use.

If you tick the 'Keep digital tuners primed' does help with your slow channel changes? With this tick, it only has to hookup the components once, and after that it's left hooked up and ready to run.

[PRBUK]

Thanks for the prompt reply!  I will change the 'keep primed' setting and retry.

In my testing I see this 'extra' request even when changing channels on an active tuner (as opposed to starting a tuner).

Any chance of a parameter so we can set the frequency for this extra request?  If it were a valid frequency the request would be processed in 250ms rather than 4000ms?

Is there another way  - such as query the tuners at startup and the results stored?

[sub]

Thanks for the prompt reply!  I will change the 'keep primed' setting and retry.

In my testing I see this 'extra' request even when changing channels on an active tuner (as opposed to starting a tuner).

Are you viewing in NextPVR.exe, or something else? Viewing in something else may be stopping/starting between channel changes.

Any chance of a parameter so we can set the frequency for this extra request?  If it were a valid frequency the request would be processed in 250ms rather than 4000ms?

It's actually not hooked up to your tuner at all at this early stage, so it's not going to matter. It hasn't even started looking for the components provided by your tuner.

Try the 'keep primed' before we bother looking at other options. With this enabled, you'll only get this extra construction time once per run of NextPVR.

[PRBUK]

I am using Kodi.

The Digital Devices log above shows that the card did try and failed to tune to 12556...

I should have realised that a parameter for a valid frequency was a dumb suggestion - you have a valid frequency - the one being tuned! 

Will test the effect of keeping primed...

[mvallevand]

There is a hit to timeshifting in Kodi, if you really want to surf, turn it off. Also make sure the pre-buffering is set as low as you can. Some user can work with 0, but I have mine at 1.

Martin

[sub]

The Digital Devices log above shows that the card did try and failed to tune to 12556...

Ok, maybe it does flow through to the tuner when it's connected to soon after. I'll make a change to ensure the dummy request used during construction matches the frequency it'll tune to.

[PRBUK]

A quick test - and yes - keeping the tuners primed has eliminated the 'phantom request' when changing channels from Kodi (so far only used one of the tuners, but I am sure it will be the same for the others!)

Thanks for the advice!

[PRBUK]

There is a hit to timeshifting in Kodi, if you really want to surf, turn it off.  Also make sure the pre-buffering is set as low as you can.  Some user can work with 0, but I have mine at 1.

Martin

Thanks Martin - yes I understand that.  I had eliminated Kodi as the source of most of the delay and could see the relevant delay in the NextPVR logs. I only mentioned Kodi as Sub was suggesting a connection to the way that the channel change request was hitting Npvr as potentially relevant

[PRBUK]

I see that the tuning process was modified in the latest release (5.2.4.220103).  I retested without the primed tuners. 

The first call to the tuner (previously using the 'phantom' frequency) has reduced from around 3850ms to 800ms (now using the 'target' frequency) and the second call to the tuner has reduced from around 250ms to 0ms (as the tuner is presumably already tuned).

So this has shortened the tuning process where the stream is stopped and started (as opposed to retuning the active stream) by over 3 seconds (from over 4 seconds to less than 1 second).  Hopefully other users have also seen/noticed  the difference!

Thank You!