bcm2835-camera: Fix timestamp calculation problem #2214

buddydvd · 2017-09-30T00:35:39Z

Use div_s64_rem() to convert usec timestamp to timeval to avoid integer signedness bug.

While capturing uncompressed frames with ffmpeg, I notice the bcm2835-v4l2 module generates very large negative timestamp values (e.g., -140448221.376697). These large negative values trigger a bunch of issues (e.g., DTS/PTS "invalid dropping" warnings) during capture.

ffmpeg -hide_banner -f v4l2 -input_format yuv420p -framerate 30 -i /dev/video0 -show_streams -f null -

By turning on module's debug flag, I see this in system log:

Convert start time 14389.960211 and 14393894979 with offset 14393759849 to -140448221.376697

Reading the bcm2835-camera.c carefully, I noticed the use of div_u64_rem(...) causes an integer signedness bug. For the conversion, it should be 14389.825081 Instead of -140448221.376697.

Use div_s64_rem() to convert usec timestamp to timeval to avoid integer signedness bug.

6by9 · 2017-10-02T13:40:58Z

Looks highly plausible.
The values in struct timeval appear to resolve to long, so certainly the signedness of div and rem was wrong, and therefore needs div_s64_rem.

Actually that code ought to be reworked as the actual vb2_buffer timestamp field is now a u64 taking nsecs, hence line 395 is converting the struct timeval straight back to a u64. That changed betwen 4.4 and 4.9.

I'm a little bemused as to how come you're getting a frame timestamped 135ms before we made the request. You're using yuv420 planar, but what resolution are you asking for? It's possibly another issue that needs investigating.

buddydvd · 2017-10-02T20:14:27Z

(Sorry for the typo above, should be using ffprobe instead ffmpeg.)

I found the bug while trying to figure out why this was happening. I noticed that start_pts turn positive every time I change the frame rate.

# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459272023127
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459270296572
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459268840187
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 25 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=3379884531
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 25 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459227361431
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 25 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459225620679
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=3395484761
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459213252133
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459211759103
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 25 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=3408621387
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 25 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459200382364
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 25 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459198083999
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=3424381115
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459184723692
# ffprobe -hide_banner -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -show_streams 2>&1 | grep start_pts
start_pts=-140459183221752

I reformatted the output in table form for clarity. Do you see the pattern?

fps	start_pts
30	-140459272023127
30	-140459270296572
30	-140459268840187
25	3379884531
25	-140459227361431
25	-140459225620679
30	3395484761
30	-140459213252133
30	-140459211759103
25	3408621387
25	-140459200382364
25	-140459198083999
30	3424381115
30	-140459184723692
30	-140459183221752

This is what I see when I execute ffmpeg without the fix.

# ffmpeg -f v4l2 -input_format yuv420p -video_size 1280x720 -framerate 30 -i /dev/video0 -f null -
ffmpeg version N-87326-g3ffd3b7f5f Copyright (c) 2000-2017 the FFmpeg developers
  built with gcc 6.3.0 (Raspbian 6.3.0-18+rpi1) 20170516
  configuration: --enable-omx --enable-omx-rpi
  libavutil      55. 75.100 / 55. 75.100
  libavcodec     57.106.101 / 57.106.101
  libavformat    57. 82.100 / 57. 82.100
  libavdevice    57.  8.101 / 57.  8.101
  libavfilter     6.105.100 /  6.105.100
  libswscale      4.  7.103 /  4.  7.103
  libswresample   2.  8.100 /  2.  8.100
Input #0, video4linux2,v4l2, from '/dev/video0':
  Duration: N/A, start: -140457942.655219, bitrate: 331776 kb/s
    Stream #0:0: Video: rawvideo (I420 / 0x30323449), yuv420p, 1280x720, 331776 kb/s, 30 fps, 30 tbr, 1000k tbn, 1000k tbc
Stream mapping:
  Stream #0:0 -> #0:0 (rawvideo (native) -> wrapped_avframe (native))
Press [q] to stop, [?] for help
Output #0, null, to 'pipe:':
  Metadata:
    encoder         : Lavf57.82.100
    Stream #0:0: Video: wrapped_avframe, yuv420p, 1280x720, q=2-31, 200 kb/s, 30 fps, 30 tbn, 30 tbc
    Metadata:
      encoder         : Lavc57.106.101 wrapped_avframe
DTS 140462610581692, next:33333 st:0 invalid dropping
PTS 140462610581692, next:33333 invalid dropping st:0
DTS 140462610615019, next:66666 st:0 invalid dropping
PTS 140462610615019, next:66666 invalid dropping st:0
DTS 140462610648347, next:99999 st:0 invalid dropping
PTS 140462610648347, next:99999 invalid dropping st:0
DTS 140462610681675, next:133332 st:0 invalid dropping
PTS 140462610681675, next:133332 invalid dropping st:0
DTS 140462610715001, next:166665 st:0 invalid dropping
PTS 140462610715001, next:166665 invalid dropping st:0
DTS 140462610748328, next:199998 st:0 invalid dropping
PTS 140462610748328, next:199998 invalid dropping st:0
DTS 140462610781656, next:233331 st:0 invalid dropping
PTS 140462610781656, next:233331 invalid dropping st:0
DTS 140462610814982, next:266664 st:0 invalid dropping

6by9 · 2017-10-03T11:04:00Z

A big thank you for the second update - my comment was more for my own benefit than a request to change the PR, but the update is very welcome.

Looks fine to me.
We don't have a realistic wrapping issue with s64/u64 - 2^63nsecs I reckon comes out as 106751 years!

buddydvd · 2017-10-03T18:43:26Z

Sure, no problem. Let me know if you want me to make any other changes.

6by9 · 2017-10-03T19:06:13Z

I'm good.
Ping @pelwell and @popcornmix. Any comments from you, or are you happy to merge?

popcornmix · 2017-10-04T11:43:17Z

Thanks!

kernel: brcmfmac: Avoid possible out-of-bounds read kernel: brcmfmac: Delete redundant length check kernel: brcmfmac: Add check for short event packets kernel: bcm2835-camera: Fix timestamp calculation problem See: raspberrypi/linux#2214 kernel: amba_pl011: Add cts-event-workaround DT property See: raspberrypi/linux#1280 kernel: amba_pl011: Insert mb() for correct FIFO handling kernel: brcmfmac: add CLM download support kernel: brcmfmac: request_firmware_direct is quieter

kernel: brcmfmac: Avoid possible out-of-bounds read kernel: brcmfmac: Delete redundant length check kernel: brcmfmac: Add check for short event packets kernel: bcm2835-camera: Fix timestamp calculation problem See: raspberrypi/linux#2214 kernel: amba_pl011: Add cts-event-workaround DT property See: raspberrypi/linux#1280 kernel: amba_pl011: Insert mb() for correct FIFO handling kernel: brcmfmac: add CLM download support kernel: brcmfmac: request_firmware_direct is quieter firmware: arm_loader: Add mbox call to query RSTS register See: arm_loader: Add mbox call to query RSTS register firmware: IL Camera: Add manual analog and digital gain controls firmware: video_decode: Allow stride to be >= min required firmware: IL ISP: Add white balance and digital gain to ISP component firmware: variants: drop [read|write]_[media|still] and image_[read|write]

* bcm2835-camera: Fix timestamp calculation problem Use div_s64_rem() to convert usec timestamp to timeval to avoid integer signedness bug. * bcm2835-camera: Store kernel start time in NSEC instead of USEC * bcm2835-camera: Reword debug message for clarity

…i#2214)" This reverts commit 90ac037. This has been fixed in an alternate format upstream, so adopt that. Signed-off-by: Dave Stevenson <dave.stevenson@raspberrypi.org>

This reverts commit 90ac037. This has been fixed in an alternate format upstream, so adopt that. Signed-off-by: Dave Stevenson <dave.stevenson@raspberrypi.org>

bcm2835-camera: Fix timestamp calculation problem

3192ba6

Use div_s64_rem() to convert usec timestamp to timeval to avoid integer signedness bug.

bcm2835-camera: Store kernel start time in NSEC instead of USEC

dee83b1

bcm2835-camera: Reword debug message for clarity

ab953d8

pelwell approved these changes Oct 4, 2017

View reviewed changes

popcornmix merged commit cb0f972 into raspberrypi:rpi-4.9.y Oct 4, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

bcm2835-camera: Fix timestamp calculation problem #2214

bcm2835-camera: Fix timestamp calculation problem #2214

buddydvd commented Sep 30, 2017

6by9 commented Oct 2, 2017

buddydvd commented Oct 2, 2017

6by9 commented Oct 3, 2017

buddydvd commented Oct 3, 2017

6by9 commented Oct 3, 2017

popcornmix commented Oct 4, 2017

bcm2835-camera: Fix timestamp calculation problem #2214

bcm2835-camera: Fix timestamp calculation problem #2214

Conversation

buddydvd commented Sep 30, 2017

6by9 commented Oct 2, 2017

buddydvd commented Oct 2, 2017

6by9 commented Oct 3, 2017

buddydvd commented Oct 3, 2017

6by9 commented Oct 3, 2017

popcornmix commented Oct 4, 2017