Improvements to recording statistics

I started a recording from the web UI guide, then cancelled it after 13 seconds which gave sigerr=14%

2020/07/11 14:10:00.156120 [DVR] Starting job 1594498800-ch768 The Hunger Games (2012) on ch=[768]
2020/07/11 14:10:00.604485 [TNR] Opened connection to 1323AADB/0 for ch768 FRFMHDP
2020/07/11 14:10:00.604937 [DVR] Recording for job 1594498800-ch768 from 1323AADB ch768 into "Movies/The Hunger Games (2012) 2020-07-11-1410.mpg" for 2h24m59.843726297s
2020/07/11 14:10:00.661024 [IDX] Generating video index for job 1594498800-ch768
2020/07/11 14:10:13.688196 [SNR] Statistics for "Movies/The Hunger Games (2012) 2020-07-11-1410.mpg": ss=94% snq=100% seq=100% bps=3315890,2995968-5378304 pps=318,291-511 sigerr=14%
2020/07/11 14:10:13.688793 [TNR] Closed connection to 1323AADB/0 for ch768 FRFMHDP
2020/07/11 14:10:13.688877 [DVR] Job cancelled: 1594498800-ch768 The Hunger Games (2012)

I then started watching the same channel in the web browser, then selected to record it again for 13 seconds from another tab in the browser and no sigerr on this recording.

2020/07/11 14:15:02.850122 [TNR] Opened connection to 1323AADB/0 for ch768 FRFMHDP
2020/07/11 14:15:02.850975 [HLS] Starting transcoder for channel 768 from 192.168.1.2 (encoder=remux, resolution=, deinterlacer=, bitrate=0)
2020/07/11 14:15:04.688057 [HLS] Probed live stream in 1.836855233s: h264 1280x720 progressive 2336330bps
2020/07/11 14:15:06.364755 [HLS] Session ch768-dANY-ip192.168.1.2 started in 4.062013577s
2020/07/11 14:15:06.366021 [ENC] Starting encoder for ch768 in /volume1/arkives/ChannelsDVR/Streaming/ch768-dANY-ip192.168.1.2-609139177/encoder-1-127564852 at 1 (2.200378) (encoder=remux, resolution=720, deinterlacer=hardware, bitrate=2336 segment_size=0.01)
2020/07/11 14:15:06.402860 [HLS] ffmpeg: ch768-dANY-ip192.168.1.2-1-copy-aac--2336-128-720-0-0--hardware-false-false-0.01:  [h264 @ 0x3b5ae80] mmco: unref short failure
2020/07/11 14:15:06.408334 [HLS] ffmpeg: ch768-dANY-ip192.168.1.2-1-copy-aac--2336-128-720-0-0--hardware-false-false-0.01:  [h264 @ 0x3b5ae80] Increasing reorder buffer to 2
2020/07/11 14:15:06.413022 [HLS] ffmpeg: ch768-dANY-ip192.168.1.2-1-copy-aac--2336-128-720-0-0--hardware-false-false-0.01:  [h264 @ 0x3b5ae80] Increasing reorder buffer to 3
2020/07/11 14:15:24.087853 [DVR] Starting job 1594498800-ch768 The Hunger Games (2012) on ch=[768]
2020/07/11 14:15:24.088059 [TNR] Sharing existing connection to 1323AADB/0 for ch768 FRFMHDP (clients=2, len=0)
2020/07/11 14:15:24.088308 [DVR] Recording for job 1594498800-ch768 from 1323AADB ch768 into "Movies/The Hunger Games (2012) 2020-07-11-1415.mpg" for 2h19m35.912049404s
2020/07/11 14:15:24.114150 [IDX] Generating video index for job 1594498800-ch768
2020/07/11 14:15:37.142577 [SNR] Statistics for "Movies/The Hunger Games (2012) 2020-07-11-1415.mpg": ss=94% snq=100% seq=100% bps=3966578,2168768-4746624 pps=376,146-454
2020/07/11 14:15:37.143088 [DVR] Job cancelled: 1594498800-ch768 The Hunger Games (2012)
1 Like

Aren't the stats displayed in the Activity section? You can open a second browser window to display that page to see the stats.

(Yes, it's annoying as it involves multiple windows, and could be added to the caption that displays the transcoding status. But, the info is available.)

I'm pretty sure (can't remember where I saw it) that Channels DVR polls an HDHR once per second for the debug info to gather stats on the tuner session. That would be a lot of info to display in addition to what they already do and may confuse some people. Think it's for logging only and not for general stat info.

We mark a given poll interval as bad if the transport error counter incremented since last time OR if the seq value was less than 100%.

Our final percentages are the number of polling intervals that were good vs not good.

Trying to understand.
How often are your poll intervals?

According to the logs the SEQ never went below 100%, so I'm assuming it's the TE counter, unless the logs don't show a dip in SEQ you saw while polling.

It appears from my experiment you quoted you're polling too soon while the tuner is just locking the channel and a few te errors could be expected.

14% of 13 seconds is 1.82 seconds, so if you're polling every second it doesn't make sense that 1.82 poll intervals were bad.

It polls every 2 seconds, starting 1 second after the DVR has connected to the HDHR.

I have found an issue with how I was calculating the minimum value if the initial values we fetched were 0. In the latest DVR pre-release I've improved the calculation to properly reflect the minimum value received. Let me know if the logs make more sense now.

1 Like

Still looks the same with v2020.07.16.0307
Now I know the poll intervals I did 10 second recordings to capture your first 5 polls at 1,3,5,7 and 9 seconds.
Shows sigerr=20% so still think it's the first poll you do.
Any way to surface the te count you look at to see where it's at each polling?

2020/07/16 15:59:20.177064 [DVR] Starting job 1594936800-ch754 Iron Resurrection on ch=[754]
2020/07/16 15:59:20.705205 [TNR] Opened connection to 1323AADB/0 for ch754 MTHD
2020/07/16 15:59:20.705606 [DVR] Recording for job 1594936800-ch754 from 1323AADB ch754 into "TV/Iron Resurrection/Iron Resurrection S04E02 2020-02-12 C10 Again 2020-07-16-1559.mpg" for 39.822825769s
2020/07/16 15:59:20.741940 [DVR] Refreshing metadata for Iron Resurrection (12661909)
2020/07/16 15:59:21.135622 [IDX] Generating video index for job 1594936800-ch754
2020/07/16 15:59:30.082051 [SNR] Statistics for "TV/Iron Resurrection/Iron Resurrection S04E02 2020-02-12 C10 Again 2020-07-16-1559.mpg": ss=94% snq=100% seq=80%,0%-100% bps=2936710,0-4250304 pps=283,0-407 sigerr=20%
2020/07/16 15:59:30.082639 [TNR] Closed connection to 1323AADB/0 for ch754 MTHD
2020/07/16 15:59:30.082683 [DVR] Job cancelled: 1594936800-ch754 Iron Resurrection

Just noticed this after posting
seq=80%,0%-100%

Don't know what to make of it.
Tried again on another channel, same thing

2020/07/16 16:32:17.066390 [DVR] Starting job 1594940400-ch750 Homestead Rescue on ch=[750]
2020/07/16 16:32:17.608912 [TNR] Opened connection to 1323AADB/0 for ch750 DSCHDP
2020/07/16 16:32:17.609205 [DVR] Recording for job 1594940400-ch750 from 1323AADB ch750 into "TV/Homestead Rescue/Homestead Rescue S02E02 2017-06-21 Honey I Torched the Homestead 2020-07-16-1632.mpg" for 27m42.933501183s
2020/07/16 16:32:17.645993 [IDX] Generating video index for job 1594940400-ch750
2020/07/16 16:32:26.707980 [SNR] Statistics for "TV/Homestead Rescue/Homestead Rescue S02E02 2017-06-21 Honey I Torched the Homestead 2020-07-16-1632.mpg": ss=97% snq=99%-100% seq=80%,0%-100% bps=3109369,0-4891008 pps=298,0-466 sigerr=20%
2020/07/16 16:32:26.708503 [TNR] Closed connection to 1323AADB/0 for ch750 DSCHDP
2020/07/16 16:32:26.708545 [DVR] Job cancelled: 1594940400-ch750 Homestead Rescue

What are you seeing for full recordings with the latest build?

If it was only this first polling interval that was the problem, it would only be 0.05% of the polling intervals that had an issue with a 60 minute recording, so it would round down to 0 in the display. If you're seeing 5%, it means that there is more polling that is showing errors beyond the first one.

Before and after updating to v2020.07.16.0307, no errors. If there's a newer pre-release you wanted me to try, what version is it?

I understand that. Any recording after I updated, 15 secs or longer, shows no sigerr.

I only brought this up because I noticed sigerr on short live viewings and tested with recordings.

Just did a 8.94 sec test recording and got sigerr=25%, so one of 4 (1,3,5,7 sec) polls reported bad, whatever that was.

2020/07/17 17:41:05.082260 [DVR] Starting job 1595030400-ch757 Life Below Zero on ch=[757]
2020/07/17 17:41:05.558148 [TNR] Opened connection to 1323AADB/0 for ch757 NGCPHD
2020/07/17 17:41:05.558580 [DVR] Recording for job 1595030400-ch757 from 1323AADB ch757 into "TV/Life Below Zero/Life Below Zero S12E02 2019-01-08 The Nightmare 2020-07-17-1741.mpg" for 18m54.917592632s
2020/07/17 17:41:05.608757 [DVR] Refreshing metadata for Life Below Zero (9895118)
2020/07/17 17:41:06.101701 [IDX] Generating video index for job 1595030400-ch757
2020/07/17 17:41:14.495190 [SNR] Statistics for "TV/Life Below Zero/Life Below Zero S12E02 2019-01-08 The Nightmare 2020-07-17-1741.mpg": ss=97% snq=100% seq=75%,0%-100% bps=3070792,0-4211200 pps=294,0-404 sigerr=25%
2020/07/17 17:41:14.495878 [TNR] Closed connection to 1323AADB/0 for ch757 NGCPHD
2020/07/17 17:41:14.495927 [DVR] Job cancelled: 1595030400-ch757 Life Below Zero

Would really like to see the debug SEQ and te that you're collecting because I think my HDHR Prime is working fine and no issues with my cable provider.

I've done a few short 10 second plays of channels on my Prime and I'm not seeing the behavior you're describing, so it does seem like something is different about your configuration.

Have you restarted your Prime recently? It could just be something strange going on with it...

I had been testing using recordings.
Now if I just play live for 10 secs in the web UI, I don't get any sigerr or SEQ dips in the logs.
?
I'll try more channels today, both recording and live play.

Viewed 5 channels live in the web UI for 10 seconds each, all show seq=80%,0%-100% and sigerr=20%

2020/07/18 12:35:20.584383 [SNR] Statistics for ch706 KVIEDT: ss=96%-97% snq=100% seq=80%,0%-100% bps=3441152,0-4351072 pps=332,0-420 sigerr=20%
2020/07/18 12:37:00.410850 [SNR] Statistics for ch750 DSCHDP: ss=97%     snq=100% seq=80%,0%-100% bps=3314515,0-5173760 pps=317,0-492 sigerr=20%
2020/07/18 12:37:50.521490 [SNR] Statistics for ch754 MTHD:   ss=95%     snq=100% seq=80%,0%-100% bps=3136742,0-4131488 pps=301,0-395 sigerr=20%
2020/07/18 12:38:50.602717 [SNR] Statistics for ch756 SCIHD:  ss=96%-97% snq=100% seq=80%,0%-100% bps=3288646,0-4891008 pps=315,0-468 sigerr=20%
2020/07/18 12:39:30.493219 [SNR] Statistics for ch757 NGCPHD: ss=97%     snq=100% seq=80%,0%-100% bps=2950547,0-3938976 pps=284,0-380 sigerr=20%

HDHR Prime was last rebooted six weeks ago on June 5

19700101-00:00:00 System: reset reason = firmware upgrade
20200605-22:05:13 CableCARD: time changed from Thu Jan 01 00:00:23 1970 to Fri Jun 05 22:05:13 2020

Rebooted HDHR Prime and tried again

19700101-00:00:00 System: reset reason = power on
20200718-19:53:24 CableCARD: time changed from Thu Jan 01 00:00:52 1970 to Sat Jul 18 19:53:24 2020
2020/07/18 12:54:40.578729 [SNR] Statistics for ch706 KVIEDT: ss=97% snq=100% seq=80%,0%-100% bps=3177049,0-4027712 pps=308,0-389 sigerr=20%
2020/07/18 12:55:00.690418 [SNR] Statistics for ch750 DSCHDP: ss=97% snq=100% seq=80%,0%-100% bps=2951449,0-4126976 pps=283,0-395 sigerr=20%
2020/07/18 12:55:20.667954 [SNR] Statistics for ch754 MTHD:   ss=94% snq=100% seq=80%,0%-100% bps=3296768,0-4869952 pps=317,0-464 sigerr=20%
2020/07/18 12:55:40.665508 [SNR] Statistics for ch756 SCIHD:  ss=97% snq=100% seq=80%,0%-100% bps=2675616,0-3376480 pps=259,0-327 sigerr=20%
2020/07/18 12:56:00.941968 [SNR] Statistics for ch757 NGCPHD: ss=97% snq=100% seq=80%,0%-100% bps=2974009,0-4704512 pps=285,0-450 sigerr=20%

Same results.

Guess I'll quit playing with it as I don't get errors with any of my normal 30+ minute recordings.
I just tried recording the same 5 channels for 8-10 minutes each and I still see some seq=99%,0%-100%

Tuner1 08:16 recording seq=100%
2020/07/18 13:30:00.553441 [SNR] Statistics for "TV/Kevin Belton's New Orleans Celebrations/Kevin Belton's New Orleans Celebrations S01E10 2019-06-11 Catfish Fest 2020-07-18-1321.mpg": ss=96%-97% snq=100% seq=100% bps=3968485,628672-5062464 pps=384,60-485

Tuner2 10:05 recording seq=100%
2020/07/18 13:31:55.148027 [SNR] Statistics for "TV/Mysteries of the Abandoned/Mysteries of the Abandoned S02E05 2018-04-17 Conspiracy on Devils Mountain 2020-07-18-1321.mpg": ss=96%-97% snq=100% seq=100% bps=3811001,366976-5512160 pps=365,29-524

Tuner3 10:00 recording seq=99%,0%-100%
2020/07/18 13:31:56.326844 [SNR] Statistics for "TV/Bitchin' Rides/Bitchin' Rides S04E14 2017-12-26 The Future Is Now 2020-07-18-1321.mpg": ss=94%-95% snq=100% seq=99%,0%-100% bps=3663844,0-5104576 pps=353,0-485

Tuner1 10:04 recording seq=99%,0%-100%
2020/07/18 13:42:12.599254 [SNR] Statistics for "TV/MythBusters/MythBusters S05E22 2007-11-21 Shooting Fish in a Barrel 2020-07-18-1332.mpg": ss=95%-96% snq=100% seq=99%,0%-100% bps=3482234,0-5415904 pps=336,0-514

Tuner2 10:03 recording seq=100%
2020/07/18 13:42:18.033631 [SNR] Statistics for "TV/Food Factory/Food Factory S06E00 2020-06-25 Earl Grey Tea  Olives 2020-07-18-1332.mpg": ss=96%-97% snq=100% seq=100% bps=3916031,236128-5254976 pps=377,2-500

I appreciate you raising this. It helped me find a bug in how I was handling getting an initial reading of 0 that caused the numbers to not match up correctly.

It is certainly weird that it's happening like this. I'm not sure why you're seeing it and I'm not. We wait to start polling until after we have established the connection with the HDHR, and so my understanding is that it has already tuned by that point.

Don't know if this helps, but i ran a simple script that;
tunes tuner2 to a virtual channel using hdhomerun_config" FFFFFFFF set /tuner2/vchannel 706
delays a second using ping -n 2 127.0.0.1
gets debug info from tuner2 a second after tuning
delays a second using ping -n 2 127.0.0.1
gets debug info from tuner2 two seconds after tuning
delays a second using ping -n 2 127.0.0.1
gets debug info from tuner2 three seconds after tuning
...
Here's the first three seconds of output, note seq=0 at one second after tune, but 100 after that

tuner2 vCh:706 at 22:35:53.80
delay a second at 22:35:53.86
get debug info at 22:35:54.87

tun: ch=qam:129000000 lock=qam256:129000000 ss=96 snq=100 seq=0 dbg=-442/4191
dev: bps=0 resync=0 overflow=0
cc: bps=3439648 resync=1 overflow=0
ts: bps=0 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 22:35:54.92
get debug info at 22:35:55.93

tun: ch=qam:129000000 lock=qam256:129000000 ss=97 snq=100 seq=100 dbg=-440/4191
dev: bps=18590944 resync=0 overflow=0
cc: bps=38810720 resync=1 overflow=0
ts: bps=1913088 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 22:35:55.99
get debug info at 22:35:57.01

tun: ch=qam:129000000 lock=qam256:129000000 ss=97 snq=100 seq=100 dbg=-440/4181
dev: bps=38810720 resync=0 overflow=0
cc: bps=38810720 resync=1 overflow=0
ts: bps=4099904 te=0 crc=0
net: pps=0 err=0 stop=0

EDIT: was using a ping command for delay and replaced it with the timeout command for more accurate one second delay. Well scratch that as timeout command isn't accurate, nor is sleep command. Went back to ping -n 2 localhost for more accurate 1 second delay.

Here's the windows commands I used in a .cmd file

REM tune to channel 706
echo tuner2 vCh:706 at %TIME% >testdebug.txt
hdhomerun_config FFFFFFFF set /tuner2/vchannel 706
echo delay a second at %TIME% >>testdebug.txt
ping -n 2 127.0.0.1
echo get debug info at %TIME% >>testdebug.txt
echo. >>testdebug.txt
hdhomerun_config FFFFFFFF get /tuner2/debug >>testdebug.txt
echo delay a second at %TIME% >>testdebug.txt
ping -n 2 127.0.0.1
echo get debug info at %TIME% >>testdebug.txt
echo. >>testdebug.txt
hdhomerun_config FFFFFFFF get /tuner2/debug >>testdebug.txt
echo delay a second at %TIME% >>testdebug.txt
ping -n 2 127.0.0.1
echo get debug info at %TIME% >>testdebug.txt
echo. >>testdebug.txt
hdhomerun_config FFFFFFFF get /tuner2/debug >>testdebug.txt
echo release tuner2 at %TIME% >>testdebug.txt
hdhomerun_config FFFFFFFF set /tuner2/vchannel none
echo get debug info at %TIME% >>testdebug.txt
echo. >>testdebug.txt
hdhomerun_config FFFFFFFF get /tuner2/debug >>testdebug.txt
EXIT

That is fascinating that the dev and ts both show bps=0... It seems like it may be taking longer to get the PMT on this channel for you than it is from my cable provider.

I was thinking the same thing, so I added a frequency tune after the vChannel tune and same result

tuner2 vCh:703, Frq:117MHz at 11:02:38.82 (hdhomerun_config FFFFFFFF set /tuner2/vchannel 703)
delay a second at 11:02:38.88 
get debug info at 11:02:39.93 
 
tun: ch=qam:117000000 lock=qam256:117000000 ss=98 snq=100 seq=0 dbg=-438/3803
dev: bps=0 resync=0 overflow=0
cc:  bps=2702688 resync=1 overflow=0
ts:  bps=0 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 11:02:39.99 
get debug info at 11:02:41.02 
 
tun: ch=qam:117000000 lock=qam256:117000000 ss=98 snq=100 seq=100 dbg=-438/3813
dev: bps=17697568 resync=0 overflow=0
cc:  bps=38810720 resync=1 overflow=0
ts:  bps=3289248 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 11:02:41.07 
get debug info at 11:02:42.10 
 
tun: ch=qam:117000000 lock=qam256:117000000 ss=98 snq=100 seq=100 dbg=-437/3813
dev: bps=38810720 resync=0 overflow=0
cc:  bps=38810720 resync=1 overflow=0
ts:  bps=6501792 te=0 crc=0
net: pps=0 err=0 stop=0

release tuner2 at 11:02:42.14 
get debug info at 11:02:42.19 
 
tun: ch=none lock=none ss=0 snq=0 seq=0 dbg=0
dev: bps=0 resync=0 overflow=0
cc:  bps=38810720 resync=1 overflow=0
ts:  bps=0 te=0 crc=0
net: pps=0 err=0 stop=0

tuner2 Frq:351MHz at 11:02:42.27 (hdhomerun_config FFFFFFFF set /tuner2/channel auto:351000000)
delay a second at 11:02:42.33 
get debug info at 11:02:43.39 
 
tun: ch=auto:351000000 lock=qam256:351000000 ss=99 snq=100 seq=0 dbg=-440/11348
dev: bps=0 resync=0 overflow=0
cc:  bps=23000672 resync=1 overflow=0
ts:  bps=0 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 11:02:43.47 
get debug info at 11:02:44.52 
 
tun: ch=auto:351000000 lock=qam256:351000000 ss=99 snq=100 seq=100 dbg=-441/11348
dev: bps=37995552 resync=0 overflow=0
cc:  bps=38810720 resync=1 overflow=0
ts:  bps=37995552 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 11:02:44.59 
get debug info at 11:02:45.64 
 
tun: ch=auto:351000000 lock=qam256:351000000 ss=99 snq=100 seq=100 dbg=-441/11358
dev: bps=38810720 resync=0 overflow=0
cc:  bps=38810720 resync=1 overflow=0
ts:  bps=38810720 te=0 crc=0
net: pps=0 err=0 stop=0

release tuner2 at 11:02:45.72 
get debug info at 11:02:45.78 
 
tun: ch=none lock=none ss=0 snq=0 seq=0 dbg=0
dev: bps=0 resync=0 overflow=0
cc:  bps=38810720 resync=1 overflow=0
ts:  bps=0 te=0 crc=0
net: pps=0 err=0 stop=0

Since the signal strength is good (not too high or low), I'm thinking maybe due to age (Prime is 3.5 years old) the power adapter is going bad, so I have one on order.

Curious what these debug numbers look like on your Prime.

So I modified the script a bit after installing the new power adapter to test.
Now using windows command 'choice' for 1 second delay (about 1.03 secs).
choice /N /C A /D A /T 1

Still takes 2-3 seconds after issuing a tune to frequency or release tuner command for the numbers to stabilize.

Reason for cablecard cc: bps=38810720 is tuner0 was recording when I ran this on tuner2.

tuner2 Frq:117MHz at 17:39:36.42 (hdhomerun_config FFFFFFFF set /tuner2/channel auto:117000000) 
delay a second at 17:39:36.49 
get debug info at 17:39:37.52 (hdhomerun_config FFFFFFFF get /tuner2/debug) 
 
1 second after tune. 
tun: ch=auto:117000000 lock=qam256:117000000 ss=98 snq=100 seq=0 dbg=-441/3823
dev: bps=0 resync=0 overflow=0
cc:  bps=38810720 resync=1 overflow=0
ts:  bps=0 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 17:39:37.58 
get debug info at 17:39:38.61 (hdhomerun_config FFFFFFFF get /tuner2/debug) 
 
2 seconds after tune. 
tun: ch=auto:117000000 lock=qam256:117000000 ss=98 snq=100 seq=100 dbg=-441/3803
dev: bps=38810720 resync=0 overflow=0
cc:  bps=70000672 resync=1 overflow=0
ts:  bps=38810720 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 17:39:38.67 
get debug info at 17:39:39.70 (hdhomerun_config FFFFFFFF get /tuner2/debug) 
 
3 seconds after tune. 
tun: ch=auto:117000000 lock=qam256:117000000 ss=98 snq=100 seq=100 dbg=-441/3823
dev: bps=38810720 resync=0 overflow=0
cc:  bps=77621440 resync=1 overflow=0
ts:  bps=38810720 te=0 crc=0
net: pps=0 err=0 stop=0

release tuner2 at 17:39:39.76 (hdhomerun_config FFFFFFFF set /tuner2/channel none) 
delay a second at 17:39:39.82 
get debug info at 17:39:40.85 (hdhomerun_config FFFFFFFF get /tuner2/debug) 
 
1 second after release. 
tun: ch=none lock=none ss=0 snq=0 seq=0 dbg=0
dev: bps=0 resync=0 overflow=0
cc:  bps=43367840 resync=1 overflow=0
ts:  bps=0 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 17:39:40.92 
get debug info at 17:39:41.95 (hdhomerun_config FFFFFFFF get /tuner2/debug) 
 
2 seconds after release. 
tun: ch=none lock=none ss=0 snq=0 seq=0 dbg=0
dev: bps=0 resync=0 overflow=0
cc:  bps=38810720 resync=1 overflow=0
ts:  bps=0 te=0 crc=0
net: pps=0 err=0 stop=0

delay a second at 17:39:42.01 
get debug info at 17:39:43.04 (hdhomerun_config FFFFFFFF get /tuner2/debug) 
 
3 seconds after release. 
tun: ch=none lock=none ss=0 snq=0 seq=0 dbg=0
dev: bps=0 resync=0 overflow=0
cc:  bps=38810720 resync=1 overflow=0
ts:  bps=0 te=0 crc=0
net: pps=0 err=0 stop=0

Since I'm not having issues and none of my normal 30+ minute recordings show any errors, just consider this informative.

But, it would be interesting to hear from others with HDHR's what their numbers look like.

Here's the windows command script I'm using in case anyone wants to try it

testdebug.cmd

REM 
REM testdebug.cmd Windows command script to tune an HDHR Prime tuner2 to a specific frequency and check debug status at 1 second intervals
REM 
REM  output is redirected to file 'testdebug.txt' in current directory
REM  replace all hdhomerun_config 'FFFFFFFF' with the 'Device Id' of a specific HDHR, otherwise it runs the commands on all HDHR's
REM  replace all 'tuner2' with 'tuner#' desired, 3 tuner Prime has tuner0, tuner1 and tuner2
REM  replace all '117' with frequency in MHz desired
REM  if hdhomerun_config not in path, use full path "C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config"
REM 
REM tune HDHR Prime tuner2 to frequency 117MHz
REM 
echo tuner2 Frq:117MHz at %TIME% (hdhomerun_config FFFFFFFF set /tuner2/channel auto:117000000) >testdebug.txt
"C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config" FFFFFFFF set /tuner2/channel auto:117000000
REM 
REM use choice to delay for one second
REM 
echo delay a second at %TIME% >>testdebug.txt
choice /N /C A /D A /T 1 >NUL
REM 
REM get debug status from HDHR tuner2 at 1 second after tuning
REM 
echo get debug info at %TIME% (hdhomerun_config FFFFFFFF get /tuner2/debug) >>testdebug.txt
echo. >>testdebug.txt
echo 1 second after tune. >>testdebug.txt
"C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config" FFFFFFFF get /tuner2/debug >>testdebug.txt
REM 
REM use choice to delay for one second
REM 
echo delay a second at %TIME% >>testdebug.txt
choice /N /C A /D A /T 1 >NUL
REM 
REM get debug status from HDHR tuner2 at 2 seconds after tuning
REM 
echo get debug info at %TIME% (hdhomerun_config FFFFFFFF get /tuner2/debug) >>testdebug.txt
echo. >>testdebug.txt
echo 2 seconds after tune. >>testdebug.txt
"C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config" FFFFFFFF get /tuner2/debug >>testdebug.txt
REM 
REM use choice to delay for one second
REM 
echo delay a second at %TIME% >>testdebug.txt
choice /N /C A /D A /T 1 >NUL
REM 
REM get debug status from HDHR tuner2 at 3 seconds after tuning
REM 
echo get debug info at %TIME% (hdhomerun_config FFFFFFFF get /tuner2/debug) >>testdebug.txt
echo. >>testdebug.txt
echo 3 seconds after tune. >>testdebug.txt
"C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config" FFFFFFFF get /tuner2/debug >>testdebug.txt
REM 
REM release HDHR tuner2
REM 
echo release tuner2 at %TIME% (hdhomerun_config FFFFFFFF set /tuner2/channel none) >>testdebug.txt
"C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config" FFFFFFFF set /tuner2/channel none
REM 
REM use choice to delay for one second
REM 
echo delay a second at %TIME% >>testdebug.txt
choice /N /C A /D A /T 1 >NUL
REM 
REM get debug status from HDHR tuner2 at 1 second after releasing
REM 
echo get debug info at %TIME% (hdhomerun_config FFFFFFFF get /tuner2/debug) >>testdebug.txt
echo. >>testdebug.txt
echo 1 second after release. >>testdebug.txt
"C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config" FFFFFFFF get /tuner2/debug >>testdebug.txt
REM 
REM use choice to delay for one second
REM 
echo delay a second at %TIME% >>testdebug.txt
choice /N /C A /D A /T 1 >NUL
REM 
REM get debug status from HDHR tuner2 at 2 seconds after releasing
REM 
echo get debug info at %TIME% (hdhomerun_config FFFFFFFF get /tuner2/debug) >>testdebug.txt
echo. >>testdebug.txt
echo 2 seconds after release. >>testdebug.txt
"C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config" FFFFFFFF get /tuner2/debug >>testdebug.txt
REM 
REM use choice to delay for one second
REM 
echo delay a second at %TIME% >>testdebug.txt
choice /N /C A /D A /T 1 >NUL
REM 
REM get debug status from HDHR tuner2 at 3 seconds after releasing
REM 
echo get debug info at %TIME% (hdhomerun_config FFFFFFFF get /tuner2/debug) >>testdebug.txt
echo. >>testdebug.txt
echo 3 seconds after release. >>testdebug.txt
"C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config" FFFFFFFF get /tuner2/debug >>testdebug.txt
EXIT

UPDATE: have to include this in this older post as the forum won't allow me a new post here. That's OK as I feel I'm just talking to myself anyway :man_shrugging:

More data points;

Wondering how this is possible with DVR tuner sharing, unless Channels DVR actually is issuing a new tune command to the HDHR when it says sharing connection.

Issue appears with the 5th, 6th and 7th 1hr recording from the same channel starting at 16:00
[SNR] Statistics snq=99%,0%-100% seq=99%,0%-100%
All recordings are good and processed by my video editor with no errors.

2020/07/26 12:00:00.014427 [DVR] Starting job 1595790000-335 The Untouchables on ch=[376]
2020/07/26 12:00:00.457706 [TNR] Opened connection to 1323AADB/0 for ch376 KQCADT2
2020/07/26 12:00:00.458052 [DVR] Recording for job 1595790000-335 from 1323AADB ch376 into "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1200.mpg" for 1h0m29.98542234s
2020/07/26 13:00:30.459120 [SNR] Statistics for "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1200.mpg": ss=97%-98% snq=100% seq=100% bps=2960267,582048-6873280 pps=293,62-660

2020/07/26 13:00:00.017964 [DVR] Starting job 1595793600-335 The Untouchables on ch=[376]
2020/07/26 13:00:00.018260 [TNR] Sharing existing connection to 1323AADB/0 for ch376 KQCADT2 (clients=2, len=0)
2020/07/26 13:00:00.018504 [DVR] Recording for job 1595793600-335 from 1323AADB ch376 into "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1300.mpg" for 1h0m29.981876419s
2020/07/26 14:00:30.006427 [SNR] Statistics for "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1300.mpg": ss=97%,96%-98% snq=100% seq=100% bps=3065047,582048-7637312 pps=302,62-732

2020/07/26 14:00:00.014164 [DVR] Starting job 1595797200-335 The Untouchables on ch=[376]
2020/07/26 14:00:00.014430 [TNR] Sharing existing connection to 1323AADB/0 for ch376 KQCADT2 (clients=2, len=0)
2020/07/26 14:00:00.014671 [DVR] Recording for job 1595797200-335 from 1323AADB ch376 into "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1400.mpg" for 1h0m29.985687033s
2020/07/26 15:00:30.012330 [SNR] Statistics for "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1400.mpg": ss=96%-98% snq=100% seq=100% bps=3158224,582048-7641824 pps=311,62-733

2020/07/26 15:00:00.013791 [DVR] Starting job 1595800800-335 The Untouchables on ch=[376]
2020/07/26 15:00:00.014035 [TNR] Sharing existing connection to 1323AADB/0 for ch376 KQCADT2 (clients=2, len=0)
2020/07/26 15:00:00.014254 [DVR] Recording for job 1595800800-335 from 1323AADB ch376 into "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1500.mpg" for 1h0m29.986065995s
2020/07/26 16:00:30.023695 [SNR] Statistics for "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1500.mpg": ss=96%,95%-98% snq=100% seq=100% bps=3197519,582048-7641824 pps=315,62-733

2020/07/26 16:00:00.013923 [DVR] Starting job 1595804400-335 The Untouchables on ch=[376]
2020/07/26 16:00:00.014174 [TNR] Sharing existing connection to 1323AADB/0 for ch376 KQCADT2 (clients=2, len=0)
2020/07/26 16:00:00.014380 [DVR] Recording for job 1595804400-335 from 1323AADB ch376 into "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1600.mpg" for 1h0m29.985927145s
2020/07/26 17:00:30.053924 [SNR] Statistics for "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1600.mpg": ss=96%,95%-98% snq=99%,0%-100% seq=99%,0%-100% bps=3277283,0-7694464 pps=322,0-738

2020/07/26 17:00:00.058708 [DVR] Starting job 1595808000-335 The Untouchables on ch=[376]
2020/07/26 17:00:00.058945 [TNR] Sharing existing connection to 1323AADB/0 for ch376 KQCADT2 (clients=2, len=0)
2020/07/26 17:00:00.059163 [DVR] Recording for job 1595808000-335 from 1323AADB ch376 into "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1700.mpg" for 1h0m29.941151946s
2020/07/26 18:00:30.017942 [SNR] Statistics for "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1700.mpg": ss=96%,95%-98% snq=99%,0%-100% seq=99%,0%-100% bps=3373916,0-8655520 pps=332,0-830

2020/07/26 18:00:00.013309 [DVR] Starting job 1595811600-335 The Untouchables on ch=[376]
2020/07/26 18:00:00.013552 [TNR] Sharing existing connection to 1323AADB/0 for ch376 KQCADT2 (clients=2, len=1316)
2020/07/26 18:00:00.013764 [DVR] Recording for job 1595811600-335 from 1323AADB ch376 into "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1800.mpg" for 1h0m29.986543852s
2020/07/26 19:00:30.038905 [SNR] Statistics for "TV/The Untouchables/The Untouchables 1959-10-15 2020-07-26-1800.mpg": ss=96%,95%-98% snq=99%,0%-100% seq=99%,0%-100% bps=3323166,0-8655520 pps=327,0-830

@eric
I think if you started sampling at 3 seconds, or threw away that first result from your first inquiry at 2 seconds I wouldn't be seeing this.

Still curious what your HDHR Prime results look like.

I've been recording eight 1hr back-back overlapping recordings from the same Prime channel for the past 3 weeks and see issues in the log that don't reflect reality. Not a big deal, UNLESS you rely on that log data. Still the same on v2020.08.12.1854 today.

The HDHR logs show the tuner was selected and not released for eight hours.

Every back-back overlapping recording shows that it was sharing the existing HDHR tuner connection, yet every one shows seq=99%,0%-100% bps=#######,0-####### pps=###,0-###

I know this is a result of your first 2 second sampling. If the code can't be fixed, than everyone should know that this is NOT an issue with their tuner, but your code. Led me to buy a new power adapter for my HDHR, which wasn't the issue.

Is this feature still active. Tried to select "View Details" on several individual recordings and nothing popped up. When I selected View Debug Log I get a new tab open up with some detail, but not what is shown above?