Regular short skips and occasional long skips (RTMP)

[psla]

0. Reviewed guide and contributing documents? (Yes/No): Yes
1. version [x.y.z, hash, other]: motion Version 4.3.1
2. installed as a package or compiled from sources [deb, rpm, git, other]: deb (dpkg)
3. standalone or part of third party [motion, MotionEyeOS, other]: motion, standalone
4. video stream source [V4L (card or USB), net cam (mjpeg, rtsp, other), mmal]: RTMP
5. hardware [x86, ARM, other]: x64
6. operating system [16.04, Stretch, etc, FreeBSD, other]: Debian Buster (10)

Problem

I am noticing occasional, frequent frame skips (it looks like 1-2 skipped frames or freeze, hard to say every 1-2 seconds), when the video is dumped in a passthrough mode. The same skips are not visible when using VLC to access the stream.

Sometimes, the recording will skip multiple seconds (e.g. jump suddenly by 5 seconds). Recorded video available upon request.

Configuration

Camera model: Reolink RLC-410
Firmware: latest ( v3.0.0.65_20071000
The computer and the cameras are hardwired, with 1gbps link.

camera_name FrontDoorCamera

# Numeric identifier for the camera.
camera_id 102

# The full URL of the network camera stream.
netcam_url rtmp://10.0.11.11/bcs/channel0_sub.bcs?channel=0&stream=0&user=viewer&password=password

# Image width in pixels.
width 640

# Image height in pixels.
height 480

netcam_highres rtmp://10.0.11.11/bcs/channel0_main.bcs?channel=0&stream=0&user=viewer&password=password
movie_passthrough on

# File name(without extension) for movies relative to target directory
movie_filename FRONTDOOR_%t-%v-%Y%m%d%H%M%S

Given that the skips/freezes are not happening in VLC, I am wondering if this is a configuration issue or a bug.

I also tried using rtmpdump with the same urls, and there are no freezes when the stream is captured using that tool.

Any help appreciated, thank you.

[Mr-Dave]

We would need to see the log (at level 7 or higher) and also do a deep dive into the resulting the frames of the mp4. The log will show the size of the memory block is being created to hold the packets. This can then be compared against the frames in the video to see if there is any correlation.

The presentation timestamps (PTS) of the video can also be inspected using ffprobe to determine whether there were actual frames missed or whether it is a problem with the timestamps.

As you would expect, there is not much processing going on in these steps so I'm not sure what could be causing it. My system runs many cameras like this without skips...Have you checked whether memory is maxed out? Is CPU maxed or spike?

You could also use ffplay and/or ffprobe directly against the high resolution streams and see if any unusual messages are reported.

[psla]

Happy to provide the logs - motion-level-7.log.gz. Camera id 102 (10.0.11.11) is the camera I used in this test. Camera 101(10.0.11.10) is offline for the purpose of this test. In this log I see the skips (& short freezes), I did not observe the skip of multiple seconds (it's less frequent)

Re ffplay/ffprobe, what is the exact command I should try?

Result of ffprobe

# ffprobe "rtmp://10.0.11.11/bcs/channel0_main.bcs?channel=0&stream=0&user=viewer&password=password"
ffprobe version 4.1.6-1~deb10u1 Copyright (c) 2007-2020 the FFmpeg developers
  built with gcc 8 (Debian 8.3.0-6)
  configuration: --prefix=/usr --extra-version='1~deb10u1' --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --arch=amd64 --enable-gpl --disable-stripping --enable-avresample --disable-filter=resample --enable-avisynth --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librsvg --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opengl --enable-sdl2 --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-shared
  libavutil      56. 22.100 / 56. 22.100
  libavcodec     58. 35.100 / 58. 35.100
  libavformat    58. 20.100 / 58. 20.100
  libavdevice    58.  5.100 / 58.  5.100
  libavfilter     7. 40.101 /  7. 40.101
  libavresample   4.  0.  0 /  4.  0.  0
  libswscale      5.  3.100 /  5.  3.100
  libswresample   3.  3.100 /  3.  3.100
  libpostproc    55.  3.100 / 55.  3.100
Input #0, flv, from 'rtmp://10.0.11.11/bcs/channel0_main.bcs?channel=0&stream=0&user=viewer&password=password':
  Metadata:
    displayWidth    : 2560
    displayHeight   : 1920
  Duration: 00:00:00.00, start: 6641.279000, bitrate: N/A
    Stream #0:0: Audio: aac (LC), 16000 Hz, mono, fltp
    Stream #0:1: Video: h264 (High), yuv420p(progressive), 2560x1920, 30 fps, 30 tbr, 1k tbn

ffplay -nodisp:

ffplay "rtmp://10.0.11.11/bcs/channel0_main.bcs?channel=0&stream=0&user=viewer&password=password"  -nodisp
ffplay version 4.1.6-1~deb10u1 Copyright (c) 2003-2020 the FFmpeg developers
  built with gcc 8 (Debian 8.3.0-6)
  configuration: --prefix=/usr --extra-version='1~deb10u1' --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --arch=amd64 --enable-gpl --disable-stripping --enable-avresample --disable-filter=resample --enable-avisynth --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librsvg --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwavpack --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opengl --enable-sdl2 --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-shared
  libavutil      56. 22.100 / 56. 22.100
  libavcodec     58. 35.100 / 58. 35.100
  libavformat    58. 20.100 / 58. 20.100
  libavdevice    58.  5.100 / 58.  5.100
  libavfilter     7. 40.101 /  7. 40.101
  libavresample   4.  0.  0 /  4.  0.  0
  libswscale      5.  3.100 /  5.  3.100
  libswresample   3.  3.100 /  3.  3.100
  libpostproc    55.  3.100 / 55.  3.100
Input #0, flv, from 'rtmp://10.0.11.11/bcs/channel0_main.bcs?channel=0&stream=0&user=viewer&password=password':
  Metadata:
    displayWidth    : 2560
    displayHeight   : 1920
  Duration: 00:00:00.00, start: 6822.988000, bitrate: N/A
    Stream #0:0: Audio: aac (LC), 16000 Hz, mono, fltp
    Stream #0:1: Video: h264 (High), yuv420p(progressive), 2560x1920, 30 fps, 30 tbr, 1k tbn
6990.23 M-A:  0.000 fd=   0 aq=    9KB vq=    0KB sq=    0B f=0/0

[Mr-Dave]

Couple of additional things.

We'd need to see an actual log that corresponds to when the issue occurs. Having the camera disconnected means the log isn't of value. The resulting video associated with the log demonstrating the issue would also be needed.

You may also want to check the frame rates by executing a ffprobe on the low resolution stream of the camera. Make sure it is also at 30 fps like the high resolution stream.

Try setting the high resolution stream at a lower resolution and see if the issue still exists.

[psla]

We'd need to see an actual log that corresponds to when the issue occurs. Having the camera disconnected means the log isn't of value. The resulting video associated with the log demonstrating the issue would also be needed.

To clarify. I have two cameras. I unplugged one and left only one plugged in (in hindsight, I should've just removed config for the first one - I will repeat that tonight). The camera that was left plugged in (102) did demonstrate the issue and the logs are captured at the time of the issue (or shortly after).

You may also want to check the frame rates by executing a ffprobe on the low resolution stream of the camera. Make sure it is also at 30 fps like the high resolution stream.

This will be difficult. My camera does not allow me to set it to high framerate (4, 7, 10, 15), and the maximum bitrate for low resolution stream is 512kbps. I can lower the high resolution framerate, and maybe the 15fps would be sufficient... But I am not sure how good the low resolution stream will be at 15 fps.

Can you clarify why setting the same framerate would potentially help?

Also, I am considering, as a workaround, using rtmpdump in on on_event_start and on_event_end. WDYT? Any concerns with this approach? My only concern is the buffer in front -- it seems that motion records a couple of seconds earlier before the motion is detected -- is that intentional, or accidental?

[psla]

• I disabled the offline camera, I left only one camera (online)
• I removed the logs, restarted motion,
• I moved a bit in front of the camera.

Skips/freezes are still happening.

In addition, I added the following script to on_event_start and on_event_end (they are just an example, not foolproof)

on_event_start

#!/bin/bash

set -e

# Stop previous recording
cameraid=$1
stream=$2
output=/mnt/oldnas/motion/rtmpdump
pidfile=/mnt/oldnas/motion/rtmpdump/$cameraid.pid

cat $pidfile | xargs -r kill

outputfilename=$output/`date +'%Y-%m-%d_%H_%M_%S'`_$cameraid.rtmp
rtmpdump -r $stream -o $outputfilename 2>/dev/null &
echo $! > $pidfile

on_event_end

#!/bin/bash

set -e

# Stop previous recording
cameraid=$1
pidfile=/mnt/oldnas/motion/rtmpdump/$cameraid.pid

cat $pidfile | xargs -r kill
truncate -s 0 $pidfile

Observations

• rtmpdump - no freezes. It includes audio (yay!)
• the mp4 produced by motion has freezes/skipped frames

I am going to continue running my modified script to monitor for the long jumps (e.g. where there is a jump in frames that skips 5 seconds on video).

This is the level-7 log:
motion-level-7.log.gz

Videos available upon request in private.

I have not tried putting the low-resolution stream and high-resolution stream at the same FPS. I am not sure how this is relevant - ideally I want to keep low resolution stream at low fps (e.g. 4 or 7), just to match motion's detection fps (which I believe is set to something like 3 fps by default?)

[Mr-Dave]

Seems like you have a workaround and I am unable to replicate or diagnose from here so I am closing issue.

In addition to the other things I suggested, I noticed in the log that a mount is being used for the target_dir. If that is slow it would affect the capture/writing. Motion alternates on the same thread between reading and writing so delays in the writing would affect the capture rate.

[psla]

Thanks mr-dave.

My /mnt contains a raid+1 always on spinning drive that don't do anything else but record the video. They have plenty of bandwidth, and this shouldn't be an issue.

The workaround is not ideal -- it feels like the recording is starting too late (I am under the impression that motion has some buffer before the motion is detected? or is this not the case?)

I would be happy to provide whatever data is needed to figure it out.

I have run the following command

sudo -u motion ffmpeg -i "rtmp://10.0.11.11/bcs/channel0_main.bcs?channel=0&stream=0&user=viewer&password="  -vcodec copy -acodec copy output.rtmp.mp4

and observed following entries:

[mp4 @ 0x558db8c3bdc0] Non-monotonous DTS in output stream 0:0; previous: 120615664, current: 120607136; changing to 120615665. This may result in incorrect timestamps in the output file.

(I have observed these entries with cameras from two different manufacturers, so I am assuming that's normal, though disappointing).

I have also observed

[flv @ 0x558db86dc840] DTS 373690346 < 373690879 out of order

The RTSP stream looks worse, but I am using RTMP in motion

[mp4 @ 0x5559c8e67240] Timestamps are unset in a packet for stream 0. This is deprecated and will stop working in the future.

and

[mp4 @ 0x5559c8e67240] Non-monotonous DTS in output stream 0:0; previous: 121410361, current: 121402743; changing to 121410362. This may result in incorrect timestamps in the output file.

and

[rtsp @ 0x5559c8e0e840] max delay reached. need to consume packet
[rtsp @ 0x5559c8e0e840] RTP: missed 12 packets
[rtsp @ 0x5559c8e0e840] max delay reached. need to consume packet
[rtsp @ 0x5559c8e0e840] RTP: missed 2 packets

Let me know if you've seen any of these. The missing packets are worrying, and frankly sound impossible. Both camera and the computer are hardwired, the camera has a dedicated network cable, and the computer has a 10gb connection to the switch, and the switch is not reporting any collisions.