[BUG] Intermittent lens shading table not loaded (we think) when exposure value is changing.

[julianstirling]

Describe the bug
This is a intermittent bug, so it is hard to be concise. I am giving lots of details in the hope you may have an idea that helps us isolate the bug.

On the OpenFlexure Microscope we have quite a string custom lens shading table to adjust for the light coming from a microscope objective. We tend to have the main stream at a preview rate of about 0.5MP (plus a lores stream for some other algorithms). When we scan images we switch the main stream to the full sensor resolution, and we stop streaming it (streaming the lores to our client).

During the switchover sometimes we seem to have one of the lens shading tables not load into the camera, as we get either strong vignetting or sometimes weird colours plus vignetting. When we cancel the scan (switching the streams back again) everything will reload fine. This is very intermittent, it may happen one in 30 scans. There are no obvious warnings or setting changes we can poll to detect it automatically.

To Reproduce

This is where things get weird. So I cannot directly reproduce it in an easy script as of yet, but I can give some background to how we are doing things and what we have learned from testing.

We always use create_video_configuration to set up the camera. If we are in scan mode (where we see this bug) then we are using start_recording and start_encoder on the lores stream.

We always pass our control values to the controls arg of create_video_configuration. We noticed when using the PiCamera2 that if we pass an ExposureTime that was read from the camera, then the camera will always round down to the next available value. This means that over time the ExposureTime "drifts" downwards.

When we had the exposure time drifting on the PiCamera 2 we saw this bug. Suddenly the stream might be bright green and vignettetted (both in the lores stream and the captured images). We have fixed this by always requesting the controls with 1 added to ExposureTime.

We are now using the PiCamera HQ. Simply adding 1 to the ExposureTime doesn't reliably stop exposure drifting. (We have a very slow unit test to check for this, but again it wrapped up in a lot of our framework so hard to provide a minimal example). Now with the PiCamera HQ we see this bug re-appearing; we seem to be able to make it less frequent by adding 5 rather than 1 to the requested ExposureTime. But at long exposure times adding 5 doesn't stop the ExposureTime drifting.

My hope is that if we can get to the bottom of the Exposure Time drifting issue this will fix the bug I am talk about. Sorry that this is sort of a double bug report.

Console Output, Screenshots
This is a stitched microscope image with an HQ camera without the intermittent bug:

But sometimes we get something like:

Note the The images overlap by about 20%, we don't do averaging we choose at each pixel location we take the pixel directly from the image whos centre is closest to prevent spurious averaging artifacts, so this isn't a weird averaging bug.

Hardware :
This is with a Pi 4 in an OpenFlexure Microscope. We have seen this in some form with PiCamera v2, but as described above we seems to have fixed it. The above report is with the PiCamera HQ

[davidplowman]

Hi - quite a lot to unpack there!

I'm struggling a bit to understand how these two effects could be related, but no matter, I guess we'll just try and look at everything. Firstly, there's the exposure time that keeps getting smaller - at least this is understandable.

The reducing exposure time is expected behaviour. When you ask for a specific exposure time, you are guaranteed never to get a larger exposure time than you asked for. But because the exposure time is quantised into sensor lines, this never corresponds to a whole number of microseconds. So it gets rounded down to the next whole number of lines, and then reports this back as an integer number of microseconds which is also inherently inaccurate.

I can't think of an easy way round this. There's certainly an argument that we should report exposure times as floats, at which point we could say "if the requested value is within a nanosecond of a whole number of lines, we'll just go with that". But that's not a trivial change as it affects the libcamera API.

My other thought is: can you explain why you need to keep setting the exposure time. I haven't really understood that. Shouldn't it be a case of:

• AEC/AGC runs in auto for a bit.
• You query the exposure time and set that value, just once.
• Leave the AEC/AGC alone until such time as you need to set it back to auto. (You don't need to re-send anything when you change camera mode.)

I believe that each different camera mode may give you a different lower value than you requested, but when you go back to a mode you've used before, you shouldn't see any continuing drift downwards. (Let me know if that isn't true.)

As regards the other problem, that's more mysterious. Could you perhaps run it with the environment variable LIBCAMERA_LOG_LEVELS set to RPiAlsc:0 which should spit out some stuff from the lens shading algorithm. Are there any visible differences between the working/non-working cases? So far as I know, there should be a complete recalculation of lens shading tables when you change the camera mode.

Are you compiling your own libcamera or not? If you are we could consider adding in some more debug, but maybe let's try the easy debug experiment first.

[julianstirling]

Thanks David.

The sensor lines explanation is what we expected. I need to think about why this doesn't work for long exposures on the picamera HQ, but also these are longer exposures in the unit test that we wouldn't use in reality; so may be shouldn't do anything.

My other thought is: can you explain why you need to keep setting the exposure time. I haven't really understood that. Shouldn't it be a case of:

A good question. As our lighting is fixed we our own exposure time adjusting algorithm during inital calibration of a new microscope. This is then saved to a file. When the microscope is rebooted we set all of the controls. The code that does this is the code we use every time we switch the stream; as such the controls are re-specified each time we switch the stream.

I was never sure whether switching the stream configuration was guaranteed to leave configuration unchanged, so we always specified it. We may need to not send it except on first boot; and then add a settings check in. I can report if we still see the drift doing it that way.

In playing with this I have found that if we switch to a cropped mode then the LST isn't loaded. This is 100% reproducible. Which probably means we are specifying something incorrectly in the LST block? As we have a fixed illumination we only ever have one LST table (and 1 CCM matrix) in our customised tuning file, I am not sure if that is a possible culprit?

We aren't compiling libcamera; but it would be great to get more camera logging; so yes we will try with LIBCAMERA_LOG_LEVELS set to RPiAlsc:0 and report back.

[davidplowman]

Thanks for the update. My hope is that you'll find you can set the fixed exposure time just once, as it should persist across configure or switch_mode calls, but like everything, that needs to be verified! I don't know whether it's possible to record the exposure value you get after running the auto mode and making sure you re-use that (rather than re-querying the algorithm), but maybe you're doing that already.

Likewise, a configure or switch_mode should trigger the switchMode function in the lens shading algorithm, here. This really should cause the tables to be recalculated, especially when the crop changes, but hopefully the debug will give us some clues there.

[julianstirling]

That is really useful. I'll try to dig in further.

I am getting no change in logging from LIBCAMERA_LOG_LEVELS set to RPiAlsc:0 I have tried *:0 and *:4 and it is not seeming to make any change. I have checked os.environ and python sees the environment variable. I am setting them via systemd as we are running as a service.

I am forcing a sensor mode change at the moment for debugging. The only thing I have noticed so far is that setting a cropped sensor mode causes the colour gains to be totally off. I can correct the image by manually changing colour gains. I am not sure if this is because the lens shading tables are truncated? Because the tables are normalised?

[davidplowman]

Maybe running it as a service is causing the logging not to appear. Might be worth trying it as a regular user and see if that shows anything up.

It's interesting that forcing a cropped sensor mode seems to cause problems. I'll try and find a moment to try something like that and see if there's anything obvious going wrong. If you were able to create a small repeatable example along those lines, then I could try that too. Thanks!

[julianstirling]

Thanks. I'll try to make a decoupled set-up outside systemd with native PiCamera2 functions and see how much complexity I need to layer in to get the bug to reappear.

[davidplowman]

I had a go at doing captures where a switch to a cropped mode is required. First, I put a few extra debug print statements into the code to check what was going on. The command line I ran was:

rpicam-still -t 1s --mode 1332:990:10 -o test.jpg

So it will be using a full FoV mode for the 1 second preview, and then switch to the 1332x990 capture mode. At the moment where it has stopped the preview in order to change camera mode, I got the following output:

[0:25:12.355671391] [5341]  INFO Camera camera.cpp:1215 configuring streams: (0) 4056x3040-YUV420/sYCC (1) 1332x990-SBGGR10_CSI2P/RAW
[0:25:12.361212258] [5342]  INFO RPI vc4.cpp:615 Sensor: /base/soc/i2c0mux/i2c@1/imx477@1a - Selected sensor format: 1332x990-SBGGR10_1X10/RAW - Selected unicam format: 1332x990-pBAA/RAW
[0:25:12.378579751] [5350]  INFO RPiAlsc alsc.cpp:296 Alsc::switchMode: recalculate tables
[0:25:12.923045961] [5350]  INFO RPiAlsc alsc.cpp:419 Alsc::prepare: metadata updated
[0:25:12.923284592] [5350]  INFO IPARPI vc4.cpp:549 applyLS: tables applied
Still capture image received

• First we see it switching to the 1332x990 mode, as expected.
• Next the switchMode function in the ALSC algorithm has detected the change of camera FoV, and has recalculated the LS tables based on this.
• Then the new tables are passed out when we "prepare" the ISP to be run.
• And finally we see that the table has been applied to the hardware block, before a final still image is received.

Based on this I don't see anything going wrong. Though the intermittent nature of the problem does suggest that there's something a bit devious happening and that it was never going to be "quite this obvious". Note quite sure where else to look at the moment, but I'll keep mulling it over...

[julianstirling]

Thanks David, that is really helpful.

We have a bit of a release crunch for other things so it is going to be a couple of weeks before I can dig into making a dummy test script and trying to get all the logging going.

[davidplowman]

Sure, let me know as and when you might have something more to look at. The other thing to consider might be whether to build your own libcamera as we could add some extra debug in any suspicious places to see what might be different when you get a run that goes wrong.