bcm2835-camera.c: bug in timestamp computation

[dgoel]

I'm using the official raspberry pi camera (connected to CSI connector) with second gen rpi, and I'm using v4l2 API to capture a camera frame on demand. However, the timestamp assigned to the received camera frame buffer (struct v4l2_buffer) is consistently around ~900ms in the past. The requested frame resolution is 640x480.

Digging through the camera driver, I noticed the following line, which tries to add the offset from the delay in capturing the frame from GPU:

https://github.com/raspberrypi/linux/blob/rpi-4.1.y/drivers/media/platform/bcm2835/bcm2835-camera.c#L362

Specifically,

                div =
                    div_u64_rem(runtime_us, USEC_PER_SEC, &rem);
                buf->vb.v4l2_buf.timestamp.tv_sec =
                    dev->capture.kernel_start_ts.tv_sec - 1 +
                    div;
                buf->vb.v4l2_buf.timestamp.tv_usec =
                    dev->capture.kernel_start_ts.tv_usec + rem;

I don't understand why 1 is being subtracted from tv_sec, and possibly explains the approx. 1 second delay in timestamp that I'm seeing. Can someone more familiar with the camera driver explain this? If this is a bug, the following patch should fix the issue (I can provide a pull request if needed):

--- a/drivers/media/platform/bcm2835/bcm2835-camera.c
+++ b/drivers/media/platform/bcm2835/bcm2835-camera.c
@@ -360,8 +360,7 @@ static void buffer_cb(struct vchiq_mmal_instance *instance,
                div =
                    div_u64_rem(runtime_us, USEC_PER_SEC, &rem);
                buf->vb.v4l2_buf.timestamp.tv_sec =
-                   dev->capture.kernel_start_ts.tv_sec - 1 +
-                   div;
+                    dev->capture.kernel_start_ts.tv_sec + div;
                buf->vb.v4l2_buf.timestamp.tv_usec =
                    dev->capture.kernel_start_ts.tv_usec + rem;

[6by9]

That does look quirky to say the least. Running some dummy numbers through I think I agree with you.
It was a while ago that this was written so my memory is a tad sketchy, and it may be inherited code that was taken as correct.

I think they were trying to handle one of the arithmetic wrapping conditions (handling secs and usecs is awkward - kernel 4.5 switches to raw usecs), but have got it wrong. Lines 368-372 do it properly.

If you could enable the debug logging(*) and provide a sample set of the log lines from line 374 ("Convert start time....") then I'd be happier to confirm it with that. Otherwise I'll try it for myself tonight.
My concern is that you say it is ~900ms in the past, so add a second and we're now in the future which is also clearly wrong.

(*) load with "sudo modprobe bcm2835-v4l2 debug=1", or there's a kernel parameter under /sys that you can modify but I can never remember the path to it.

[dgoel]

Here's the output:

[82532.975953] bcm2835-v4l2: Convert start time 82507.570148 and 82509979570 with offset 82535357714 to 82531.948292
[82532.976054] bcm2835-v4l2: buffer_prepare: dev:a4438800
[82532.976073] bcm2835-v4l2: buffer_queue: dev:a4438800 buf:ab653000
[82533.009019] bcm2835-v4l2: buffer_cb: status:0, buf:ab651800, length:460800, flags 4, pts 82535391029
[82533.009048] bcm2835-v4l2: Convert start time 82507.570148 and 82509979570 with offset 82535391029 to 82531.981607
[82533.009711] bcm2835-v4l2: buffer_prepare: dev:a4438800
[82533.009735] bcm2835-v4l2: buffer_queue: dev:a4438800 buf:ab651800
[82533.042442] bcm2835-v4l2: buffer_cb: status:0, buf:ab653000, length:460800, flags 4, pts 82535424345
[82533.042471] bcm2835-v4l2: Convert start time 82507.570148 and 82509979570 with offset 82535424345 to 82532.014923
[82533.042562] bcm2835-v4l2: buffer_prepare: dev:a4438800
[82533.042581] bcm2835-v4l2: buffer_queue: dev:a4438800 buf:ab653000
[82533.077878] bcm2835-v4l2: buffer_cb: status:0, buf:ab651800, length:460800, flags 4, pts 82535457661
[82533.077909] bcm2835-v4l2: Convert start time 82507.570148 and 82509979570 with offset 82535457661 to 82532.048239
[82533.110347] bcm2835-v4l2: buffer_cb: status:0, buf:ab653000, length:460800, flags 4, pts 82535490976
[82533.110375] bcm2835-v4l2: Convert start time 82507.570148 and 82509979570 with offset 82535490976 to 82532.081554

If you add the GPU offset, it's fairly obvious that the computed time is ~1 sec in the past.

After adding back the second, the timestamp would actually reflect when the start of frame interrupt is received by the GPU (captured by pts). You can easily verify this from the above log messages. For example, take the last time. The message at 82533.110375 shows that the frame timestamp is 82532.081554. If you add a second to the latter, you get 82533.081554. This means that the frame capture was started ~28.8 ms ago (with respect to when the message is printed), which seems much more reasonable.

BTW, I did a grep of div_u64_rem() in the media sub-directory of the source tree and found that the same bug is present here:

https://github.com/raspberrypi/linux/blob/rpi-4.1.y/drivers/media/usb/uvc/uvc_video.c#L679

[6by9]

Agreed with both your debug and patch. Happy to approve a PR for it.

Quite plausibly that code was copied from UVC - it looks like it was me who added that code, but I have no memory of it. It was November 2013!

PTS from the GPU is from the frame start interrupt, so 29ms sound pretty reasonable for VGA. It'll take 23ms to get the rest of the frame in as the mode runs at a max of 42fps, so I'm quite chuffed at only another 6ms to get the frame completed and shipped across to the kernel.