DVR started recording late

Channels DVR Server Troubleshooting
#1

I've reloaded my Pi with Raspbian OS Lite. Noticed recording tonight stated it started late. Looked in the log and appears they did start 41seconds late. The DVR was not doing anything and was not using the DVR or the HDHR.

image

HDHR Log also shows the 41 seconds late request and no errors before.

image

I checked the date and time on the OS and it's time is sync'd. Also thinking about it, the DVR log itself knew it was 41seconds late.

What would cause the recordings to start late? Yes I know I can pad time, but seems strange it would not start on-time. The next set of recordings started on-time. Thanks.

#2

It's hard to tell with screenshots.
Looks like you had 3 recordings start.
Can you copy and paste the log entries.
You can put them between lines of three backticks ```

When were the recordings scheduled (from a pass, manually at what time, etc.)
The full job# will tell if it was manually scheduled or from a pass.
The DVR log will show it's waiting xx minutes to start recording, like so

2021/09/27 09:40:39.740505 [DVR] Waiting 6h19m10.259506604s until next job 1632783590-26 Rick Steves' Europe
2021/09/27 15:59:50.006734 [DVR] Starting job 1632783590-26 Rick Steves' Europe on ch=[6004]
#3

Your previous posts have usually indicated an issue with your home internet connection or other home networking issues. Have you ensured that everything is working as expected?

If the problem was the recording not starting at all, the first recommendation would be to eliminate everything but the required devices for recording from your path. But since the problem is only a late start, has anything changed in your network topography?

#4

Hello, yes was recording three OTA all from Season Pass. Do note I've reloaded from the Channels Pi USB Image and used the Restore function to migrate to the new OS(followed the Linux install guide). It's the same Pi board but swapped out a USB3 HDD for a M.2 Sata. This is the second migration as I went from a smaller drive to a larger HDD and now to a M.2 SSD. Not overclocked either.

Using Pre-release 2021.09.23.2243
Here is the log cutout:
2021/09/27 13:32:18.043288 [DVR] Waiting 5h27m41.956737647s until next job 1632787200-21
(Note, did reboot here as I did a Apt update/upgrade for the OS: 2021/09/27 15:47:56.773691 [SYS] Starting Channels DVR v2021.09.23.2243 (linux-armv7l pid:558)
2021/09/27 15:47:59.191726 [DVR] Waiting 3h12m0.808300383s until next job 1632787200-21
2021/09/27 19:00:42.353351 [DVR] Starting job 1632787200-21
If my math is correct, should have started right at the top of the hour before and after the reboot; as the time adds up.
The rest of the recordings tonight all started on-time. Did not touch anything besides looking at the log in the Web interface.
2021/09/27 20:00:00.048135 [DVR] Starting job
2021/09/27 21:00:00.031941 [DVR] Starting job

@racameron, to answer your question, I did a system check after the reboot and before the late recording start, and everything was fine too:
2021/09/27 17:13:03.208357 [TRS] DNS: OK: Resolved host via system DNS
2021/09/27 17:13:03.576630 [TRS] Cloud Reachable: OK: Connected to community.getchannels.com
2021/09/27 17:13:03.982119 [TRS] Local Time: OK: Local clock is accurate
2021/09/27 17:13:03.982515 [TRS] TV Everywhere: OK
2021/09/27 17:13:03.982802 [TRS] Remote Access: OK: Remote access not configured
2021/09/27 17:13:03.984800 [TRS] Disk Permissions: OK
DVR and HDHR are in the same shelf same switch. The rest of the OTA and all the TVE Recordings after did start on time too.
Also we were eating so a low time for Internet usage for us. :wink:

If my OS time was off, the DVR logs would think it's starting on-time. With the DVR listing the recordings were Delayed and starting late, that is where I'm perplexed where 41 seconds of drift came from. This is not the end of the world, just trying to understand what could have caused this. Thanks.

#5

Only thing that comes to mind for me is heavy system load at the time of the issue.

#6

I'm assuming there are other log entries between these two you trimmed out?
Maybe something relevant.

I don't know how the Channels code works on a RPi.
i.e. does it set a timer in advance to start a recording later, etc.
Could be local clock drifting, subsystem (like disk) taking time to respond, etc.

I know my NAS's and Win10 PC time is kept accurate to within less than a second using time.google.com as their NTP server.
TIME.IS

#7

@chDVRuser, from the reboot, did a DVR status check and family watched some OTA and TVE Streams till 17:44. It was idle until 19:00.41 where the Channels client showed recording started late.
That is when I went to my PC to investigate. 41 seconds of drift over a few hours does not add up. Also checking DVR Status shows "local clock is accurate" . Check in Raspbian CLI command timedatectl, states system clock synchronized too.

Even if my time was off, why would Channels DVR start the recording late? Wouldn't it show time stamp starting on time anyway? If there was an issue connecting to the HDHR, would the DVR log show starting job on time?

I did one recording test at 4am(one-time schedule) and one at 9am(Pass). No issues with those starting on-time

I've moved to the Prerelease 2021.09.28.1512 and will see if I have any quirks this evening and update this thread. Thanks.

#8

If the tuners were unavailable at the scheduled start time, but became available later, that could explain the delay.

Remember, by default the DVR has no knowledge of the status of tuners being used by clients watching live OTA TV. Only when tuner sharing is enabled in the client will the DVR become aware of the status of a HDHR tuner, as it becomes the client's delegate for tuning.

#9

@racameron, HDHR was idle as well. The DVR log it would show if there was no available tuner.

#10

Well, then I'm out of ideas. You're only providing partial logs and minimal details, so I'm out of relevant WAGs.

#11

@racameron, thanks. I don't want to share what my family watches, so not sure all that verbose details on that is relevant. As for Minimal details, open to ideas. Don't feel I've been limited there.

I've seen where a TVE Recording started a few seconds late; but the DVR Log showed authentication issues and retried. The log here just shows it started late with no errors. These were OTA recordings too. I could see that the HDHR Tuner could take a few seconds to start, but the log I shared showed the DVR not trying to start until 41seconds after it should have. So the log should show it started recording, then requesting tuner access.

So the log below shows the DVR Job started late and .4 seconds later requesting connection to HDHR:
2021/09/27 19:00:41.533974 [DVR] Starting job 1632787200-46
2021/09/27 19:00:41.934595 [TNR] Opened connection to 1xxxx

So regardless if my HDHR was available or not, the DVR Job started late. If my time was off, the job would have logged it started on time?

I checked the forum and only found a post about this a while ago affecting Apple; so did not respond to that thread since I was on a Pi.

Thanks

#12

Late wake up is indeed unexpected and generally means the OS/kernel did not wake the process in time. I've seen it happen on Windows but even there 41s is quite extreme.

I know the Pi does not have an RTC so perhaps that is related?

I have not heard of this with our official Pi image which uses a 64bit kernel.

#13

Thanks @tmm1. The Raspbian OS Lite is 32bit. Their 64bit is still in beta. I went from the Official DVR Pi Image to Raspbian so I could load Fan scripts and enable SSD Trim to maximize the flash cell life of the SSD. If this continues to be an issue, I'll just pad extra time in the beginning of recordings and wait until the 64bit Raspbian OS is released(unless you guys are planning to update the DVR Image with Trim and fan scripts) :wink: Other reason I moved is the HDD was spinning 24/7, so I assume spindown/sleeping of HDD was not available with the official image.

MakerFire does make a RTC GPIO Module using a CR1220 battery. If this is a bigger issue, I'll see about testing one of those with the 32bit OS. Thanks.

#14

While not supported, it is possible to run additional scripts/applications on the RPi image. Just beware that applications will probably need to be statically linked as library versions may differ or not be present; also, you'll probably have to re-install them when the OS image is updated.

#15

@racameron, I thought about doing that, but since I was replacing the HDD drive with a M.2, I was going to do a full rebuild anyway and it would be easier for me to use 'apt' to load the extras I wanted. Either way, I would be forking from the Official Image. I'm pretty sure this is not the last time I'll be reloading the Pi. :wink:

#16

I always pad my recordings so this never happens. Sometimes the tuners are not available immediately or there's a network connection issue. The broadcast signal from the station could be delayed for some reason and not start exactly on time. Padding your recordings is always a good idea because there are too many variables involved that could cause problems like this. Expecting a recording to start or end exactly on time is more wishful thinking than a reality.

#17

Can you share what you're doing for TRIM and HDD sleep? And which fan scripts are you using specifically?

#18

Our RPI image does have a periodic fstrim already built-in. You can verify with systemctl list-timers.

1 Like
#19

@tmm1, took a break from the Internet and come back and see all this activity! :slight_smile: Sorry for the late reply, looks like you added TRIM to the Official RPi Image already. I was just following this guide Enabling TRIM on an external SSD on a Raspberry Pi | Jeff Geerling

The main point from that blog is making sure the SDD and the SATA controller both support TRIM. There were different cases I would have wanted to purchase(aka cheaper) but unknown if the SATA controller supported TRIM. I saw a post that the Argon M.2 case now come factory with firmware supporting TRIM. I bought my case last month on Amazon and it did have firmware supporting TRIM. If not, there is a hack to load TRIM enabled firmware for older cases.

As for fan script, I'm using Agron's script: curl https://download.argon40.com/argon1.sh | bash
With the Argon M.2 case, I'm trying their default fan settings. The fan stays off most of the time as the CPU temps seems to stay below 55c for me. Checking with: vcgencmd measure_temp I'm right now hovering 44c with just one recording playing. Ambient temp where the Pi is located is now 78f(~25.5c). Without the fan script, the fan will stay at 30% speed. It's quiet, but a tad too noticeable when the room is quiet. With the fan script the default is to turn on at 55c at 10% speeds.

For HDD Sleep, I've moved to a M.2 SATA so did not look into that further. I do use HDDs with Open Media Vault. OMV already has SMART support enabled and the HDDs do spin down. Just a note, I was testing with some older USB HDDs that were USB2 and those did not spin down or were passing SMART metrics. All the USB3 HDDs I had did work with OMV for SMART and HDD Spindown.

I have not had anymore late recording starts; but plan to flip back to the Official RPi image. Thanks.

#20

Thanks. I will be working on support for the various Argon40 fans/cases.

2 Likes