2022-01-02, 02:00 PM
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
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)
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:
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?
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?