Bug Report: comskip updates are causing new DVR issues

djcastaldo · May 25, 2017, 6:33am

Lately I have been getting new buffer warnings in the log. Commercial Detection is taking longer than it used to. comskip is nearly maxing out my RAM. And CPU usage is all over the place. web-ui fails to load. recordings are timing out. I first noticed the buffer log warnings on 23 May. I think it is result of changes to comskip, which was previously working perfectly.

I had to ssh in to the server and kill the comskip process to return normal functionality of the DVR. I don’t know how long it is going to last, however. I hope we can switch back to the previous settings, which worked fine.

djcastaldo · May 25, 2017, 10:11am

30-min show (takes about 6 minutes):

2017/05/22 12:30:02 [DVR] Running commercial detection on file 1820 (TV/RightThisMinute/2017-05-22-1200 RightThisMinute 2017-05-22 S06E451.mpg) 2017/05/22 12:36:17 [DVR] Commercial detection finished with 10 markers.
1-hour show (takes about 12 minutes):

2017/05/22 14:00:02 [DVR] Running commercial detection on file 1821 (TV/Crime Watch Daily With Chris Hansen/2017-05-22-1300 Crime Watch Daily With Chris Hansen 2017-05-22 S01E181 Doctors Deadly Orders.mpg) 2017/05/22 14:11:57 [DVR] Commercial detection finished with 16 markers.
DVR update:

2017/05/22 18:15:36 [SYS] Downloading new version v2017.05.22.2051 2017/05/22 18:15:50 [SYS] Update downloaded and verified successfully. 2017/05/22 18:15:50 [SYS] Shutting down for upgrade from v2017.05.17.1932 to v2017.05.22.2051
30-min show after update (now takes about 12 minutes):

2017/05/22 19:00:01 [DVR] Running commercial detection on file 1822 (TV/NBC Nightly News With Lester Holt/2017-05-22-1830 NBC Nightly News With Lester Holt 2017-05-22.mpg) 2017/05/22 19:11:30 [DVR] Commercial detection finished with 14 markers.
1-hour show after update (now takes over 20 minutes):

2017/05/23 01:37:02 [DVR] Running commercial detection on file 1827 (TV/The Late Late Show With James Corden/2017-05-23-0037 The Late Late Show With James Corden 2017-05-22 S02E177 Lionel Richie Jenna Dewan Tatum.mpg) 2017/05/23 01:57:31 [DVR] Commercial detection finished with 12 markers.

and sometimes there are these new errors:
-redacted-

and here is the most recent errors.

2017/05/25 00:37:03 [DVR] Running commercial detection on file 1859 (TV/The Tonight Show Starring Jimmy Fallon/2017-05-24-2334 The Tonight Show Starring Jimmy Fallon 2017-05-24 S04E147 Orlando Bloom Zoe ListerJones Mike Vecchione.mpg) 2017/05/25 01:06:47 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16786164) 2017/05/25 01:06:48 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16786708) 2017/05/25 01:06:51 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:06:52 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25166488) 2017/05/25 01:06:54 [WRN] Buffer for 1055351A ch13.1 is more than 95% full (clients=1, len=31877468) 2017/05/25 01:06:56 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31877344) 2017/05/25 01:07:11 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:07:11 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:07:16 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16779920) 2017/05/25 01:07:20 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:07:23 [WRN] Buffer for 1055351A ch13.1 is more than 95% full (clients=1, len=31877468) 2017/05/25 01:07:24 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:07:30 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:07:47 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16785580) 2017/05/25 01:09:25 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:09:25 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16784132) 2017/05/25 01:09:29 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:09:29 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:09:32 [WRN] Buffer for 1055351A ch13.1 is more than 95% full (clients=1, len=31877468) 2017/05/25 01:09:35 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31877468) 2017/05/25 01:10:12 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16800708) 2017/05/25 01:10:14 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16800656) 2017/05/25 01:10:18 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25168076) 2017/05/25 01:10:19 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25172592) 2017/05/25 01:10:21 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31877044) 2017/05/25 01:10:22 [WRN] Buffer for 1055351A ch13.1 is more than 95% full (clients=1, len=31876824) 2017/05/25 01:10:24 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16778160) 2017/05/25 01:10:28 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25166344) 2017/05/25 01:10:29 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16778308) 2017/05/25 01:10:32 [WRN] Buffer for 1055351A ch13.1 is more than 95% full (clients=1, len=31876992) 2017/05/25 01:10:33 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25171656) 2017/05/25 01:10:35 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31880228) 2017/05/25 01:10:58 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16798064) 2017/05/25 01:11:00 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16807056) 2017/05/25 01:11:01 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25186888) 2017/05/25 01:11:02 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25169040) 2017/05/25 01:11:04 [WRN] Buffer for 1055351A ch13.1 is more than 95% full (clients=1, len=31890592) 2017/05/25 01:11:05 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16806372) 2017/05/25 01:11:12 [DVR] Cancelling stream 1055351A ch11.1 after 3s read timeout 2017/05/25 01:11:29 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16777620) 2017/05/25 01:11:29 [TNR] Closed connection to 1055351A for ch11.1 2017/05/25 01:11:29 [DVR] Job 1495687020-70 Late Night With Seth Meyers ended prematurely: 26m30.295481288s 2017/05/25 01:11:31 [DVR] Starting job 1495687020-70 Late Night With Seth Meyers on ch=[11.1 4.1] 2017/05/25 01:11:31 [DVR] Waiting 2h18m28.042185396s until next job 1495697400-28 Extra 2017/05/25 01:11:32 [TNR] Opened connection to 1055351A for ch11.1 [transcode=none] 2017/05/25 01:11:32 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25166900) 2017/05/25 01:11:32 [DVR] Recording for job 1495687020-70 from 1055351A ch11.1 into "TV/Late Night With Seth Meyers/2017-05-25-0037 Late Night With Seth Meyers 2017-05-24 S04E114 Kevin Spacey Ellie Kemper Tom Perez Matt Frazier.mpg" for 26m28.042095395s 2017/05/25 01:11:35 [WRN] Buffer for 1055351A ch13.1 is more than 95% full (clients=1, len=31877184) 2017/05/25 01:11:47 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777868) 2017/05/25 01:11:56 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25166184) 2017/05/25 01:12:01 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777816) 2017/05/25 01:12:05 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25166000) 2017/05/25 01:12:15 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:12:15 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:12:20 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:12:20 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:12:22 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:12:23 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31877468) 2017/05/25 01:12:26 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:13:13 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16779336) 2017/05/25 01:13:16 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25175004) 2017/05/25 01:13:20 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31891868) 2017/05/25 01:13:22 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:13:29 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:13:33 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:13:47 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16787456) 2017/05/25 01:13:48 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16809136) 2017/05/25 01:13:50 [WRN] Buffer for 1055351A ch13.1 is more than 75% full (clients=1, len=25192056) 2017/05/25 01:13:52 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25169156) 2017/05/25 01:13:54 [WRN] Buffer for 1055351A ch13.1 is more than 95% full (clients=1, len=31884548) 2017/05/25 01:13:56 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31903656) 2017/05/25 01:14:12 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777304) 2017/05/25 01:14:32 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16789072) 2017/05/25 01:14:38 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16778128) 2017/05/25 01:14:42 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16786380) 2017/05/25 01:14:43 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16787524) 2017/05/25 01:16:13 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16786764) 2017/05/25 01:16:17 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16778616) 2017/05/25 01:16:19 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25192580) 2017/05/25 01:16:23 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31903400) 2017/05/25 01:16:36 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777696) 2017/05/25 01:16:39 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25165860) 2017/05/25 01:16:42 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31877460) 2017/05/25 01:16:56 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777832) 2017/05/25 01:17:29 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777684) 2017/05/25 01:17:34 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25181660) 2017/05/25 01:17:41 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31877468) 2017/05/25 01:17:47 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16779424) 2017/05/25 01:17:50 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:17:53 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16777304) 2017/05/25 01:17:59 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16809136) 2017/05/25 01:18:04 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16803872) 2017/05/25 01:18:10 [WRN] Buffer for 1055351A ch11.1 is more than 50% full (clients=1, len=16803872) 2017/05/25 01:18:14 [WRN] Buffer for 1055351A ch11.1 is more than 75% full (clients=1, len=25165868) 2017/05/25 01:18:17 [WRN] Buffer for 1055351A ch11.1 is more than 95% full (clients=1, len=31877468) 2017/05/25 01:18:20 [WRN] Buffer for 1055351A ch13.1 is more than 50% full (clients=1, len=16809136) 2017/05/25 01:18:20 [TNR] Closed connection to 1055351A for ch13.1 2017/05/25 01:18:20 [DVR] Job cancelled: 1495687020-13 The Late Late Show With James Corden 2017/05/25 01:18:21 [DVR] Waiting 2h11m38.133751545s until next job 1495697400-28 Extra 2017/05/25 01:18:31 [DVR] Waiting 2h11m28.182128791s until next job 1495697400-28 Extra 2017/05/25 01:18:33 [TNR] Closed connection to 1055351A for ch11.1 2017/05/25 01:18:33 [DVR] Job cancelled: 1495687020-70 Late Night With Seth Meyers

So something is broken in comskip since the May 22 update.

tmm1 · May 25, 2017, 2:16pm

What does http://x.x.x.x:8089/dvr/files/1827/comskip.ini say?

tmm1 · May 25, 2017, 2:30pm

Never mind, that will be a 404.

I’m interested in the “thread_count=” line from http://x.x.x.x:8089/dvr/files/1827/comskip.log

djcastaldo · May 25, 2017, 2:46pm

I didn’t notice anything particular that was unusual about that log, but I emailed it to you. The biggest problem is that it has the possibility to occasionally cause the issue as it did with file 1859. I don’t have a log for that one though, probably because I killed the process before it finished.

tmm1 · May 25, 2017, 2:53pm

Are these mpeg2 or h264 recordings?

djcastaldo · May 25, 2017, 2:57pm

should be mpeg. they are from US broadcast towers and my HDHRs are not doing any transcoding.

tmm1 · May 25, 2017, 5:12pm

Should be fixed in latest build, let me know if you still have issues.

djcastaldo · May 26, 2017, 1:17am

2017/05/25 21:00:01 [DVR] Running commercial detection on file 1870 (TV/Beat Shazam/2017-05-25-2000 Beat Shazam 2017-05-25 S01E01 Episode One.mpg) 2017/05/25 21:11:55 [DVR] Commercial detection finished with 10 markers.

Back to normal comskip time for a 1-hour show! And no crazy buffer warnings. The most recent update where you switched it back to a single core is what appears to have fixed this. Thank you for the quick response!