Software trigger doesn't always work

Based on the code snippet provided by @NiklasKroeger-AlliedVision in this comment we implemented our images acquisition relying on the software trigger.

Now we have noticed that sometimes after releasing the trigger (cam.TriggerSoftware.run()) the callback (frame_callback) doesn't get called.

We don't know if an image get actually grabbed or not, but would guess not because the Frame Id is always consecutive. We have observed this behavior with different cameras on different systems (desktops and embedded). Note: in the example we changed the sleep to 0.5 seconds. With 1s or higher, we could also observe the problem but less frequently.

Is this a known issue or are we using this feature wrongly? Thank you very much for any help.

This is a modified snippet with a print after cam.TriggerSoftware.run() and some timing informations:

import vimba
import time

from PySide2.QtCore import QElapsedTimer, QTime

elapsedTimer = QElapsedTimer()

def frame_callback(cam: vimba.Camera, frame: vimba.Frame):
    # Called every time a new frame is received. Perform image analysis here
    print('{} - {} acquired {} after {} ms'.format(QTime.currentTime().toString('mm:ss.zzz'), cam, frame, elapsedTimer.elapsed()), flush=True)
    # Hand used frame back to Vimba so it can store the next image in this memory
    cam.queue_frame(frame)

def setup_software_triggering(cam: vimba.Camera):
    # Always set the selector first so that folling features are applied correctly!
    cam.TriggerSelector.set('FrameStart')

    # optional in this example but good practice as it might be needed for hadware triggering
    cam.TriggerActivation.set('RisingEdge')

    # Make camera listen to Software trigger
    cam.TriggerSource.set('Software')
    cam.TriggerMode.set('On')

with vimba.Vimba.get_instance() as vmb:
    cams = vmb.get_all_cameras()
    with cams[0] as cam:
        setup_software_triggering(cam)
        try:
            # Tell the camera to start streaming. The first frame will be recorded when the software
            # trigger is executed
            cam.start_streaming(handler=frame_callback)
            # example loop to record 10 images and then stop.
            for _ in range(10000):
                elapsedTimer.restart()
                cam.TriggerSoftware.run()
                print('{} - Time after trigger run {} ms'.format(QTime.currentTime().toString('mm:ss.zzz'), elapsedTimer.elapsed()), flush=True)
                time.sleep(0.5)
        finally:
            cam.stop_streaming()
        print("done")

And this an example output with a "double" trigger with only one grabbed frame:

41:39.130 - Time after trigger run 1 ms
41:39.254 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=47, status=FrameStatus.Complete, buffer=0x7ff6e550a010) after 126 ms
41:39.632 - Time after trigger run 1 ms
41:39.757 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=48, status=FrameStatus.Complete, buffer=0x7ff6e4963010) after 126 ms
41:40.134 - Time after trigger run 1 ms
41:40.259 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=49, status=FrameStatus.Complete, buffer=0x7ff6db459010) after 126 ms
41:40.636 - Time after trigger run 1 ms
41:40.760 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=50, status=FrameStatus.Complete, buffer=0x7ff6e6c58010) after 125 ms
41:41.137 - Time after trigger run 1 ms
41:41.639 - Time after trigger run 1 ms
41:41.764 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=51, status=FrameStatus.Complete, buffer=0x7ff6e60b1010) after 126 ms
41:42.141 - Time after trigger run 1 ms
41:42.266 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=52, status=FrameStatus.Complete, buffer=0x7ff6e550a010) after 125 ms
41:42.642 - Time after trigger run 1 ms
41:42.767 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=53, status=FrameStatus.Complete, buffer=0x7ff6e4963010) after 125 ms
41:43.145 - Time after trigger run 1 ms
41:43.269 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=54, status=FrameStatus.Complete, buffer=0x7ff6db459010) after 126 ms
41:43.647 - Time after trigger run 1 ms

Here the output again with log level TRACE enabled, we see that frame 42 needs to be triggered twice:

VimbaPython_2022-10-17_20-37-15_Trace.log

In the provided snippet we don't set the exposure time explicitly. But in our application we do that and we disabled all kinds of "Auto" features which could cause a variation in acquisition time, like auto exposure time, gain, white balance and so on. This did not helped.

Edit: I also added a print into __frame_cb_wrapper in camera.py. The callback is not called in case of the double trigger problem. I was also wondering who is giving the frame Id? The C driver or the camera device itself?

37:35.717 - Time after trigger run 3 ms
37:35.841 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=39, status=FrameStatus.Complete, buffer=0x7fb6685bd010) after 126 ms
2022-10-17 20:37:35,841 | Trace    | Enter | vimba.camera.Camera.queue_frame(self, Frame(id=39, status=FrameStatus.Complete, buffer=0x7fb6685bd010))
2022-10-17 20:37:35,842 | Trace    | Enter |   vimba.camera._StateAcquiring.queue_frame(self, Frame(id=39, status=FrameStatus.Complete, buffer=0x7fb6685bd010))
2022-10-17 20:37:35,842 | Trace    | Enter |     vimba.c_binding.vimba_c.call_vimba_c(VmbCaptureFrameQueue, (c_void_p(6206), <cparam 'P' (0x7fb6b59530c0)>, <CFunctionType object at 0x7fb6b3a25840>))
2022-10-17 20:37:35,842 | Trace    | Leave |     vimba.c_binding.vimba_c.call_vimba_c
2022-10-17 20:37:35,843 | Trace    | Leave |   vimba.camera._StateAcquiring.queue_frame
2022-10-17 20:37:35,843 | Trace    | Leave | vimba.camera.Camera.queue_frame
2022-10-17 20:37:36,219 | Trace    | Enter | vimba.feature.CommandFeature.run(self)
2022-10-17 20:37:36,219 | Trace    | Enter |   vimba.c_binding.vimba_c.call_vimba_c(VmbFeatureCommandRun, (c_void_p(6206), b'TriggerSoftware'))
2022-10-17 20:37:36,221 | Trace    | Leave |   vimba.c_binding.vimba_c.call_vimba_c
2022-10-17 20:37:36,221 | Trace    | Leave | vimba.feature.CommandFeature.run
37:36.221 - Time after trigger run 2 ms
37:36.345 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=40, status=FrameStatus.Complete, buffer=0x7fb66b459010) after 126 ms
2022-10-17 20:37:36,346 | Trace    | Enter | vimba.camera.Camera.queue_frame(self, Frame(id=40, status=FrameStatus.Complete, buffer=0x7fb66b459010))
2022-10-17 20:37:36,346 | Trace    | Enter |   vimba.camera._StateAcquiring.queue_frame(self, Frame(id=40, status=FrameStatus.Complete, buffer=0x7fb66b459010))
2022-10-17 20:37:36,347 | Trace    | Enter |     vimba.c_binding.vimba_c.call_vimba_c(VmbCaptureFrameQueue, (c_void_p(6206), <cparam 'P' (0x7fb6b5952fe0)>, <CFunctionType object at 0x7fb6b3a25840>))
2022-10-17 20:37:36,347 | Trace    | Leave |     vimba.c_binding.vimba_c.call_vimba_c
2022-10-17 20:37:36,347 | Trace    | Leave |   vimba.camera._StateAcquiring.queue_frame
2022-10-17 20:37:36,347 | Trace    | Leave | vimba.camera.Camera.queue_frame
2022-10-17 20:37:36,722 | Trace    | Enter | vimba.feature.CommandFeature.run(self)
2022-10-17 20:37:36,723 | Trace    | Enter |   vimba.c_binding.vimba_c.call_vimba_c(VmbFeatureCommandRun, (c_void_p(6206), b'TriggerSoftware'))
2022-10-17 20:37:36,725 | Trace    | Leave |   vimba.c_binding.vimba_c.call_vimba_c
2022-10-17 20:37:36,725 | Trace    | Leave | vimba.feature.CommandFeature.run
37:36.725 - Time after trigger run 3 ms
37:36.849 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=41, status=FrameStatus.Complete, buffer=0x7fb66a8b2010) after 127 ms
2022-10-17 20:37:36,849 | Trace    | Enter | vimba.camera.Camera.queue_frame(self, Frame(id=41, status=FrameStatus.Complete, buffer=0x7fb66a8b2010))
2022-10-17 20:37:36,850 | Trace    | Enter |   vimba.camera._StateAcquiring.queue_frame(self, Frame(id=41, status=FrameStatus.Complete, buffer=0x7fb66a8b2010))
2022-10-17 20:37:36,850 | Trace    | Enter |     vimba.c_binding.vimba_c.call_vimba_c(VmbCaptureFrameQueue, (c_void_p(6206), <cparam 'P' (0x7fb6b5952d40)>, <CFunctionType object at 0x7fb6b3a25840>))
2022-10-17 20:37:36,850 | Trace    | Leave |     vimba.c_binding.vimba_c.call_vimba_c
2022-10-17 20:37:36,851 | Trace    | Leave |   vimba.camera._StateAcquiring.queue_frame
2022-10-17 20:37:36,851 | Trace    | Leave | vimba.camera.Camera.queue_frame
2022-10-17 20:37:37,226 | Trace    | Enter | vimba.feature.CommandFeature.run(self)
2022-10-17 20:37:37,227 | Trace    | Enter |   vimba.c_binding.vimba_c.call_vimba_c(VmbFeatureCommandRun, (c_void_p(6206), b'TriggerSoftware'))
2022-10-17 20:37:37,228 | Trace    | Leave |   vimba.c_binding.vimba_c.call_vimba_c
2022-10-17 20:37:37,228 | Trace    | Leave | vimba.feature.CommandFeature.run
37:37.229 - Time after trigger run 2 ms
2022-10-17 20:37:37,729 | Trace    | Enter | vimba.feature.CommandFeature.run(self)
2022-10-17 20:37:37,730 | Trace    | Enter |   vimba.c_binding.vimba_c.call_vimba_c(VmbFeatureCommandRun, (c_void_p(6206), b'TriggerSoftware'))
2022-10-17 20:37:37,731 | Trace    | Leave |   vimba.c_binding.vimba_c.call_vimba_c
2022-10-17 20:37:37,731 | Trace    | Leave | vimba.feature.CommandFeature.run
37:37.732 - Time after trigger run 2 ms
37:37.856 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=42, status=FrameStatus.Complete, buffer=0x7fb669d0b010) after 126 ms
2022-10-17 20:37:37,856 | Trace    | Enter | vimba.camera.Camera.queue_frame(self, Frame(id=42, status=FrameStatus.Complete, buffer=0x7fb669d0b010))
2022-10-17 20:37:37,857 | Trace    | Enter |   vimba.camera._StateAcquiring.queue_frame(self, Frame(id=42, status=FrameStatus.Complete, buffer=0x7fb669d0b010))
2022-10-17 20:37:37,857 | Trace    | Enter |     vimba.c_binding.vimba_c.call_vimba_c(VmbCaptureFrameQueue, (c_void_p(6206), <cparam 'P' (0x7fb6b5952f70)>, <CFunctionType object at 0x7fb6b3a25840>))
2022-10-17 20:37:37,857 | Trace    | Leave |     vimba.c_binding.vimba_c.call_vimba_c
2022-10-17 20:37:37,857 | Trace    | Leave |   vimba.camera._StateAcquiring.queue_frame
2022-10-17 20:37:37,858 | Trace    | Leave | vimba.camera.Camera.queue_frame
2022-10-17 20:37:38,233 | Trace    | Enter | vimba.feature.CommandFeature.run(self)
2022-10-17 20:37:38,233 | Trace    | Enter |   vimba.c_binding.vimba_c.call_vimba_c(VmbFeatureCommandRun, (c_void_p(6206), b'TriggerSoftware'))
2022-10-17 20:37:38,235 | Trace    | Leave |   vimba.c_binding.vimba_c.call_vimba_c
2022-10-17 20:37:38,235 | Trace    | Leave | vimba.feature.CommandFeature.run
37:38.235 - Time after trigger run 2 ms
37:38.359 - Camera(id=DEV_1AB22C0074E3) acquired Frame(id=43, status=FrameStatus.Complete, buffer=0x7fb669164010) after 127 ms

Hello Damiano, thank you for the logs. It looks like the command is handed from VimbaPython to VimbaC without issue. So at least VimbaPython doesn't seem to be an issue. The frame ID is given by the camera itelf, so there is really no frame triggered in the camera, when the error occurs. Can you let me know more about the setup: Vimba version, operating system etc. Does the problem also occur on other PCs? I would recommend to uninstall Vimba and reinstall it (to the newest version). There might be an issue with the installation or the driver. If this was a general issue with VimbaC I would assume it to be much more frequent. It usually only occurs if there are other factors preventing the command from executing, but that should also raise an exception. Anyways, let me know if the reinstall helps. Cheers, Teresa

Just to add what @Teresa-AlliedVision already said: If you want to take an even deeper look into what is going on, you can also enable additional logging for VimbaC by setting the LogFileName option in the VimbaX.xml configuration file to a path where you want the log to be written to. This will give you a full log of all VimbaC functions that are called and the return code of the functions. This can also be very helpful in debugging these kinds of issues to narrow down where something might get lost.

The XML configuration file can be found next to the VimbaC library. The exact path depends on your operating system.

On 64bit Windows the directory would be C:\Program Files\Allied Vision\Vimba_X.Y\VimbaC\Bin\Win64
On Linux it depends where you unpacked the Vimba tarball to

Does it work even if i'm using a virtual environment,i didn't install vimbaPython by the usual way .I'm trying to activate the full log option but even if I set the LogFileName parameters where I unziped VimbaPython, it doesn't work anyway ...

I downloaded the package V6.0. Output of Vimba.get_instance().get_version(): VimbaPython: 1.2.1 (using VimbaC: 1.9.1, VimbaImageTransform: 1.0)

Operating system I am using openSUSE tumbleweed on a Lenovo t14 laptop. But we observed the same issue with Ubuntu 20.04 and 22.04 on other (Dell) machines. We can observe the issue on ARM too on the NVidia jetson nano platform.

Python version seems also to make no difference. We tried with a normal installation and in a conda virtual environment with versions 3.7 and 3.10.

On the hardware side the camera is attached with a good quality short cable directly to an USB 3 port without any hub in between.

Now I am trying to enable the additional VimbaC logs. I editedt the xml file /opt/Vimba_6_0/VimbaC/DynamicLib/x86_64bit/VimbaC.xml but no log file get created in my home directory. I also tried creating the file by hand but it doesn't get filled. With a relative path also no success. This is how i modified the XML:

<?xml version="1.0" standalone="no" ?>
<Settings>

    <!--
            Use this to activate logging and set filename for logging (path can be absolute or relative to API)
            Default behavior if omitted:    Logging is deactivated
    -->
        <LogFileName>/home/domi/VimbaC.log</LogFileName>

    <!--
            Append messages to log file or reset log file at each API restart (if logging is enabled)
            True:                           Always append log messages
            False:                          Reset log file at each API restart
            Default behavior if omitted:    Reset log file at each API restart
    -->
        <AppendLog>True</AppendLog>

</Settings>

I am quite sure I am in the right location because I listed the dll used by the script:

t14 :: /proc/15285 1 » cat maps | grep Vimba
7fe26ec00000-7fe26f209000 r-xp 00000000 00:28 106572                     /opt/Vimba_6_0/VimbaUSBTL/CTI/x86_64bit/VimbaUSBTL.cti
7fe26f209000-7fe26f409000 ---p 00609000 00:28 106572                     /opt/Vimba_6_0/VimbaUSBTL/CTI/x86_64bit/VimbaUSBTL.cti
7fe26f409000-7fe26f48b000 rw-p 00609000 00:28 106572                     /opt/Vimba_6_0/VimbaUSBTL/CTI/x86_64bit/VimbaUSBTL.cti
7fe33d600000-7fe33d6b5000 r-xp 00000000 00:28 107274                     /opt/Vimba_6_0/VimbaImageTransform/DynamicLib/x86_64bit/libVimbaImageTransform.so
7fe33d6b5000-7fe33d8b4000 ---p 000b5000 00:28 107274                     /opt/Vimba_6_0/VimbaImageTransform/DynamicLib/x86_64bit/libVimbaImageTransform.so
7fe33d8b4000-7fe33d8b7000 rw-p 000b4000 00:28 107274                     /opt/Vimba_6_0/VimbaImageTransform/DynamicLib/x86_64bit/libVimbaImageTransform.so
7fe33da00000-7fe33dad2000 r-xp 00000000 00:28 107357                     /opt/Vimba_6_0/VimbaC/DynamicLib/x86_64bit/libVimbaC.so
7fe33dad2000-7fe33dcd2000 ---p 000d2000 00:28 107357                     /opt/Vimba_6_0/VimbaC/DynamicLib/x86_64bit/libVimbaC.so
7fe33dcd2000-7fe33dcd8000 rw-p 000d2000 00:28 107357                     /opt/Vimba_6_0/VimbaC/DynamicLib/x86_64bit/libVimbaC.so

Is it also possible to look at the sources of the library or is it closed?

I have played around with the VimbaC.xml file and it appears, that the file is only applied correctly if it is located in your current working directory where you are launching the application from. I will need to check internally if this is the intended behaviour.

My setup that resulted in a created VimbaC.log:

my_working_directory
├── my_script.py
└── VimbaC.xml

executing python my_script.py resulted in the creation of VimbaC.log (I kept the default filename for the log file).

Is it also possible to look at the sources of the library or is it closed?

Sorry our core library VimbaC is not available as open source. Only the provided header files and the precompiled library that are part of the Vimba installation are provided so VimbaC can be used in your application.

Oh thanks, it is probably the only thing I did not tried :) I attached here a python and a C log of the same run. Frame with ID 210 had to be triggered twice. I looked at them but I could see nothing much different in the two run command calls. Other than Input Parameter name has another pointer address on the second call. I tried some more times and that address seems to always change in such cases. But it also changes sometimes when no "double triggering" happens.

VimbaPython_2022-10-20_08-52-52_Trace.log VimbaC.log

From the logs I cannot see any issues in the VimbaPython or VimbaC level. Everything looks as it should. Perhaps there is some kind of timing issue inside the camera? Maybe it is not yet ready to process another trigger?

@Teresa-AlliedVision Do you maybe have any further ideas why triggers might be missed?

Generally Rolling Shutter cameras can have some timing issues with triggers, but at least with hardware triggers they can still trigger at half the FPS that they reach when streaming at full datarate.

@domi4484 What camera are you using? I'll get a setup running to reproduce the error. You said it also occurred on Ubuntu 20.04 on a Dell machine, that would be easy to test here. Did you have any other cameras to test it with? It's a weid error, especially since everything else works fine, but it can be reproduced on other PCs, so I wouldn't exclude the possibility of something being broken in the camera. If you haven't done it yet, update the firmware on the camera again.

Thank you both for the help and sorry that I did not checked the camera firmware before. I had version 00.02.00 and on the Known issues it is stated that triggers can be missed. Now I updated and I already grabbed 3920 frames without error :partying_face:

alliedvision / VimbaPython

Software trigger doesn't always work #130