Raspiraw issue: permanent buffer delay of 1 useless frame

[Theodiy]

Hi,
I use raspiraw with picamV2 to make an automatic tool that takes long exposure pictures (>1s) for light painting.
It works well but I have one frame delay starting at the 2nd frame.
For example for a sequence of 5 frames taken I got these images :
i1 = f1
i2 = dark frame or last frame of the previous sequence ! so useless frame
i3 = f2
i4 = f3
i5 = f4

So, at high frame rate (30fps) it's not a problem because it produces only a 33ms delay and one useless image (the i2) .
But at long exposure (i.e. 1sec) I have 1sec delay between what the sensor takes and what I see !

If I send start register to the sensor earlier compared to the mmal component creation and start, I get directly the useless frame at the beginning image1 (i1) and after all the following is shifted by one image (i.e. i2=f1... so with the delay of 1 image). What does the GPU with this frame in buffer !?

I tried also some trick with the pool of buffer, I can't change the number of buffer in the pool (actually 4) without crash !
And in the mmal log I saw that only 2 buffers are really used out of the 4 created in the pool and sent to the gpu.
For exemple :

Code: Select all

mmal: Create pool of 4 buffers of size 384000
mmal: Sent buffer 0x13ba128
mmal: Sent buffer 0x13ba300
mmal: Sent buffer 0x13ba4d8
mmal: Sent buffer 0x13ba6b0
mmal: Now streaming...
mmal: Buffer 0x13ba128 returned, filled 384000, timestamp 1508538481, flags 0004
mmal: Buffer 0x13ba300 returned, filled 384000, timestamp 1508538481, flags 0084 Image1 = f1
mmal: Buffer 0x13ba4d8 returned, filled 384000, timestamp 1509735898, flags 0004
mmal: Buffer 0x13ba6b0 returned, filled 384000, timestamp 1509735898, flags 0084 Image2  = useless frame
mmal: Buffer 0x13ba128 returned, filled 384000, timestamp 1510933316, flags 0004
mmal: Buffer 0x13ba300 returned, filled 384000, timestamp 1510933316, flags 0084 Image3 = f2
mmal: Buffer 0x13ba4d8 returned, filled 384000, timestamp 1512130734, flags 0004
mmal: Buffer 0x13ba6b0 returned, filled 384000, timestamp 1512130734, flags 0084 Image4 = f3
mmal: Buffer 0x13ba128 returned, filled 384000, timestamp 1513328152, flags 0004
mmal: Buffer 0x13ba300 returned, filled 384000, timestamp 1513328152, flags 0084 Image5 = f4
mmal: Buffer 0x13ba4d8 returned, filled 384000, timestamp 1514525569, flags 0004
mmal: Buffer 0x13ba6b0 returned, filled 384000, timestamp 1514525569, flags 0084 Image6 = f5

The useless frame is annoying but I can deal with that, the major issue for me is the delay for long exposure !
Can anyone have a lead about this useless frame and delay ?

[6by9]

Assumuing it has a new buffer to swap to, the GPU returns a pair of buffers to you every time it receives a "frame end" event from the sensor. When frame ends occur is up to how you program the sensor.
Sensor startup on a rolling shutter sensor is always a funny one, as it depends on whether readout starts immediately or the reset starts first. See https://picamera.readthedocs.io/en/latest/fov.html for a decent description of how rolling shutters are really working.

I will agree that there seems to be something a little funny on that second frame. I'd need to examine logs carefully to try and track down what is going on.
There is an issue in raspiraw's splitting of big values across multiple registers - it tries to be too clever and writes the wrong thing for exposure, vts, and gain. I think I have a valid fix, but check your values very carefully there in the meantime.

I can see 4 unique buffer handles being passed around

mmal: Buffer 0x13ba128 returned, filled 384000, timestamp 1508538481, flags 0004
mmal: Buffer 0x13ba300 returned, filled 384000, timestamp 1508538481, flags 0084 Image1 = f1
mmal: Buffer 0x13ba4d8 returned, filled 384000, timestamp 1509735898, flags 0004
mmal: Buffer 0x13ba6b0 returned, filled 384000, timestamp 1509735898, flags 0084 Image2 = useless frame

All the ones with flags 0084 will be immediately returned as they are the embedded metadata (not used on IMX219 IIRC), but they are there.
A diff such as

Code: Select all

diff --git a/raspiraw.c b/raspiraw.c
index e828aed..ebcc4c0 100644
--- a/raspiraw.c
+++ b/raspiraw.c
@@ -1208,7 +1208,7 @@ int main(int argc, char** argv) {
        }
 
        output->buffer_size = output->buffer_size_recommended;
-       output->buffer_num = output->buffer_num_recommended;
+       output->buffer_num = 8; //output->buffer_num_recommended;
 
        if (cfg.capture)
        {

gives me the output

Code: Select all

mmal: Now streaming...
mmal: Buffer 0x163c148 returned, filled 384000, timestamp 671796467, flags 0004
mmal: Buffer 0x163c320 returned, filled 384000, timestamp 671796467, flags 0084
mmal: Buffer 0x163c4f8 returned, filled 384000, timestamp 672095998, flags 0004
mmal: Buffer 0x163c6d0 returned, filled 384000, timestamp 672095998, flags 0084
mmal: Buffer 0x163c8a8 returned, filled 384000, timestamp 672395529, flags 0004
mmal: Buffer 0x163ca80 returned, filled 384000, timestamp 672395529, flags 0084
mmal: Buffer 0x163cc58 returned, filled 384000, timestamp 672695062, flags 0004
mmal: Buffer 0x163ce30 returned, filled 384000, timestamp 672695062, flags 0084
mmal: Buffer 0x163c148 returned, filled 384000, timestamp 672994592, flags 0004
mmal: Buffer 0x163c320 returned, filled 384000, timestamp 672994592, flags 0084

so 8 buffers circulating with no crash. You don't say where you made the change
(I'm guessing you enlarged the pool but hadn't told the component - that will fail).

[Theodiy]

Ok thanks for the explanations!

I tried to initialize the camera and send the start register (enable streaming), wait one second, send the stop register, then initialize mmal, and again send the start register to the sensor. But I got the same issue again, the funny second frame and then normal images but delayed of 1 frame.
I tried different things around the camera like manually set a value to vts_reg and exposure_reg according to the datasheet (chap 5.5) but again the same story.

For the number of buffer, my bad ! I tried to set buffer_num<4 (to force the gpu to send me a valid buffer at the second frame) and in this case I get a crash, but with buffer_num >= 4 no crash (but always the funny second frame) !

Thanks again, I'm still trying to fix this annoying frame delay.

[Theodiy]

Hi !

I check my register values two times, all is right.
No lead about this annoying second frame !
6by9, have you find a valid fix or have you some path of research ?
Thanks

[tmorley]

All the ones with flags 0084 will be immediately returned as they are the embedded metadata (not used on IMX219 IIRC), but they are there.

FYI, it seems the embedded metadata on the IMX219 contains a bunch of registers with the settings for that frame. I've been using it as a simple bit of debugging while watching changes happen.

Usefully register 0x018 seems to have a frame counter from the sensor, and when starting a sequence I have seen the second frame being rather out of order

Tim

[6by9]

All the ones with flags 0084 will be immediately returned as they are the embedded metadata (not used on IMX219 IIRC), but they are there.

FYI, it seems the embedded metadata on the IMX219 contains a bunch of registers with the settings for that frame. I've been using it as a simple bit of debugging while watching changes happen.

Usefully register 0x018 seems to have a frame counter from the sensor, and when starting a sequence I have seen the second frame being rather out of order

Yes, you appear to be correct that IMX219 does produce embedded data (the firmware just doesn't use it), and register 0x0018 appears to be a frame counter. Decoding embedded data can be a bit of a faff, but isn't too bad. I was about to submit a firmware tweak to not return the embedded data buffers if not requested, but it sounds like there is some use for them on IMX219 and should be left enabled.

I've got various other things on, but will try to have a look at what is going on during startup. I have tried doing a memset on the start of each of the buffers to an arbitrary value, that second buffer appears to be coming back without having been written at all (both image and metadata).
I've also tried an alternate CSI2 source and that is routinely returning 2 unfilled metadata buffers at the start, but they're all at the correct time interval. It'd take something very odd to achieve that within the receiver, so I'm not excluding the sensor from being at fault here.
What I'd really like to try is a source that is producing a unique count within each frame to confirm what's going on, but I haven't got one of those currently.

I don't suppose you fancy writing a parser for the embedded data and creating a pull requrest? The format is common for almost all Bayer CSI2 sensors, although it does vary slightly between raw 8, 10, and 12 modes. It's documented in the IMX219 datasheet (Google for it).

[tmorley]

I don't suppose you fancy writing a parser for the embedded data and creating a pull requrest? The format is common for almost all Bayer CSI2 sensors, although it does vary slightly between raw 8, 10, and 12 modes. It's documented in the IMX219 datasheet (Google for it).

I've already got a simple parser embedded in the callback function, I'll clean it up a bit and create a pull request for it.

It only handles raw10 mode at the moment, but that shouldn't be difficult to fix!

Would you prefer it to just dump the registers out via vcos_log_??? or shall i create a new output file for each frame?

Tim

[6by9]

I don't suppose you fancy writing a parser for the embedded data and creating a pull requrest? The format is common for almost all Bayer CSI2 sensors, although it does vary slightly between raw 8, 10, and 12 modes. It's documented in the IMX219 datasheet (Google for it).

I've already got a simple parser embedded in the callback function, I'll clean it up a bit and create a pull request for it.
It only handles raw10 mode at the moment, but that shouldn't be difficult to fix!
Would you prefer it to just dump the registers out via vcos_log_??? or shall i create a new output file for each frame?

Thanks. vcos_log_error is fine by me, although probably under a switch to disable it to avoid spewing out too much junk.
I've copy/pasted some parsing code from the firmware into the callback to do a simple decode of the first few tags, but haven't got time to tidy it up at the moment.

[tmorley]

Thanks. vcos_log_error is fine by me, although probably under a switch to disable it to avoid spewing out too much junk.
I've copy/pasted some parsing code from the firmware into the callback to do a simple decode of the first few tags, but haven't got time to tidy it up at the moment.

There should be a pull request on the raspiraw repository now! Currently only handles raw10, but that's the default on the for an imx219 at the moment.

Tim

[6by9]

Thanks. vcos_log_error is fine by me, although probably under a switch to disable it to avoid spewing out too much junk.
I've copy/pasted some parsing code from the firmware into the callback to do a simple decode of the first few tags, but haven't got time to tidy it up at the moment.

There should be a pull request on the raspiraw repository now! Currently only handles raw10, but that's the default on the for an imx219 at the moment.

Thank you. Just reviewing it now.

[Theodiy]

Hi,

I come back with some news about this permanent delayed frame.
I try a simple main that initialize a pipeline of 3 mmal components without any callback function (each component connected between them):
vc.ril.raw -> vc.ril.isp -> vc.ril.video_render

I get a nice display with frame captured, de-bayerized and displayed only by GPU, (CPU load 0% !). Pretty cool.

But the same delay of one frame still happens (except for the first frame) : if I take frame with 3s of exposure time, I need 3s for waiting the exposure time (logic!) and 3s more (why?) to have this frame displayed !
During a stream of 3s exposure frame, if I send i2c register to the camera to stop streaming everything is stopped immediately. Then I send i2c register to start again the streaming and continue to get frame one after another with the same frame delay:
If I sketch what I got:

Code: Select all

camera | ???  | frame displayed
-------+------+----------------
  f1   |  --  |    --
  f2   |  --  |    f1
  f3   |  f2? |    darkframe
  f4   |  f3? |    f2
  f5   |  f4? |    f3
-> i2c stop cmd
       |  f4? |    f3
       |  f4? |    f3
-> i2c start cmd
  f7   |  f6? |    f4
  f8   |  f7? |    f6

So I get the frame f4 after the start cmd but I loose the frame f5 and after get the frame f6 !
I tried several camera modes, timings, numbers of channels, framerates but always this bug.
Maybe it comes from the vc.ril.rawcam component because this doesn't happen with raspivid and official raspberry camera?

[6by9]

"vcgencmd version" please to tell us what version of firmware you are using. If you haven't updated recently then please do so.

[Theodiy]

Nice ! It was that ! I had an old version of March 2018, I did an update to 4.14.71.
I thing it was corrected with the firmware bump 4.14.66 :
-> firmware: rawcam: Fix double buffer return issue

thanks !