Long delay between SW trigger and handler function.

[alexdesion]

Hello.

I am using 2 allied vision cameras with must be triggered by SW at the same time. In order to do this I have the following code:

• A controller thread, sets an event to the consumer
  frame_consumer.capture_event.set()

• The consumer wait for that event. When its set, then it SW triggers both cameras

class FrameConsumer(threading.Thread):
    def __init__(self):
        # Omitted for simplicity

    def run(self):
        self.logger.info('Thread \'AlliedVisionCamerasConsumer\' started')

        while not self._stop_event.is_set():
            self.capture_event.wait()
            self.logger.info(
                f"Consumer received event at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")
            if not self._stop_event.is_set():
                time_stamp_name = datetime.now().strftime('%Y-%m-%d-%H-%M-%S-%f') + ".jpg"
                pictures_taken = False
                picture_producer_1_taken = False
                picture_producer_2_taken = False
                self.producer_1.queued_frame = None
                self.producer_2.queued_frame = None

                while not pictures_taken:
                    if not picture_producer_1_taken:
                        self.producer_1.cam.TriggerSoftware.run()
                        self.logger.info(
                            f"Consumer trigger cam 1 at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")

                    if not picture_producer_2_taken:
                        self.producer_2.cam.TriggerSoftware.run()
                        self.logger.info(
                            f"Consumer trigger cam 2 at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")

                    while self.producer_1.queued_frame is None or self.producer_2.queued_frame is None:
                        time.sleep(0.001)
                    self.logger.info(
                        f"Consumer queued frames are not None anymore at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")

                    if not picture_producer_1_taken and self.producer_1.queued_frame.get_status() == FrameStatus.Complete:
                        picture_producer_1_taken = True
                        self.logger.info(
                            f"Consumer got pic 1 at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")
                    elif not picture_producer_1_taken:
                        self.producer_1.queued_frame = None
                        self.logger.warning(f'Picture on camera {self.cam_names[0]} incomplete1')

                    if not picture_producer_2_taken and self.producer_2.queued_frame.get_status() == FrameStatus.Complete:
                        picture_producer_2_taken = True
                        self.logger.info(
                            f"Consumer got pic 2 at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")
                    elif not picture_producer_2_taken:
                        self.producer_2.queued_frame = None
                        self.logger.warning(f'Picture on camera {self.cam_names[1]} incomplete2')

                    if picture_producer_1_taken and picture_producer_2_taken:
                        pictures_taken = True

• Each producer stores on a variable the frame when the handler function executed

class FrameProducer(threading.Thread):
    def __init__(self, cam: Camera, serial, camera_info, logger):
        threading.Thread.__init__(self)
        self.logger = logger

        self.cam = cam
        self.killswitch = threading.Event()
        self.camera_name = camera_info["name"]
        self.camera_info = camera_info
        self.serial = serial

        self.queued_frame = None

    def handler(self, cam, frame):
        self.logger.info(
            f"Producer cam {self.camera_name} started frame queueing at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")
        cam.queue_frame(frame)
        self.queued_frame = frame
        self.logger.info(
            f"Producer cam {self.camera_name} queued frame at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")

    def stop(self):
        self.killswitch.set()

    def setup_camera(self):
        try:
            # Set software trigger
            self.cam.TriggerSource.set('Software')
            self.cam.TriggerSelector.set('FrameStart')
            self.cam.TriggerMode.set('On')
            self.cam.AcquisitionMode.set('Continuous')

            self.cam.ExposureAuto.set('Off')
            self.cam.ExposureTime.set(self.camera_info["exposure"])

            self.cam.Width.set(self.camera_info["width"])
            self.cam.OffsetX.set(self.camera_info["width_offset"])

            self.cam.Height.set(self.camera_info["height"])
            self.cam.OffsetY.set(self.camera_info["height_offset"])

            self.cam.BalanceWhiteAuto.set("Off")
            self.cam.BalanceRatioSelector.set("Red")
            self.cam.BalanceRatio.set(self.camera_info["analog_red"])
            self.cam.BalanceRatioSelector.set("Blue")
            self.cam.BalanceRatio.set(self.camera_info["analog_blue"])

            self.cam.GVSPAdjustPacketSize.run()
            while not self.cam.GVSPAdjustPacketSize.is_done():
                pass

        except (AttributeError, VimbaFeatureError):
            self.logger.info('Camera {}: Failed to set Feature \'ExposureAuto\''.format(
                          self.cam.get_id()))

        pixel_formats = self.cam.get_pixel_formats()

        cv_fmts = intersect_pixel_formats(pixel_formats, OPENCV_PIXEL_FORMATS)
        color_fmts = intersect_pixel_formats(cv_fmts, COLOR_PIXEL_FORMATS)

        if color_fmts:
            self.cam.set_pixel_format(color_fmts[0])

        else:
            mono_fmts = intersect_pixel_formats(cv_fmts, MONO_PIXEL_FORMATS)

            if mono_fmts:
                self.cam.set_pixel_format(mono_fmts[0])

            else:
                raise VimbaCameraError(
                    f'Camera with serial {self.serial} does not support a OpenCV compatible format natively. Abort.')

    def run(self):
        self.logger.info('Thread \'AlliedVisionCamerasProducer({})\' started'.format(self.cam.get_serial()))

        try:
            with self.cam:
                self.setup_camera()

                try:
                    self.cam.start_streaming(self.handler)
                    self.killswitch.wait()
                finally:
                    self.cam.stop_streaming()

        except VimbaCameraError as e:
            raise VimbaCameraError(str(e))
            pass

        self.logger.info('Thread \'AlliedVisionCamerasProducer({})\' terminated'.format(self.cam.get_serial()))

The issue is related the big delay between the call to the SW trigger of each camera

                    if not picture_producer_1_taken:
                        self.producer_1.cam.TriggerSoftware.run()
                        self.logger.info(
                            f"Consumer trigger cam 1 at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")

                    if not picture_producer_2_taken:
                        self.producer_2.cam.TriggerSoftware.run()
                        self.logger.info(
                            f"Consumer trigger cam 2 at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")

and the execution of the handler function on each producer

    def handler(self, cam, frame):
        self.logger.info(
            f"Producer cam {self.camera_name} started frame queueing at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")
        cam.queue_frame(frame)
        self.queued_frame = frame
        self.logger.info(
            f"Producer cam {self.camera_name} queued frame at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}")

I added some prints in the code to really see how big this delay is. Here is the output:
2023-05-22 13:52:44,823 | INFO | Consumer received event at 2023-05-22 11:52:44.823.
2023-05-22 13:52:44,825 | INFO | Consumer trigger cam 1 at 2023-05-22 11:52:44.825.
2023-05-22 13:52:44,828 | INFO | Consumer trigger cam 2 at 2023-05-22 11:52:44.828.
2023-05-22 13:52:45,114 | INFO | Producer cam cam1 started frame queueing at 2023-05-22 11:52:45.114.
2023-05-22 13:52:45,114 | INFO | Producer cam cam1 queued frame at 2023-05-22 11:52:45.114.
2023-05-22 13:52:46,187 | INFO | Producer cam cam2 started frame queueing at 2023-05-22 11:52:46.187.
2023-05-22 13:52:46,187 | INFO | Producer cam cam2 queued frame at 2023-05-22 11:52:46.187.
2023-05-22 13:52:46,188 | INFO | Consumer queued frames are not None anymore at 2023-05-22 11:52:46.188.

As you can see, on cam1 that delay is about 300 ms from 11:52:44.825 to 11:52:45.114. On cam2 is way bigger, about 1.4 secons from 11:52:44.828 to 1:52:46.187.

What is the reason of this delay? The dalay is not caused because having 2 cameras. If I try only with one of them, it keeps constant 300 ms for cam1 and 1.4s for cam2. Both cameras are the same model, Alvium G5-500c.

Btw, trigger delay parameter is set to 0 in both cameras.

[Teresa-AlliedVision]

Do you check the timestamp of the frame object (frame.timestamp)? This shows the time of when the camera started exposing the sensor, it is essentially the time of the start of the frame.
That would be helpful to see: Is the delay between triggering and exposing the frame or between the start of exposure and receiving the frame.
What are the settings of the cameras and how are they conneced to the PC?
If the delay is always the same for each camera, then I would either assume, that the cameras are set to a long exposure time and/or that the network settings aren't optimized and a lot of resends happen.
The resends should lead to variable delays, so I would also check the feature "DeviceLinkThroughputLimit". This is the data rate of the camera in Bytes/s and should be at about 80% to 95% of the maximum, to leave some bandwidth for resends.

[alexdesion]

Thanks for your reply @Teresa-AlliedVision

I checked the time stamp of the frame inside the handler function (where I can access it).

self.logger.info(
            f"Producer cam {self.camera_name} started frame queueing at {datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]}"
            f"\n\tFrame timestamp {frame.get_timestamp()}")

And here is the output for the more delayed camera:

2023-05-23 14:00:11,275 | INFO | Consumer trigger cam 2 at 2023-05-23 12:00:11.275
2023-05-23 14:00:12,630 | INFO | Producer cam alliedV_spread_cam2 started frame queueing at 2023-05-23 12:00:12.630
Frame timestamp 2461762152200

I am not sure of how compare this timestamp with the time trigger starts.

Regarding the other topic:

• Cameras are connected to a switch on the network. The PC is directly connected to the network. Jumbo Packets are enable on PC interface.
• The exposure time for the cameras is 7977.391 µs, I reduced to 100µs and the delay stays the same, so I dont't think that's the reason of the problem.
• Cameras DeviceLinkThroughputLimit is inside the range 80% to 95%, so there is bandwidth for resends.