search

TheImagingSource / ic4-examples

IC4 Example Programs
Apache License 2.0
5 stars 3 forks source link

stream_statistics frame missings ? #6

Closed benjaminforest closed 7 months ago

benjaminforest commented 7 months ago

Hi,

I'm trying to use grabber.stream_statistics to know if I'm missing frames, but I don't understand the results I'm getting from it. Sometimes a frame is missed, and i get the following stats:

Grabber.StreamStatistics(device_delivered=1000, device_transmission_error=0, device_underrun=0, transform_delivered=0, transform_underrun=0, sink_delivered=999, sink_underrun=0, sink_ignored=0)

My question is : where is my missing frame if it doesnt appear in stats but has been delivered by device ? Did I miss something in the documentation?

Another question : device_delivered does not seem to be more than allocated buffers in sink. Why is that ?

All the best,

The following code reproduce the problem on my PC:

import sys
import time

import imagingcontrol4 as ic4

def sleep_ns(duration):
    now = time.perf_counter_ns()
    end = now + duration
    while now < end:
        now = time.perf_counter_ns()

class MyListener(ic4.QueueSinkListener):
    def __init__(self):
        pass

    def sink_connected(self, sink: ic4.QueueSink, image_type: ic4.ImageType, min_buffers_required: int) -> bool:
        # Just accept whatever is passed
        sink.alloc_and_queue_buffers(2000)
        return True

    def sink_disconnected(self, sink: "QueueSink"):
        print("Disconnected !!")

    def frames_queued(self, sink: ic4.QueueSink):
        pass

ic4.Library.init(api_log_level=ic4.LogLevel.INFO, log_targets=ic4.LogTarget.STDERR)

for _ in range(20):

    device_list = ic4.DeviceEnum.devices()
    found_dev = None
    for dev in device_list:
        print(f"{dev.model_name} ({dev.serial}) [{dev.interface.display_name}]")
        if dev.model_name == "DMM 37UX265-ML":
            found_dev = dev
    if found_dev is None:
        print("No device matching foound")
        sys.exit(1)
    grabber = ic4.Grabber()
    grabber.device_open(found_dev)

    grabber.device_property_map.set_value(ic4.PropId.USER_SET_SELECTOR, "Default")
    grabber.device_property_map.execute_command(ic4.PropId.USER_SET_LOAD)

    grabber.device_property_map.set_value(ic4.PropId.PIXEL_FORMAT, ic4.PixelFormat.Mono16)

    grabber.device_property_map.set_value(ic4.PropId.WIDTH, 1024)
    grabber.device_property_map.set_value(ic4.PropId.HEIGHT, 768)

    grabber.device_property_map.set_value(ic4.PropId.BINNING_VERTICAL, 2)
    grabber.device_property_map.set_value(ic4.PropId.BINNING_HORIZONTAL, 2)

    grabber.device_property_map.set_value(ic4.PropId.OFFSET_AUTO_CENTER, "Off")
    grabber.device_property_map.set_value(ic4.PropId.OFFSET_X, 0)
    grabber.device_property_map.set_value(ic4.PropId.OFFSET_Y, 0)

    grabber.device_property_map.set_value(ic4.PropId.EXPOSURE_AUTO, "Off")
    grabber.device_property_map.set_value(ic4.PropId.EXPOSURE_TIME, 500) # microseconds

    grabber.device_property_map.set_value(ic4.PropId.GAIN_AUTO, "Off")
    grabber.device_property_map.set_value(ic4.PropId.GAIN, 0) # dB

    grabber.device_property_map.set_value(ic4.PropId.GAMMA, 1)

    fps = grabber.device_property_map[ic4.PropId.ACQUISITION_FRAME_RATE].maximum
    interval_ns = (1/fps)*1e9

    grabber.device_property_map.set_value(ic4.PropId.ACQUISITION_FRAME_RATE, grabber.device_property_map[ic4.PropId.ACQUISITION_FRAME_RATE].maximum)

    grabber.device_property_map.set_value(ic4.PropId.TRIGGER_MODE, "On") # allow to trigger images acquisition

    listener = MyListener()
    sink = ic4.QueueSink(listener, [ic4.PixelFormat.Mono16])

    grabber.stream_setup(sink, setup_option=ic4.StreamSetupOption.ACQUISITION_START)

    # time.sleep(1) # not working otherwise, probably initializing things

    for _ in range(2000):
        sleep_ns(interval_ns)
        grabber.device_property_map.set_value(ic4.PropId.TRIGGER_SOFTWARE, True)  # Trig image acquisition

    time.sleep(1)

    print(f"stream stats : {grabber.stream_statistics}")

    grabber.acquisition_stop()
    grabber.device_close()
TIS-Tim commented 7 months ago

Hi Benjamin,

the device_deliveredcounter is incremented when the driver delivers the frame to ic4, but the sink counters are only updated once the sink has handled the image (and ultimately decided which counter to increment). So what you see is probably not really a missed frame, but a frame that is just happening at the same time you ask for the counters. (Now that I see your code, do you see the 999/1000 counters even with the sleep before querying statistics?)

In a sense, the "success" counters (device_delivered, transform_delivered, sink_delivered) are not really important. The error counters indicate problems and are what one should really evaluate.

Regarding the second question: device_deliveredwill be limited to the number of allocated buffers if you do not allow the buffers to be requeued. In the general case, there are no hidden copy operations, the buffers you get from the sink are physically the same buffers that were queued into the driver.

Since you never pop buffers from the sink's output queue, after triggering 2000 images, all 2000 images are in the sink's output queue and the data stream effectively stops because of buffer starvation.

If you would trigger a few more frames once more after the loop, I would totally expect device_underrunto increment.

benjaminforest commented 7 months ago

Hi, thanks for the quick and complete answer !

The problem is that, as you said, I happen to see the stats after waiting a considerable time, so I don't think my frame is between device and sink.

If I add, as you suggest, a few more triggers after my buffer is full, I see the following: stream stats : Grabber.StreamStatistics(device_delivered=<2001 or 2000 depending on the try>, device_transmission_error=0, device_underrun=0, transform_delivered=0, transform_underrun=0, sink_delivered=2000, sink_underrun=0, sink_ignored=0) So no underrun, which surpises me also. Maybe I'm encountering a dead lock or something ? How do I allow to requeue buffers ?

Do you know of another way to check for buffer starvation ?

Maybe I'm pushing the system a bit, but I was performing integration tests and set rough values ...

TIS-Tim commented 7 months ago

I did a quick check with a different USB camera (don't have your model around) and it looks like there is indeed something wrong with the device_underrun count. Will investigate next week.

I did not see the inconsistent sink_delivered though, my output always is Grabber.StreamStatistics(device_delivered=2000, device_transmission_error=0, device_underrun=0, transform_delivered=0, transform_underrun=0, sink_delivered=2000, sink_underrun=0, sink_ignored=0). But it is certainly possible that this depends on the timing of the specific camera, so I also have to verify that on Monday.

TIS-Tim commented 7 months ago

Totally ignored your question on how to requeue buffers:

First step is to take ownership of the filled buffer(s) by calling sink.pop_output_buffer(). The returned buffer object is then owned by your program. To allow reuse, just let go of that object (or explicitly call .release() on it); it will then automatically be requeued for future use.

TIS-Tim commented 7 months ago

Hi Benjamin,

several things going on here: Because of the way USB works, the driver cannot detect that there are frames transmitted without having buffers available. That is the reason for it not counting up device_underrun if you trigger more images that there are buffers available.

Additionally, it looks like the 37U series can unexpectedly drop an additional frame if a lack of driver buffers causes the camera's internal buffers to overflow. This will likely be fixed in the future, but for now I can only recommend to avoid letting the driver run out of buffers (which is a good recommendation in any case).

benjaminforest commented 7 months ago

I did a quick check with a different USB camera (don't have your model around) and it looks like there is indeed something wrong with the device_underrun count. Will investigate next week.

I did not see the inconsistent sink_delivered though, my output always is Grabber.StreamStatistics(device_delivered=2000, device_transmission_error=0, device_underrun=0, transform_delivered=0, transform_underrun=0, sink_delivered=2000, sink_underrun=0, sink_ignored=0). But it is certainly possible that this depends on the timing of the specific camera, so I also have to verify that on Monday.

I'm not surprised, it is not very hard to reproduce with my device, but I still have to make a few try to get the result, so adding the host and setup difference ...

benjaminforest commented 7 months ago

Hi Benjamin,

several things going on here: Because of the way USB works, the driver cannot detect that there are frames transmitted without having buffers available. That is the reason for it not counting up device_underrun if you trigger more images that there are buffers available.

Additionally, it looks like the 37U series can unexpectedly drop an additional frame if a lack of driver buffers causes the camera's internal buffers to overflow. This will likely be fixed in the future, but for now I can only recommend to avoid letting the driver run out of buffers (which is a good recommendation in any case).

OK thanks, I'll ensure that.

benjaminforest commented 7 months ago

Thanks a lot for all this feedback. I'm still encountering missed frames, that I don't understand. To summarize:

TIS-Tim commented 7 months ago

USB can detect underrun, but only after the next frame has been received successfully. The driver will see the gap in frame numbers and increase one of the error counters then.

In my system, your program always outputs device_delivered=2000, sink_delivered=2000; I don't quite understand what is going wrong when you test this.

Do you have a very slow/small/busy computer, that can have unexpected scheduling? What is the serial number and firmware version of your camera?

Regarding the 37U-specific oddity: Just make sure to never artificially starve the driver/camera of buffers. Even your original program does not show the issue, only after I modified it to provoke actual device_underrun drops it became visible.

benjaminforest commented 7 months ago

Thanks again for your time.

My testing PC is not that slow (core i7 11th gen, 32G of RAM),

Here are my camera infos: Model : "DMM 37UX265-ML" Driver : 1.0.0.224 Serial: 17020004 Device version : IMX265_M.MX/2396/1070 USB3mx-IMX-GS4/1

Could you share your version of the program ? I thinks there are things I did not understand with the way driver is using buffers. For example, it seems that deleting a QueueSink does not free the attached buffers ? Maybe there is a documentation about that ? Is it particular to your implementation, or any genicam doc should be enough ?

benjaminforest commented 7 months ago

For example, If I check the state after a stream stop, I see that all my driver buffer are full (device_delivered=2000), even when before the stream stop it is annoucing (device_delivered=0). What is hapenning when I stop the stream that triggers this ?

TIS-Tim commented 7 months ago

I am testing with exactly the same code; just the camera name exchanged to a (very similar) camera I have.

But: Once I downgraded to the same driver version, I started to see instances of 2000/1999. Can you try the newer version? It is available here: https://www.theimagingsource.com/en-us/support/download/ic4gentlprodu3vwintis-1.1.0.373/

The values from Grabber.stream_stats are counters for the currently active data stream and therefore reset when Grabber.stream_setup is called. They do not reflect the current buffer usage. To get information on where the buffers are, you can use QueueSink.queue_sizes.

Do you indeed see device_delivered decrease before calling stream_setup again?

Buffer memory is freed when no longer required. That means, the stream has to be stopped, and either the sink is destroyed or all buffers are taken out of the sink and released for requeue (which after stream stop frees the buffer).

benjaminforest commented 7 months ago

Tried with the new driver version and now my tests passed twice in a row, which never happened before ! :) Thanks for the help, I'll close the issue.

benjaminforest commented 7 months ago

Sorry to bother you again, but now I encounter another related problem : from time to time I receive 0 frames when doing the test below:

import sys
import time

import imagingcontrol4 as ic4

def sleep_ns(duration):
    now = time.perf_counter_ns()
    end = now + duration
    while now < end:
        now = time.perf_counter_ns()

class MyListener(ic4.QueueSinkListener):
    def __init__(self):
        pass

    def sink_connected(self, sink: ic4.QueueSink, image_type: ic4.ImageType, min_buffers_required: int) -> bool:
        # Just accept whatever is passed
        sink.alloc_and_queue_buffers(2000)
        return True

    def sink_disconnected(self, sink: "QueueSink"):
        print("Disconnected !!")

    def frames_queued(self, sink: ic4.QueueSink):
        pass

ic4.Library.init(api_log_level=ic4.LogLevel.INFO, log_targets=ic4.LogTarget.STDERR)

device_list = ic4.DeviceEnum.devices()
found_dev = None
for dev in device_list:
    print(f"{dev.model_name} ({dev.serial}) [{dev.interface.display_name}]")
    if dev.model_name == "DMM 37UX265-ML":
        found_dev = dev
if found_dev is None:
    print("No device matching foound")
    sys.exit(1)
grabber = ic4.Grabber()
grabber.device_open(found_dev)

grabber.device_property_map.set_value(ic4.PropId.USER_SET_SELECTOR, "Default")
grabber.device_property_map.execute_command(ic4.PropId.USER_SET_LOAD)

grabber.device_property_map.set_value(ic4.PropId.PIXEL_FORMAT, ic4.PixelFormat.Mono16)

grabber.device_property_map.set_value(ic4.PropId.WIDTH, 1024)
grabber.device_property_map.set_value(ic4.PropId.HEIGHT, 768)

grabber.device_property_map.set_value(ic4.PropId.BINNING_VERTICAL, 2)
grabber.device_property_map.set_value(ic4.PropId.BINNING_HORIZONTAL, 2)

grabber.device_property_map.set_value(ic4.PropId.OFFSET_AUTO_CENTER, "Off")
grabber.device_property_map.set_value(ic4.PropId.OFFSET_X, 0)
grabber.device_property_map.set_value(ic4.PropId.OFFSET_Y, 0)

grabber.device_property_map.set_value(ic4.PropId.EXPOSURE_AUTO, "Off")
grabber.device_property_map.set_value(ic4.PropId.EXPOSURE_TIME, 500) # microseconds

grabber.device_property_map.set_value(ic4.PropId.GAIN_AUTO, "Off")
grabber.device_property_map.set_value(ic4.PropId.GAIN, 0) # dB

grabber.device_property_map.set_value(ic4.PropId.GAMMA, 1)

fps = grabber.device_property_map[ic4.PropId.ACQUISITION_FRAME_RATE].maximum
interval_ns = (1/fps)*1e9 + 0.1*1e9

grabber.device_property_map.set_value(ic4.PropId.ACQUISITION_FRAME_RATE, grabber.device_property_map[ic4.PropId.ACQUISITION_FRAME_RATE].maximum)

grabber.device_property_map.set_value(ic4.PropId.TRIGGER_MODE, "On")  # allow to trigger images acquisition

invalid_stats = 0
loop_count = 1000
trigger_count = 5
for _ in range(loop_count):

    print(f"New acquisition")

    listener = MyListener()
    sink = ic4.QueueSink(listener, [ic4.PixelFormat.Mono16])

    grabber.stream_setup(sink, setup_option=ic4.StreamSetupOption.ACQUISITION_START)

    assert grabber.is_acquisition_active
    assert grabber.is_streaming
    assert grabber.is_device_valid

    for _ in range(trigger_count):
        sleep_ns(interval_ns)
        grabber.device_property_map.set_value(ic4.PropId.TRIGGER_SOFTWARE, True)  # Trig image acquisition

    stats = grabber.stream_statistics
    if stats.device_delivered == 0 or stats.device_delivered != stats.sink_delivered:
        invalid_stats += 1
        print(f"stats : {grabber.stream_statistics}")

    grabber.acquisition_stop()
    grabber.stream_stop()

grabber.device_close()
print(f"Finished demo - {loop_count} loops of {trigger_count} trigger each. Problematic stats count : {invalid_stats}")

Any idea how I could debug this Issue ?

benjaminforest commented 7 months ago

nb: I also missed some frames but they are counted in device_transmission_error, so I think this is good enough since I know where it is :).

TIS-Tim commented 7 months ago

No bother at all, happy for more scrutiny which eventually will lead to better software.

How often do you see those anomalities like 0 images?

Beware that querying grabber.stream_statistics immediately after issuing the software trigger is a race; the image is still being transmitted at this point and the counters may or may not have been incremented yet.

Wireshark can be a great tool for diagnosing what a camera is actually doing, filtering by "u3v" works, and their packet dissector is quite good.

benjaminforest commented 7 months ago

Anomalities like 0 images happens quite often in my example, something like 1 on 5 try or a little less. I'll try to get more feedback with wireshark, this is maybe linked with my usb configuration ...

TIS-Tim commented 7 months ago

1 on 5 tries of running a 1000 loops? Or ~200 failures when running 1000 loops?

benjaminforest commented 7 months ago

demo_failure.zip Attached the wireshark capture. You can see that every 0.5s, 5 stream packet are sent as scripted, but the last one doesn't. I'll try to dig, but I'm not an usb protocol expert.

benjaminforest commented 7 months ago

1 on 5 tries of running a 1000 loops? Or ~200 failures when running 1000 loops? I don't run the full loop, but yes it would be 100-200 errors for the full loop

benjaminforest commented 7 months ago

Another wonder : I suppose this is normal ? image I may have both drivers installed

benjaminforest commented 7 months ago

And do you know where I found the genicam file for my camera ? I think There is one xml file describing adresses and so on ?

TIS-Tim commented 7 months ago

That log certainly looks surprising. On my computer, your script can run 1000 loops with only one false-positive logged (probably because of the trigger/query race).

Which USB controller/port do you use? Switching from front to back (or just to a different back port) has magically fixed stuff in the past.

Having both drivers installed is perfectly normal. While in theory a DirectShow program could then interfere with the operation of the U3V driver, there is no indication of that in the wireshark capture.

To get to the GenICam file, you can use ic4-demoapp. Select Device->Driver Properties, then switch to Guru. Under "Debug Control", there is a command button to save the document.

benjaminforest commented 7 months ago

Thanks for the file. I tried by plugging my camera to another superspeed port, but I still encounter the problem. Maybe there is an update of the camera firmware needed as well ?

benjaminforest commented 7 months ago

I try to explain the failing by coloring things using genicam xml provided adresses.

Appart from the stream payloads, I don't see a clear difference at the moment

failing_sequence successful sequence

benjaminforest commented 7 months ago

I tested on my laptop : I don't manage to reproduce the problem. This is probably linked to our integration PC... Thanks again for your help