Random pause when watching recorded tv

I am getting random pauses when watching recorded tv - specifically Dateline. The pause in video ranges from about 10-30 seconds. Log is below.

2020/03/20 09:20:32.109133 [DVR] indexed 113 movies (27 channels) [0s fetch, 0s index]
2020/03/20 09:20:32.113131 [DVR] Fetching guide data for 99 stations in X-TVE @ 2020-04-04 9:00PM
2020/03/20 09:20:33.129958 [DVR] indexed 636 airings (99 channels) [0s fetch, 0s index]
2020/03/20 09:20:33.529957 [DVR] indexed 45 movies (17 channels) [0s fetch, 0s index]
2020/03/20 09:20:33.537950 [DVR] Fetching guide data for 194 stations in USA-PA54007-X @ 2020-04-05 3:00AM
2020/03/20 09:20:36.046640 [DVR] indexed 2080 airings (194 channels) [1s fetch, 1s index]
2020/03/20 09:20:36.487386 [DVR] indexed 63 movies (16 channels) [0s fetch, 0s index]
2020/03/20 09:20:36.495382 [DVR] Fetching guide data for 99 stations in X-TVE @ 2020-04-05 3:00AM
2020/03/20 09:20:37.761307 [DVR] indexed 787 airings (99 channels) [0s fetch, 0s index]
2020/03/20 09:20:38.173785 [DVR] indexed 23 movies (15 channels) [0s fetch, 0s index]
2020/03/20 09:20:39.700303 [IDX] Pruned 101 expired groups from USA-PA54007-X in 5.9565ms.
2020/03/20 09:20:39.709327 [IDX] Pruned 58 expired groups from X-TVE in 9.0242ms.
2020/03/20 09:20:39.750304 [DVR] Rule '48 Hours' (4) found 1 new airings
2020/03/20 09:20:39.750304 [IDX] Pruned 1132 expired airings from USA-PA54007-X in 30.9686ms.
2020/03/20 09:20:39.757350 [DVR] queued recording job for SH000167470000-1586052000 @ Sat Apr 4 9:59:00PM (1586051940-4)
2020/03/20 09:20:39.763296 [IDX] Pruned 415 expired airings from X-TVE in 12.9921ms.
2020/03/20 09:20:39.794293 [DVR] Rule 'Dateline NBC' (14) found 2 new airings
2020/03/20 09:20:39.798311 [DVR] queued recording job for SH000191550000-1586044800 @ Sat Apr 4 7:59:00PM (1586044740-14)
2020/03/20 09:20:39.803334 [DVR] queued recording job for SH000191550000-1586048400 @ Sat Apr 4 8:59:00PM (1586048340-14)
2020/03/20 09:20:39.848281 [DVR] Rule 'The Alaska Triangle' (27) found 1 new airings
2020/03/20 09:20:39.852279 [DVR] queued recording job for EP032980980013 @ Sat Apr 4 9:59:00PM (1586051940-27)
2020/03/20 09:20:39.954220 [DVR] Rule 'Aerial America' (30) found 2 new airings
2020/03/20 09:20:39.959233 [DVR] queued recording job for EP014672190008 @ Sat Apr 4 11:59:00AM (1586015940-30)
2020/03/20 09:20:39.963215 [DVR] queued recording job for EP014672190016 @ Sun Apr 5 7:59:00AM (1586087940-30)
2020/03/20 09:20:39.981205 [DVR] Waiting 11h38m20.0187946s until next job 1584752340-14 Dateline NBC

2020/03/20 12:51:38 [Recovery] 2020/03/20 - 12:51:38 panic recovered:
write tcp 192.168.1.21:8089->192.168.1.13:56175: wsasend: An existing connection was forcibly closed by the remote host.
github.com/gin-gonic/[email protected]/render/json.go:58 (0x9ff56a)
github.com/gin-gonic/[email protected]/context.go:816 (0xa081bc)
github.com/gin-gonic/[email protected]/context.go:859 (0x1330028)
github.com/fancybits/channels-server@/http_device.go:239 (0x132fe92)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/fancybits/channels-server@/http_device.go:35 (0x13119a8)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/fancybits/channels-server@/http.go:230 (0x130ea75)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/fancybits/channels-server@/http.go:210 (0x130e659)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/fancybits/channels-server@/http.go:202 (0x130d705)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/gin-gonic/[email protected]/recovery.go:83 (0xa17f1a)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/fancybits/channels-server@/http.go:285 (0x1329a92)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/gin-contrib/[email protected]/sessions.go:65 (0x121d37d)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/gin-contrib/[email protected]/gzip.go:47 (0x121611d)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/fancybits/channels-server@/http.go:265 (0x1329858)
github.com/gin-gonic/[email protected]/context.go:147 (0xa04131)
github.com/gin-gonic/[email protected]/gin.go:403 (0xa0e330)
github.com/gin-gonic/[email protected]/gin.go:364 (0xa0da14)
net/http/server.go:2802 (0x71610a)
net/http/server.go:1890 (0x7118db)
runtime/asm_amd64.s:1357 (0x4626f0)

2020/03/20 15:37:49.366631 [DVR] Waiting 5h21m10.6333682s until next job 1584752340-14 Dateline NBC
2020/03/20 20:59:00.017483 [DVR] Starting job 1584752340-14 Dateline NBC on ch=[1011 811]
2020/03/20 20:59:00.017483 [DVR] Waiting 59m59.9825168s until next job 1584755940-30 Aerial America
2020/03/20 20:59:00.477553 [TNR] Opened connection to 13177781/0 for ch811 WPXIDT
2020/03/20 20:59:00.502034 [DVR] Recording for job 1584752340-14 from 13177781 ch811 into "TV\Dateline NBC\Dateline NBC S28E23 The Ranch 2020-03-20-2059.mpg" for 2h1m59.9825168s
2020/03/20 20:59:00.516480 [IDX] Generating video index for job 1584752340-14
2020/03/20 21:02:07.162437 [WRN] Buffer for 13177781 ch811 is more than 50% full (clients=1, len=16777684)
2020/03/20 21:02:14.109886 [WRN] Buffer for 13177781 ch811 is more than 75% full (clients=1, len=25165868)
2020/03/20 21:02:19.413953 [WRN] Buffer for 13177781 ch811 is more than 95% full (clients=1, len=31877468)
2020/03/20 21:02:20.376387 [WRN] Buffer for 13177781 ch811 is more than 99% full (clients=1, len=33219788)
2020/03/20 21:17:06.961489 [WRN] Buffer for 13177781 ch811 is more than 50% full (clients=1, len=16777684)
2020/03/20 21:17:13.712533 [WRN] Buffer for 13177781 ch811 is more than 75% full (clients=1, len=25165868)
2020/03/20 21:17:19.260892 [WRN] Buffer for 13177781 ch811 is more than 95% full (clients=1, len=31877468)
2020/03/20 21:17:20.308961 [WRN] Buffer for 13177781 ch811 is more than 99% full (clients=1, len=33219788)
2020/03/20 21:32:09.004639 [WRN] Buffer for 13177781 ch811 is more than 50% full (clients=1, len=16777684)
2020/03/20 21:32:16.019524 [WRN] Buffer for 13177781 ch811 is more than 75% full (clients=1, len=25165868)
2020/03/20 21:32:21.121511 [WRN] Buffer for 13177781 ch811 is more than 95% full (clients=1, len=31877468)
2020/03/20 21:32:22.304662 [WRN] Buffer for 13177781 ch811 is more than 99% full (clients=1, len=33219788)
2020/03/20 21:47:04.876769 [WRN] Buffer for 13177781 ch811 is more than 50% full (clients=1, len=16777684)
2020/03/20 21:47:11.732135 [WRN] Buffer for 13177781 ch811 is more than 75% full (clients=1, len=25165868)
2020/03/20 21:47:17.035614 [WRN] Buffer for 13177781 ch811 is more than 95% full (clients=1, len=31877468)
2020/03/20 21:47:18.260853 [WRN] Buffer for 13177781 ch811 is more than 99% full (clients=1, len=33219788)
2020/03/20 21:59:00.005930 [DVR] Starting job 1584755940-30 Aerial America on ch=[1477 915]
2020/03/20 21:59:00.005930 [DVR] Waiting 9h59m59.99407s until next job 1584791940-30 Aerial America
2020/03/20 21:59:00.533699 [TNR] Opened connection to 13177781/1 for ch915 SMTHHD
2020/03/20 21:59:00.554485 [DVR] Recording for job 1584755940-30 from 13177781 ch915 into "TV\Aerial America\Aerial America S01E32 2013-07-21 Montana 2020-03-20-2159.mpg" for 1h1m59.99407s
2020/03/20 21:59:00.574545 [IDX] Generating video index for job 1584755940-30
2020/03/20 22:02:08.149021 [WRN] Buffer for 13177781 ch811 is more than 50% full (clients=1, len=16777684)
2020/03/20 22:02:14.926165 [WRN] Buffer for 13177781 ch811 is more than 75% full (clients=1, len=25165868)
2020/03/20 22:02:20.650886 [WRN] Buffer for 13177781 ch811 is more than 95% full (clients=1, len=31877468)
2020/03/20 22:02:21.593774 [WRN] Buffer for 13177781 ch811 is more than 99% full (clients=1, len=33219788)
2020/03/20 22:02:30.004750 [WRN] Buffer for 13177781 ch915 is more than 50% full (clients=1, len=16777684)
2020/03/20 22:02:47.599892 [WRN] Buffer for 13177781 ch915 is more than 75% full (clients=1, len=25165868)
2020/03/20 22:17:09.080987 [WRN] Buffer for 13177781 ch811 is more than 50% full (clients=1, len=16777684)
2020/03/20 22:17:15.811649 [WRN] Buffer for 13177781 ch811 is more than 75% full (clients=1, len=25165868)
2020/03/20 22:17:21.263342 [WRN] Buffer for 13177781 ch811 is more than 95% full (clients=1, len=31877468)
2020/03/20 22:17:22.215784 [WRN] Buffer for 13177781 ch811 is more than 99% full (clients=1, len=33219788)
2020/03/20 22:17:31.580270 [WRN] Buffer for 13177781 ch915 is more than 50% full (clients=1, len=16777684)
2020/03/20 22:17:49.349748 [WRN] Buffer for 13177781 ch915 is more than 75% full (clients=1, len=25165868)
2020/03/20 22:32:07.445749 [WRN] Buffer for 13177781 ch811 is more than 50% full (clients=1, len=16777684)
2020/03/20 22:32:14.122252 [WRN] Buffer for 13177781 ch811 is more than 75% full (clients=1, len=25165868)
2020/03/20 22:32:19.547995 [WRN] Buffer for 13177781 ch811 is more than 95% full (clients=1, len=31877468)
2020/03/20 22:32:20.732586 [WRN] Buffer for 13177781 ch811 is more than 99% full (clients=1, len=33219788)
2020/03/20 22:32:29.445654 [WRN] Buffer for 13177781 ch915 is more than 50% full (clients=1, len=16777684)
2020/03/20 22:32:47.090057 [WRN] Buffer for 13177781 ch915 is more than 75% full (clients=1, len=25165868)
2020/03/20 22:47:10.485520 [WRN] Buffer for 13177781 ch811 is more than 50% full (clients=1, len=16777684)
2020/03/20 22:47:17.485613 [WRN] Buffer for 13177781 ch811 is more than 75% full (clients=1, len=25165868)
2020/03/20 22:47:22.774583 [WRN] Buffer for 13177781 ch811 is more than 95% full (clients=1, len=31877468)
2020/03/20 22:47:23.777095 [WRN] Buffer for 13177781 ch811 is more than 99% full (clients=1, len=33219788)
2020/03/20 22:47:32.893490 [WRN] Buffer for 13177781 ch915 is more than 50% full (clients=1, len=16777684)
2020/03/20 22:47:50.868284 [WRN] Buffer for 13177781 ch915 is more than 75% full (clients=1, len=25165868)
2020/03/20 22:53:02.708889 [SYS] Created database snapshot: backup-20200320.225302
2020/03/20 22:53:02.708889 [SYS] Removing old backup backup-20200229.190452

This is bad and means video data is being dropped. Usually this is due to resource exhaustion, commonly in disk write throughput. I would check the Task Manager while recording to see if CPU, RAM or Disk are maxing out.

I wonder if it was just too much to be watching, recording (2 shows), and processing commercials on another show? I normally don’t have problems, it just seems like it happens when my wife is watching/recording her shows, lol. We’ll blame it on her!

I’m betting my Drobo 5C (DAS) is probably the weak link, it has decent transfer speeds (USB 3.0) when watching 40GB Blu-ray rips, I usually see about 350Mbps but I’m guessing multiple devices reading and writing to it isn’t the best. It has WD Red (5400) drives in it. It’s hooked up to my Alienware Alpha PC which shouldn’t have any issues with anything thrown at it.

Here’s what it looks like while recording 2 stations and watching one.


Any suggestions?

Were you getting buffer full errors in the logs at the same time you took those screenshots? The screenshots show the disk is basically idling.

No, I just purposely set the DVR to record 2 stations while watching a 3rd. I was hoping to recreate the issue.

I’m kinda confused because the screenshots were live while running 3 shows so I’m not sure what my issue is. Disk S: is the Drobo that all media is stored on and recorded to. Disk C: is the OS and the PC that is running Channels in the system tray.

I’ve turned off commercial skip thinking that maybe it was causing an issue. I also changed the transcoding from hardware to software - although I know that will only impact the PC when connecting remotely.

I’m also confused why my video card has no activity. Is it not used at all with the HDHomerun and Channels?

No, it isn't. Just the disk and network. It doesn't need the graphics subsystem except in the case of hardware-based transcoding.