[BUG] 'queue=False' appears not to disable queue prepopulation

[alexw-im]

Describe the bug While using "queue=False" in i.e. config = picam2.create_still_configuration({"size": (1280, 800)}, raw={'format': 'R10'}, queue=False, controls=controls), it doesn't appear to accomplish the design intent of keeping the output buffer from pre-filling.

To Reproduce I'm using an OV9281 sensor (arducam module in this case) with a Pi 4B.

import time
from picamera2 import Picamera2, Preview
from libcamera import controls

picam2 = Picamera2()
controls = {"ExposureTime": 100000, "AnalogueGain": 1.0}
config = picam2.create_still_configuration({"size": (1280, 800)}, raw={'format': 'R10'}, queue=False, controls=controls)
picam2.configure(config)
# In fact, picam2.start() would do this anyway for us:
picam2.start_preview(Preview.NULL)

picam2.start()
time.sleep(3)


count = 0
if __name__ == '__main__':
    #r = picam2.capture_request() # Fill the buffer with an initial frame so we know the one we try to get will be fresh
    while True:
        time.sleep(1)
        count += 1
        # metadata = picam2.capture_file(f"test-{count}.jpg")
        start = time.time()
        #r.release()
        r = picam2.capture_request()
        elapsed = time.time()-start
        print(f"Elapsed: {elapsed}")
        meta = r.get_metadata()
        print(meta)
        r.save("main", f"test-{count}.jpg")
        r.release()
        # print(metadata) 
        print(f"Triggered {count}")

picam2.stop()

Expected behaviour This snippet SHOULD take one 100ms capture on-demand once per while loop, then sleep a while (a second). The idea is that I want a single frame as close to right-after-when-I-request-it as possible.

Having read 4.2.1.4 in the Picamera2 manual, I figured I'd use the queue=False option in my configuration to make sure the queue was never pre-filled with prior-to-trigger image data.

As written, the call to picam2.capture_request() should be blocking and take at least as long as the exposure. I'd expect that the "elapsed time" counter should always be >> 100ms: 100ms to expose, plus however much to read out, process, compute, update apt, check stocks, phone home, etc.

In this case, however, my "elapsed" timer SOMETIMES takes >> 100ms, and sometimes returns within single-digit milliseconds. See console output below.

Console Output, Screenshots Note below that all snapshots take well over 100ms to return, except the 3rd trigger which returns in only 4.9ms

Elapsed: 0.16357421875
{'SensorTimestamp': 7125409563000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.06434440612793, 'FocusFoM': 5392, 'ExposureTime': 99999}
Triggered 1
Elapsed: 0.1396324634552002
{'SensorTimestamp': 7126710165000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.03728675842285, 'FocusFoM': 5391, 'ExposureTime': 99999}
Triggered 2
Elapsed: 0.004918098449707031
{'SensorTimestamp': 7127810681000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.044885635375977, 'FocusFoM': 5403, 'ExposureTime': 99999}
Triggered 3
Elapsed: 0.1906599998474121
{'SensorTimestamp': 7129111285000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.053913116455078, 'FocusFoM': 5368, 'ExposureTime': 99999}
Triggered 4
Elapsed: 0.19505882263183594
{'SensorTimestamp': 7130411888000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.055377960205078, 'FocusFoM': 5328, 'ExposureTime': 99999}
Triggered 5
Elapsed: 0.19681406021118164
{'SensorTimestamp': 7131712491000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.062702178955078, 'FocusFoM': 5463, 'ExposureTime': 99999}
Triggered 6

Workaround : I believe the above is a bug: perhaps "queue=False" gets ignored if there's only one allocated memory queue, assuming that the user won't want a frame "only very occasionally"?

In any event, the following configuration of the script works around the issue by deliberately holding the queue until right before the desired capture. We start by capturing a request right before entering the loop, then from that point on we only release that request right before making a new one.

The fact that this workaround works as expected makes me think the base case is indeed buggy and I'm not simply misunderstanding usage.

import time
from picamera2 import Picamera2, Preview
from libcamera import controls

picam2 = Picamera2()
controls = {"ExposureTime": 100000, "AnalogueGain": 1.0}
config = picam2.create_still_configuration({"size": (1280, 800)}, raw={'format': 'R10'}, queue=False, controls=controls)
picam2.configure(config)
# In fact, picam2.start() would do this anyway for us:
picam2.start_preview(Preview.NULL)

picam2.start()
time.sleep(3)


count = 0
if __name__ == '__main__':
    r = picam2.capture_request() # Fill the buffer with an initial frame so we know the one we try to get will be fresh
    while True:
        time.sleep(1)
        count += 1
        # metadata = picam2.capture_file(f"test-{count}.jpg")
        start = time.time()
        r.release()
        r = picam2.capture_request()
        elapsed = time.time()-start
        print(f"Elapsed: {elapsed}")
        meta = r.get_metadata()
        print(meta)
        r.save("main", f"test-{count}.jpg")
        #r.release()
        # print(metadata) 
        print(f"Triggered {count}")

picam2.stop()

And the output. Note that the minimum elapsed capture time is 152ms:

Elapsed: 0.1956775188446045
{'SensorTimestamp': 7881759452000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.440120697021484, 'FocusFoM': 5148, 'ExposureTime': 99999}
Triggered 1
Elapsed: 0.15225839614868164
{'SensorTimestamp': 7883060059000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.417917251586914, 'FocusFoM': 5349, 'ExposureTime': 99999}
Triggered 2
Elapsed: 0.18652868270874023
{'SensorTimestamp': 7884360663000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.452198028564453, 'FocusFoM': 5353, 'ExposureTime': 99999}
Triggered 3
Elapsed: 0.19385337829589844
{'SensorTimestamp': 7885661265000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.430110931396484, 'FocusFoM': 5308, 'ExposureTime': 99999}
Triggered 4
Elapsed: 0.18757224082946777
{'SensorTimestamp': 7886961876000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.414443969726562, 'FocusFoM': 5424, 'ExposureTime': 99999}
Triggered 5
Elapsed: 0.19856715202331543
{'SensorTimestamp': 7888262469000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.442598342895508, 'FocusFoM': 5386, 'ExposureTime': 99999}
Triggered 6
Elapsed: 0.1977245807647705
{'SensorTimestamp': 7889563076000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.397911071777344, 'FocusFoM': 5296, 'ExposureTime': 99999}
Triggered 7
Elapsed: 0.2108614444732666
{'SensorTimestamp': 7890863676000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.412031173706055, 'FocusFoM': 5342, 'ExposureTime': 99999}
Triggered 8
Elapsed: 0.20072627067565918
{'SensorTimestamp': 7892164282000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.511882781982422, 'FocusFoM': 5301, 'ExposureTime': 99999}
Triggered 9
Elapsed: 0.18394255638122559
{'SensorTimestamp': 7893464881000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.493953704833984, 'FocusFoM': 5321, 'ExposureTime': 99999}
Triggered 10
Elapsed: 0.2063596248626709
{'SensorTimestamp': 7894765487000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.491409301757812, 'FocusFoM': 5355, 'ExposureTime': 99999}
Triggered 11
Elapsed: 0.19242191314697266
{'SensorTimestamp': 7896066091000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.49312400817871, 'FocusFoM': 5355, 'ExposureTime': 99999}
Triggered 12
Elapsed: 0.2053236961364746
{'SensorTimestamp': 7897366691000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.47867202758789, 'FocusFoM': 5327, 'ExposureTime': 99999}
Triggered 13
Elapsed: 0.20030546188354492
{'SensorTimestamp': 7898667300000, 'ScalerCrop': (0, 0, 1280, 800), 'DigitalGain': 1.0000009536743164, 'SensorBlackLevels': (4096, 4096, 4096, 4096), 'AeLocked': True, 'FrameDuration': 100036, 'AnalogueGain': 1.0, 'Lux': 22.511098861694336, 'FocusFoM': 5376, 'ExposureTime': 99999}
Triggered 14

Hardware : Pi 4B with ArduCam OV9281 B0165 module.

Additional context My true motive for this is to timestamp the frame capture as accurately as possible. I know that neither python nor linux are real-time and thus there are any number of preemptions that could cause jitter in my "timestamp-then-snap" delay, but I'm hunting for ways to minimize that. I know the returned "SensorTimestamp" is quite precise and accurate to the true second-shutter timing, but as far as I'm aware there's no way to accurately translate that to system time, correct? Whatever I can do to get a precise time.time() for the start/center/end of the shutter-open, I'd quite like to do, up to and including preempt_rt, but I'm not sure how dramatically that would help.