Recordings copy speed from cache to NAS - Unable to keep up with recording segments in cache errors

[LaurenceGough]

Hi all,

I am looking for a bit of help.

Thanks to the recent Frigate BETAs I have identified what seems like a very intermittent issue writing to my NAS. The NAS is dedicated to Frigate with a single 2TB WD20PURX-64PFUY0 (the purple surveillance drive) HDD. Only /recordings/ is stored on the NAS. DB etc is local to the host.

Example of the error: "WARNING : Unable to keep up with recording segments in cache for Cam1. Keeping the 5 most recent segments out of 6 and discarding the rest..." etc

This causes a loss of recording during the duration of this, usually around 30-40 seconds is lost.

This can happen quite a bit in an hour or it can go half a day or more without showing once!

Thanks to Blake's recommendation I added the following to my config:

logger:
  logs:
    frigate.record: debug

This then shows the copy procedures from the cache to the NAS in the logs, on average this takes around 1 second, but close to where it goes wrong it can go up to 5-15 seconds for a few clips after.

One example:

2023-02-05 19:17:02.316665692  [2023-02-05 19:17:02] frigate.record                 DEBUG   : Copied /media/frigate/recordings/2023-02-05/19/Cam2/15.16.mp4 in 2.9474120140075684 seconds.
2023-02-05 19:17:06.411911579  [2023-02-05 19:17:06] frigate.record                 DEBUG   : Copied /media/frigate/recordings/2023-02-05/19/Cam2/15.24.mp4 in 3.513415813446045 seconds.
2023-02-05 19:17:06.570395745  [2023-02-05 19:17:06] frigate.record                 WARNING : Unable to keep up with recording segments in cache for Cam1. Keeping the 5 most recent segments out of 8 and discarding the rest...
2023-02-05 19:17:06.579165134  [2023-02-05 19:17:06] frigate.record                 WARNING : Unable to keep up with recording segments in cache for Cam2. Keeping the 5 most recent segments out of 9 and discarding the rest...
2023-02-05 19:17:13.828748463  [2023-02-05 19:17:13] frigate.record                 DEBUG   : Copied /media/frigate/recordings/2023-02-05/19/Cam1/16.08.mp4 in 6.398522853851318 seconds.
2023-02-05 19:17:21.282820385  [2023-02-05 19:17:21] frigate.record                 DEBUG   : Copied /media/frigate/recordings/2023-02-05/19/Cam1/16.18.mp4 in 6.570835828781128 seconds.

This NAS is old and only has 256MB of RAM but it is dedicated to only this, it is connected to a gigabit link through a gigabit switch to the Raspberry Pi host which Frigate is running on as a docker container. The HDD passes SMART tests with 0 warnings but I haven't done anything more extensive on it.

The CPU usage on the Pi never goes above 50%, checked with Portainer and with htop. RAM usage is around 50%.

Does anyone have any ideas on what the issue could be? I've turned on all of the options on my NAS to increase performance such as no journaling, write caching on etc. I have restarted my NAS and I have fully updated and restarted my Raspberry Pi. I have tried to accessing events, seeking in these events etc and this doesn't cause the issue. I was thinking maybe during this that was slowing writes.

I am leaving a continuous ping running from the Pi to the NAS and it was always 2ms or less and never dropped or had any packet loss. The switch ports confirm no packet errors, or loss. Even during this issue pings are below 2ms and no packets are lost.

Thank you.

[NickM-27]

If your NAS only has 256MB RAM I doubt it has a fast HDD. Probably just slow, outdated hardware.

[blakeblackshear]

It could also just be that you are running up against the limits of what a Pi can send over a network interface. It's reading from the cameras and writing to the NAS. It could also be that the thread which writes to the NAS is being interrupted to do other things for Frigate. It may just be more than the little Pi can handle.

[blakeblackshear]

The Coral USB3 and ethernet may also share a bus and compete with each other.

[NickM-27]

The Coral USB3 and ethernet may also share a bus and compete with each other.

looks like this is the case for Pi 3 but was addressed in the pi 4: https://raspberrypi.stackexchange.com/a/99897

[LaurenceGough]

Hmm that is a really great point.

Doing a bit of digging it seems the Pi 4 is restricted to a 1x 2.0 PCIE lane for all 4x USB ports. That is 500MB/s or 4 Gbps shared.

So I'm not sure how much the Coral uses (I've no idea!). The SSD running the Pi is also running from USB 3.

However, as Nick mentioned it looks like the Ethernet runs from a separate bus now. I know that was an issue before with the Pi 3.

Pi 4 graph found here: https://heise.cloudimg.io/width/2000/q75.png-lossy-75.webp-lossy-75.foil1/_www-heise-de_/ct/imgs/04/2/7/4/3/7/8/1/RPi4-Block-e4359fdb4be588cf.png

So by purchasing a USB caddy to use as storage I might be just causing a different issue...

I've started looking at the ODROID and other alternatives to the Pi again now. I of course something that will do the job but also not something that drains a ton of power. Something with proper SATA and/or NVME connections sounds ideal...

[NickM-27]

AFAIK the odroid doesn't have working hwaccel with ffmpeg. I'd personally suggest some Intel based small form factor device. Just because it has a higher TDP than a pi doesn't mean it is going to use that much power as it's just a (loosely defined) max draw.

[LaurenceGough]

As this issue comes and goes for me, having a very brief look at the record.py code that runs in Frigate which performs this function I have made a suggested pull request of changing the value of 5 to 20, which I don't think mine has gone quite as high yet but it gives a bit of a buffer. Perhaps 15 might be a middle ground?

The only downside that I could see, in my very, very limited knowledge is a potential for a slightly increased cache usage, but I don't think by that much. However, perhaps merging the change would completely break Frigate, I really don't know enough about it :D. I think it'd fix the issue for me though. Maybe one day when I have the time I'll give it a try building it and testing it myself.

#5419

I see this is why so many products have analytics so they can easily see if this is an issue for some of their users or not. (I'm not suggesting this at all! haha! )

[LaurenceGough]

Just for info it also does it when set to record motion on both cameras rather than record always on both.

    record:
      enabled: True
      retain:
         days: 20
         mode: motion

[DrSpaldo]

I'm getting similar log messages. Except mine is Unraid with SSD cache & spinning drives for storage as well as 64 gigs ram. I have bumped up the shm to 1gb & tmpfs to 16gig. See if that makes a difference..

[NickM-27]

If it keeps happening you should include the times it takes for moving the files via debug logs for frigate.record

[LaurenceGough]

Is it still an issue with your updated settings? As Nick said above if you turn on debug with:

logger:
  logs:
    frigate.record: debug

What times are you seeing?

Thanks

[DrSpaldo]

Is it still an issue with your updated settings? As Nick said above if you turn on debug with:

logger:
  logs:
    frigate.record: debug

What times are you seeing?

Thanks

I changed the settings as above and also turned on the debug. It eventually almost stopped my entire Unraid machine. Everything was so slow I couldn't even load the Frigate or Unraid web interface. So I had to SSH in and kill the Frigate process, that fixed the slow issue. Then I slightly reduced the shm & tmpfs and turned off the debugging. I can't work out where the old logs are kept, so I can't see around that time exactly what was happening.

I am still getting a couple of the same "WARNING : Unable to keep up with recording segments in cache " messages in the logs, but they are pretty limited to a bunch every day or so. I am actually thinking that it could (and this is a guess) be the same time that the mover is activating and moving the files from my cache drive to the main array in Unraid. I have no basis for the theory, other than it may be a time when HDD access is slower. Because when I had the debug log on at first, the move operation was 0.x seconds, so it was pretty fast...

[DrSpaldo]

Actually, I just checked the Unraid log. Can't see the mover doing anything at that time. At another time I can see this error in the log:

Feb 20 22:30:11 SpaldoUnraid kernel: oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=emulator,mems_allowed=0,global_oom,task_memcg=/docker/341b48023b9789f52e371f8e0bf598ebfbb91868321d8137e94f41908eafa8f3,task=frigate.capture,pid=32553,uid=0
Feb 20 22:30:11 SpaldoUnraid kernel: Out of memory: Killed process 32553 (frigate.capture) total-vm:40479300kB, anon-rss:36674540kB, file-rss:0kB, shmem-rss:52kB, UID:0 pgtables:72128kB oom_score_adj:0

[Red-ington]

Did we have a fix for this??

[LaurenceGough]

Hi all @Red-ington (tagging as I saw you posted above).

I have found a workaround that almost resolves the issue for me but not quite fully.

The segment (recording) drop issue was on average happening for 15-25 minutes of elevated segments at completely random times, 4-6 times a day. The build that Nick kindly created was better, but still during these times I think I recall the count going up to 50-60 at one point!! Other times around 30-40.

I checked the full syslogs on my Raspberry Pi and NAS and any other logs, any cron jobs that I could find. There was absolutely nothing apart from Frigate segment drop messages. CPU usage never above 50% on either device. RAM usage was high on the NAS but kind of expected as it only has 256MB RAM and is probably caching a lot. Nothing really obvious using the RAM, SMB wasn't using much.

Anyway, I thought I'd change the NAS to use NFS rather than SMB/CIFS/SAMBA. The difference is night and day. Exactly the same setup otherwise. Netgear decided to make the share path quite different when using NFS so that caught me out for a little bit... PS for anyone reading, use showmount -e to check what NFS path is being advertised, it's not always what you set. nfs-common package will need to be installed to be used as NFS client and to run showmount.

However, there were still about 5 times it went to a high of 6-8 segments for a few minutes since I performed this fix ~20 hours ago. The duration is clearly lower and it went no higher than a max of 8 segments at one time, a big improvement. Best of all, no recording losses for the first time in ages!!!!

Perhaps the issue was with the oplocks of SMB/SAMBA, although I believe this is requested by the client, which would be either Frigate, Docker or Portainer, I am not quite sure what the client would be considered in this case. The version of NFS I use doesn't support oplocks.

Hopefully this helps at least one other person.

Nick kindly created a new build of Frigate which has an extended cache size before discarding and it has additional logging (please note this was a one off build for testing):

I (Nick did, this is a quote) have created a build at crzynik/frigate:rec-seg-20 which sets the segment count to 20 and also adds a log to put how many segments are currently stored.

Also tagging this issue in as it's a similar issue. #5818

There is a lot of useful information in that issue too, it's worth a read.

Thanks

[f1d094]

For anyone who is still wrestling with this issue, the solution for me was to completely disable swap inside the container. Despite a very capable system I had had loads of "Unable to keep up with recording segments in cache..." issues, which brought me here. Previsously I had an already conservative --memory-swappiness=1 which is now --memory-swappiness=0.

Please note that I have plenty of RAM dedicated to the container as well as hard limits on utilization so that any memory leaks leading to OOM don't bring down the system. Be sure to check your nvidia-smi, vmstat 1, iotop, iostat -sxy --human 1 1, and podman stats, etc. to make sure you don't have an unrelated issue before trying.

For anyone interested, below is my current podman run command for initializing the container. We are now humming along with 21 cameras and barely breaking a sweat:

podman run -d \
  --name frigate \
  --privileged \
  --memory=6g \
  --memory-swap=6g \
  --memory-swappiness=0 \
  --ipc=private \
  --restart unless-stopped \
  --mount type=tmpfs,target=/tmp/cache,tmpfs-size=5000000000 \
  --device /dev/bus/usb:/dev/bus/usb \
  --device nvidia.com/gpu=0 \
  --security-opt=label=disable \
  --cap-add=CAP_PERFMON \
  --shm-size 1g \
  -v /mnt/Media:/media/frigate \
  -v /opt/Frigate/config:/config \
  -v /etc/localtime:/etc/localtime:ro \
  --ip=172.30.2.2 \
  -p 8555:8555/tcp \
  -p 8555:8555/udp \
  --network=daleks-net \
  ghcr.io/blakeblackshear/frigate:stable

[NickM-27]

if you want to put up a PR to add a note of this in the troubleshooting docs that would be great

[f1d094]

Hmm...wouldn't let me create a PR because I am not a collaborator. :-/

[NickM-27]

you'll need to fork the repo and make a PR via that

[f1d094]

Ah yes. Need coffee.

[f1d094]

PR#10021 change as you see fit. Thank you for all your hard work.

[lillrynkan]

I had the same issue using an external (USB) spinning disk (2TB) that has been used to max capacity for some 2 years. I did some tests on the disk and found it did not perform fast at all (~5Mb/sec). I ended up reformatting the partition and performance was then back to normal. The disk was originally formatted with exfat. I am suspecting that the issue was heavy fragmentation on the disk. A suggestion that might be preventing this is to have an option to control the deletion of old recording so that this happens based on % instead of 1h recording since 1h recording on large volumes is a very low % and will increase fragmentation. However I think this problem is mostly affecting exfat file systems on spinning disks.

[f1d094]

I think a nice performance improvement would be to use lazy deletion regardless of FS, assuming it is supported.

@blakeblackshear: Is there a mechanism to ionice the deletes?