ros-drivers / flir_camera_driver

164 stars 154 forks source link

[humble] Dropped frames when syncing Blackfly_s cameras #196

Closed jjc-sri closed 2 months ago

jjc-sri commented 3 months ago

Is this behavior also observed when using SpinView? The cameras are able to sync after setting the correct parameters in SpinView.

Describe the bug I'm unable to capture properly synchronized images using the spinnaker_synchronized_camera_driver with two FLIR Blackfly_s cameras. The primary camera provides the trigger to the secondary camera via a trigger cable. I'm running with user li-dahua's script, as referenced in the resolution of this issue. Because my camera model is the same as used in the example, all I changed was the camera serial numbers. Most importantly, I verified that the script(s) set the correct sync parameters for each camera.

The issue: Not only is rviz output laggy (with noticably different lags for each camera), but creating a ros bag shows that frames are missing. Some frames align between the two streams (albeit with different timestamps; we use an LED panel to establish correspondence), but other frames have no corresponding frame in the other stream. It works out so that about half of the frames have a corresponding frame that was captured at the same time in the other stream.

This causes two problems. First, the synced frame rate is effectively reduced to ~half of the original frame rate. Second, it’s difficult to programmatically match corresponding frames together. I’ve had some success performing matching based on nearest timestamps, but I’m not sure how robust that is, nor is it particularly convenient. Doesn’t the documentation for this sync driver specify that synced frames will be assigned identical timestamps?

Useful logging output

> ros2 launch spinnaker_synchronized_camera_driver stereo_synced.launch.py
[INFO] [launch]: All log files can be found below /home/ubuntu/.ros/log/2024-07-15-15-56-27-068800-ubuntu22-Precision-7530-211567
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [component_container-1]: process started with pid [211579]
[component_container-1] [INFO] [1721073387.405658631] [stereo_camera_container]: Load Library: /opt/ros/humble/lib/libcamera_driver.so
[component_container-1] [INFO] [1721073387.429959167] [stereo_camera_container]: Found class: rclcpp_components::NodeFactoryTemplate<spinnaker_camera_driver::CameraDriver>
[component_container-1] [INFO] [1721073387.429996544] [stereo_camera_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<spinnaker_camera_driver::CameraDriver>
[component_container-1] [INFO] [1721073387.433942839] [22645262]: reading ros parameters for camera with serial: 22645262
[component_container-1] [INFO] [1721073387.433973794] [22645262]: adjusting time stamps!
[component_container-1] [INFO] [1721073387.434054859] [22645262]: parameter definitions file: /opt/ros/humble/share/spinnaker_camera_driver/config/blackfly_s.yaml
[component_container-1] [INFO] [1721073387.436097367] [cam0]: using default calibration URL
[component_container-1] [INFO] [1721073387.436124692] [cam0]: camera calibration URL: file:///home/ubuntu/.ros/camera_info/cam0.yaml
[component_container-1] [INFO] [1721073388.625059900] [22645262]: using spinnaker lib version: 3.1.0.79
[component_container-1] [INFO] [1721073388.625313524] [22645262]: found camera with serial number: 22645262
[component_container-1] [INFO] [1721073389.003037615] [22645262]: setting ImageFormatControl/PixelFormat to: BGR8
[component_container-1] [INFO] [1721073389.012562823] [22645262]: setting AnalogControl/GainAuto to: Continuous
[component_container-1] [INFO] [1721073389.016075648] [22645262]: setting DigitalIOControl/LineSelector to: Line1
[component_container-1] [INFO] [1721073389.016774641] [22645262]: setting DigitalIOControl/LineMode to: Output
[component_container-1] [INFO] [1721073389.017674946] [22645262]: setting DigitalIOControl/LineSelector to: Line2
[component_container-1] [INFO] [1721073389.018167327] [22645262]: setting DigitalIOControl/V3_3Enable to: 1
[component_container-1] [INFO] [1721073389.019307282] [22645262]: setting AcquisitionControl/ExposureAuto to: Continuous
[component_container-1] [INFO] [1721073389.022899983] [22645262]: setting AcquisitionControl/TriggerSelector to: FrameStart
[component_container-1] [INFO] [1721073389.024511012] [22645262]: setting AcquisitionControl/TriggerMode to: Off
[component_container-1] [INFO] [1721073389.026902819] [22645262]: setting ChunkDataControl/ChunkModeActive to: 1
[component_container-1] [INFO] [1721073389.030682987] [22645262]: setting ChunkDataControl/ChunkSelector to: FrameID
[component_container-1] [INFO] [1721073389.032692615] [22645262]: setting ChunkDataControl/ChunkEnable to: 1
[component_container-1] [INFO] [1721073389.035755391] [22645262]: setting ChunkDataControl/ChunkSelector to: ExposureTime
[component_container-1] [INFO] [1721073389.036171244] [22645262]: setting ChunkDataControl/ChunkEnable to: 1
[component_container-1] [INFO] [1721073389.038887196] [22645262]: setting ChunkDataControl/ChunkSelector to: Gain
[component_container-1] [INFO] [1721073389.039343688] [22645262]: setting ChunkDataControl/ChunkEnable to: 1
[component_container-1] [INFO] [1721073389.041941468] [22645262]: setting ChunkDataControl/ChunkSelector to: Timestamp
[component_container-1] [INFO] [1721073389.042324355] [22645262]: setting ChunkDataControl/ChunkEnable to: 1
[component_container-1] [INFO] [1721073390.148133235] [22645262]: camera has pixel format: BGR8
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/cam0' in container '/stereo_camera_container'
[component_container-1] [INFO] [1721073390.155193185] [stereo_camera_container]: Found class: rclcpp_components::NodeFactoryTemplate<spinnaker_camera_driver::CameraDriver>
[component_container-1] [INFO] [1721073390.155282848] [stereo_camera_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<spinnaker_camera_driver::CameraDriver>
[component_container-1] [INFO] [1721073390.161512190] [22567836]: reading ros parameters for camera with serial: 22567836
[component_container-1] [INFO] [1721073390.161540250] [22567836]: adjusting time stamps!
[component_container-1] [INFO] [1721073390.161618584] [22567836]: parameter definitions file: /opt/ros/humble/share/spinnaker_camera_driver/config/blackfly_s.yaml
[component_container-1] [INFO] [1721073390.162875900] [cam1]: using default calibration URL
[component_container-1] [INFO] [1721073390.162914833] [cam1]: camera calibration URL: file:///home/ubuntu/.ros/camera_info/cam1.yaml
[component_container-1] [INFO] [1721073390.164851834] [22567836]: using spinnaker lib version: 3.1.0.79
[component_container-1] [INFO] [1721073390.165094350] [22567836]: found camera with serial number: 22567836
[component_container-1] [INFO] [1721073390.524135631] [22567836]: setting ImageFormatControl/PixelFormat to: BGR8
[component_container-1] [INFO] [1721073390.533362985] [22567836]: setting AnalogControl/GainAuto to: Continuous
[component_container-1] [INFO] [1721073390.536994107] [22567836]: setting DigitalIOControl/LineSelector to: Line3
[component_container-1] [INFO] [1721073390.537647190] [22567836]: setting DigitalIOControl/LineMode to: Input
[component_container-1] [INFO] [1721073390.538885269] [22567836]: setting AcquisitionControl/ExposureAuto to: Continuous
[component_container-1] [INFO] [1721073390.542572649] [22567836]: setting AcquisitionControl/TriggerSelector to: FrameStart
[component_container-1] [INFO] [1721073390.543330627] [22567836]: setting AcquisitionControl/TriggerMode to: On
[component_container-1] [INFO] [1721073390.544821262] [22567836]: setting AcquisitionControl/TriggerSource to: Line3
[component_container-1] [INFO] [1721073390.546184294] [22567836]: setting AcquisitionControl/TriggerOverlap to: ReadOut
[component_container-1] [INFO] [1721073390.548066354] [22567836]: setting ChunkDataControl/ChunkModeActive to: 1
[component_container-1] [INFO] [1721073390.571560907] [22567836]: setting ChunkDataControl/ChunkSelector to: FrameID
[component_container-1] [INFO] [1721073390.572977492] [22567836]: setting ChunkDataControl/ChunkEnable to: 1
[component_container-1] [INFO] [1721073390.576133584] [22567836]: setting ChunkDataControl/ChunkSelector to: ExposureTime
[component_container-1] [INFO] [1721073390.576770492] [22567836]: setting ChunkDataControl/ChunkEnable to: 1
[component_container-1] [INFO] [1721073390.580087919] [22567836]: setting ChunkDataControl/ChunkSelector to: Gain
[component_container-1] [INFO] [1721073390.580746271] [22567836]: setting ChunkDataControl/ChunkEnable to: 1
[component_container-1] [INFO] [1721073390.583621730] [22567836]: setting ChunkDataControl/ChunkSelector to: Timestamp
[component_container-1] [INFO] [1721073390.584080229] [22567836]: setting ChunkDataControl/ChunkEnable to: 1
[component_container-1] [INFO] [1721073391.668398366] [22567836]: camera has pixel format: BGR8
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/cam1' in container '/stereo_camera_container'
[component_container-1] [ERROR] [1721073391.670583333] [stereo_camera_container]: Could not find requested resource in ament index
[ERROR] [launch_ros.actions.load_composable_nodes]: Failed to load node 'sync' of type 'cam_sync_ros2::CamSync' in container '/stereo_camera_container': Could not find requested resource in ament index
[ERROR] [launch_ros.actions.load_composable_nodes]: Failed to load node 'exposure_control' of type 'exposure_control_ros2::ExposureControl' in container '/stereo_camera_container': Could not find requested resource in ament index
[component_container-1] [ERROR] [1721073391.672317489] [stereo_camera_container]: Could not find requested resource in ament index
[component_container-1] [INFO] [1721073392.434204881] [22645262]: rate [Hz] in   7.69 out   0.00 drop   0%
[component_container-1] [INFO] [1721073395.161810074] [22567836]: rate [Hz] in   8.24 out   0.00 drop   0%
[component_container-1] [INFO] [1721073397.434150659] [22645262]: rate [Hz] in   7.61 out   0.00 drop   0%
[component_container-1] [INFO] [1721073400.161821212] [22567836]: rate [Hz] in   7.97 out   0.00 drop   0%
[component_container-1] [INFO] [1721073402.434433065] [22645262]: rate [Hz] in   7.57 out   0.00 drop   0%
[component_container-1] [INFO] [1721073405.161762445] [22567836]: rate [Hz] in   7.80 out   0.00 drop   0%
[component_container-1] [INFO] [1721073407.434260422] [22645262]: rate [Hz] in   7.53 out   0.00 drop   0%
[component_container-1] [INFO] [1721073410.161682227] [22567836]: rate [Hz] in   7.69 out   0.00 drop   0%
[component_container-1] [INFO] [1721073412.434137695] [22645262]: rate [Hz] in   7.51 out   0.00 drop   0%

I notice the two "Failed to load node" errors toward the end of setup. I'm not sure how important those are; clearly they don't kill the launch.

System details

berndpfrommer commented 3 months ago

Something is really wrong with that launch script. From the log, it looks like it is not launching a synchronized camera driver node, but two stand alone driver nodes.

On Mon, Jul 15, 2024, 4:04 PM jjc-sri @.***> wrote:

Assigned #196 https://github.com/ros-drivers/flir_camera_driver/issues/196 to @berndpfrommer https://github.com/berndpfrommer.

— Reply to this email directly, view it on GitHub https://github.com/ros-drivers/flir_camera_driver/issues/196#event-13510469133, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABPLK2W56VBVJJYAS7F7VD3ZMQTLHAVCNFSM6AAAAABK5GTFIWVHI2DSMVQWIX3LMV45UABCJFZXG5LFIV3GK3TUJZXXI2LGNFRWC5DJN5XDWMJTGUYTANBWHEYTGMY . You are receiving this because you were assigned.Message ID: @.*** com>

berndpfrommer commented 3 months ago

This launch file is not in the spinnaker_synchronized_camera_driver package. Please use this file instead.

jjc-sri commented 3 months ago

I've switched to running ros2 launch spinnaker_synchronized_camera_driver primary_secondary.launch.py.

The rviz visualization is indistinguishable from before: ~1-2 seconds of lag, with different lags for each camera, but (as before) the primary camera continues while the secondary camera stops producing images when the sync cable is removed.

Saving a rosbag and inspecting images of an LED panel shows that many images are in sync with an image from the other camera but with different timestamps. There are still dropped frames from each camera. (The truly synced frame rate is now roughly 2/3 the raw frame rate).

This is the log while the ros bag was being recorded:

> ros2 launch spinnaker_synchronized_camera_driver primary_secondary.launch.py 
[INFO] [launch]: All log files can be found below /home/ubuntu/.ros/log/2024-07-16-16-07-01-642119-ubuntu22-Precision-7530-251505
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [component_container-1]: process started with pid [251517]
[component_container-1] [INFO] [1721160421.990637328] [cam_sync_container]: Load Library: /opt/ros/humble/lib/libsynchronized_camera_driver.so
[component_container-1] [INFO] [1721160422.001507757] [cam_sync_container]: Found class: rclcpp_components::NodeFactoryTemplate<spinnaker_camera_driver::CameraDriver>
[component_container-1] [INFO] [1721160422.001532486] [cam_sync_container]: Found class: rclcpp_components::NodeFactoryTemplate<spinnaker_synchronized_camera_driver::SynchronizedCameraDriver>
[component_container-1] [INFO] [1721160422.001538453] [cam_sync_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<spinnaker_synchronized_camera_driver::SynchronizedCameraDriver>
[component_container-1] [INFO] [1721160422.003954719] [cam_sync]: created exposure controller: cam0.exposure_controller
[component_container-1] [INFO] [1721160422.004019770] [cam_sync]: created exposure controller: cam1.exposure_controller
[component_container-1] [INFO] [1721160422.004196866] [cam0]: parameter definitions file: /opt/ros/humble/share/spinnaker_camera_driver/config/blackfly_s.yaml
[component_container-1] [INFO] [1721160422.006031492] [cam_sync]: camera calibration URL: file://camera_calibrations/22645262.yaml
[component_container-1] [ERROR] [1721160422.006053700] [cam_sync]: Invalid camera calibration URL: file://camera_calibrations/22645262.yaml
[component_container-1] [INFO] [1721160423.326245579] [cam0]: using spinnaker lib version: 3.1.0.79
[component_container-1] [INFO] [1721160423.326849863] [cam0]: found camera with serial number: 22645262
[component_container-1] [INFO] [1721160424.841298665] [cam0]: camera has pixel format: BGR8
[component_container-1] [INFO] [1721160424.842126242] [cam1]: parameter definitions file: /opt/ros/humble/share/spinnaker_camera_driver/config/blackfly_s.yaml
[component_container-1] [INFO] [1721160424.846492307] [cam_sync]: camera calibration URL: file://camera_calibrations/22567836.yaml
[component_container-1] [ERROR] [1721160424.846508680] [cam_sync]: Invalid camera calibration URL: file://camera_calibrations/22567836.yaml
[component_container-1] [INFO] [1721160424.847758032] [cam1]: using spinnaker lib version: 3.1.0.79
[component_container-1] [INFO] [1721160424.847871709] [cam1]: found camera with serial number: 22567836
[component_container-1] [INFO] [1721160425.033763212] [cam0]: bright 1 at time/gain: [9993 0] new: [9993 9.99322]
[component_container-1] [INFO] [1721160425.267233296] [cam0]: bright 1 at time/gain: [9993 9.99322] new: [9993 19.9864]
[component_container-1] [INFO] [1721160425.535383621] [cam0]: bright 1 at time/gain: [9993 19.9864] new: [9993 29.9]
[component_container-1] [INFO] [1721160425.807423281] [cam_sync]: frequency estimator initialized with 8.929 Hz
[component_container-1] [INFO] [1721160425.807557045] [cam0]: bright 1 at time/gain: [9993 29.9] new: [15000 29.9]
[component_container-1] [INFO] [1721160426.419398935] [cam1]: camera has pixel format: BGR8
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/cam_sync' in container '/cam_sync_container'
[component_container-1] [INFO] [1721160426.659595580] [cam1]: bright 1 at time/gain: [9993 17.8979] new: [15000 29.9]
[component_container-1] [INFO] [1721160431.419774921] [cam_sync]: ------ frequency:      7.475 Hz
[component_container-1] [INFO] [1721160431.419918575] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160431.419959189] [cam_sync]: cam0        0    0     1.33%    23.51%
[component_container-1] [INFO] [1721160431.420003188] [cam_sync]: cam1        0    0    -0.49%    27.28%
[component_container-1] [INFO] [1721160436.419659424] [cam_sync]: ------ frequency:      7.447 Hz
[component_container-1] [INFO] [1721160436.419741834] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160436.419749837] [cam_sync]: cam0        0    0    -1.25%    20.56%
[component_container-1] [INFO] [1721160436.419759216] [cam_sync]: cam1        0    0     9.80%    20.89%
[component_container-1] [INFO] [1721160441.419746070] [cam_sync]: ------ frequency:      7.490 Hz
[component_container-1] [INFO] [1721160441.419869510] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160441.419903435] [cam_sync]: cam0        0    0    -4.92%     8.10%
[component_container-1] [INFO] [1721160441.419938417] [cam_sync]: cam1        0    0     3.94%    10.39%
[component_container-1] [INFO] [1721160446.419640133] [cam_sync]: ------ frequency:      7.490 Hz
[component_container-1] [INFO] [1721160446.419685932] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160446.419693678] [cam_sync]: cam0        0    0    -3.77%     6.28%
[component_container-1] [INFO] [1721160446.419700787] [cam_sync]: cam1        0    0     5.55%     7.63%
[component_container-1] [INFO] [1721160451.419626554] [cam_sync]: ------ frequency:      7.463 Hz
[component_container-1] [INFO] [1721160451.419719909] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160451.419740017] [cam_sync]: cam0        0    0    -3.70%     2.20%
[component_container-1] [INFO] [1721160451.419759472] [cam_sync]: cam1        0    0     3.56%     2.34%
[component_container-1] [INFO] [1721160456.419655900] [cam_sync]: ------ frequency:      7.453 Hz
[component_container-1] [INFO] [1721160456.419725243] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160456.419735813] [cam_sync]: cam0        0    0    -3.68%     1.02%
[component_container-1] [INFO] [1721160456.419744408] [cam_sync]: cam1        0    0     3.84%     1.52%
[component_container-1] [INFO] [1721160461.419603979] [cam_sync]: ------ frequency:      7.462 Hz
[component_container-1] [INFO] [1721160461.419672428] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160461.419681550] [cam_sync]: cam0        0    0    -3.60%     0.93%
[component_container-1] [INFO] [1721160461.419691139] [cam_sync]: cam1        0    0     3.50%     1.14%
[component_container-1] [INFO] [1721160466.419658794] [cam_sync]: ------ frequency:      7.460 Hz
[component_container-1] [INFO] [1721160466.419780441] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160466.419802975] [cam_sync]: cam0        0    0    -3.88%     0.85%
[component_container-1] [INFO] [1721160466.419823869] [cam_sync]: cam1        0    0     4.05%     1.48%
[component_container-1] [INFO] [1721160471.419638946] [cam_sync]: ------ frequency:      7.452 Hz
[component_container-1] [INFO] [1721160471.419689490] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160471.419697840] [cam_sync]: cam0        0    0    -3.64%     0.86%
[component_container-1] [INFO] [1721160471.419706420] [cam_sync]: cam1        0    0     3.69%     1.03%
[component_container-1] [INFO] [1721160476.419635684] [cam_sync]: ------ frequency:      7.466 Hz
[component_container-1] [INFO] [1721160476.419683964] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160476.419692128] [cam_sync]: cam0        0    0    -3.57%     0.98%
[component_container-1] [INFO] [1721160476.419700644] [cam_sync]: cam1        0    0     3.58%     1.55%
[component_container-1] [INFO] [1721160481.419625496] [cam_sync]: ------ frequency:      7.455 Hz
[component_container-1] [INFO] [1721160481.419669041] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160481.419676270] [cam_sync]: cam0        0    0    -3.67%     1.11%
[component_container-1] [INFO] [1721160481.419683430] [cam_sync]: cam1        0    0     3.79%     1.14%
[component_container-1] [INFO] [1721160486.419701389] [cam_sync]: ------ frequency:      7.430 Hz
[component_container-1] [INFO] [1721160486.419804514] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160486.419829538] [cam_sync]: cam0        0    0    -4.43%     3.13%
[component_container-1] [INFO] [1721160486.419853205] [cam_sync]: cam1        0    0     4.11%     3.70%
[component_container-1] [INFO] [1721160491.419680917] [cam_sync]: ------ frequency:      7.453 Hz
[component_container-1] [INFO] [1721160491.419761857] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160491.419779629] [cam_sync]: cam0        0    0    -5.40%     4.82%
[component_container-1] [INFO] [1721160491.419797355] [cam_sync]: cam1        0    0     5.36%     7.02%
[component_container-1] [INFO] [1721160496.420065725] [cam_sync]: ------ frequency:      7.447 Hz
[component_container-1] [INFO] [1721160496.420199029] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721160496.420238397] [cam_sync]: cam0        0    0    -4.82%     5.83%
[component_container-1] [INFO] [1721160496.420276489] [cam_sync]: cam1        0    0     5.49%     7.20%
berndpfrommer commented 3 months ago

About lag on rviz: there could be buffering on the ROS2 transport, who knows. I've had my share of interesting experiences with ROS2 transports, so let's focus on the time stamps. The log looks good to me. The frequency says 7.447Hz which is lower than what I expected. Can you give me the exact model number of the cameras you are using? Would be helpful to know what frame rate you are requesting, whether it's a GigE or USB camera, and the image resolution you are pulling. There are no gaps in the frame numbers, meaning the driver receives the images from the SDK nicely. The driver is designed to put identical time stamps on the header stamps. The rosbag2 recording time stamps will not align, but the header stamps should. If you find the header stamps misaligned, please send me a short rosbag with the data (a few seconds maybe) that shows the skipped header stamps. Along with the complete, exact launch file you are using. If you run ros2 topic hz /cam_sync/cam0/image_raw on the same host that the camera is connected to, what frequency does it report?

jjc-sri commented 3 months ago

The model number is BFS-U3-161S7C-C. It's a USB3 camera and I'm receiving frames with 5320 x 3032 resolution.

I hadn't changed the default framerate and resolution parameters, but now I'm requesting the full 5320 x 3032 resolution. The lower level driver doesn't seem to accept a frame_rate parameter: [component_container-1] [WARN] [1721342659.571167070] [cam0]: setting AcquisitionControl/AcquisitionFrameRate failed: node AcquisitionControl/AcquisitionFrameRate not writable!

Decreasing the resolution to 720x1280 does increase the frame rate reported by the sync driver to about 28.3 Hz. The rosbag timestamps are still mismatched.

My understanding is that the only timestamps contained in the rosbag are the header timestamps, which are what I've observed fail to align.

Here's a google drive folder containing two rosbags: the one whose name ends in high-res is at the original resolution and a framerate of ~7.5 Hz, and the one whose name ends in 720p was captured at 720p and ~28 Hz. Both have header timestamps which mismatch, according to the timestamps reported by the rosbags python package. Note that each rosbag directory contains its log output in a log.out file.

You can find my exact launch file here. This is the one that generated the high res images at a lower frame rate. To generate lower res images at a higher frame rate, I simply commented out lines 70 and 71 and uncommented lines 72 and 73, setting the image width and height.

For the original (high res, ~7.5 Hz) launch configuration, ros2 topic hz /cam_sync/cam0/image_raw reports a much lower frequency -- between 1 an 3 Hz (typically between 1 and 2 Hz). However, for the other (low res, ~28 Hz) launch configuration, it reports between 28.0 and 28.3 Hz.

berndpfrommer commented 3 months ago

Can you set the frame rate using SpinView?

berndpfrommer commented 3 months ago

I looked at the first few header stamps of your 720p bag and they line up nicely. The command I use is this:

ros2 topic echo /cam_sync/cam0/image_raw | grep -A 4 stamp

Apologies for posting a screen shot, but formatting it otherwise would have taken more time: header_stamps_720p

berndpfrommer commented 3 months ago

About the high-res bag: I don't feel like graphing the time stamps, but I see quite a few time stamps that align just fine. I suspect the rest is missing frames. I can't imagine the camera driver log looking very nice and clean in that situation. I'd expect a ton of nasty messages. Not sure what the rosbags python package spits out but the time that is returned is probably the recording time, not the header stamp. The recording time will be all over the place. The header stamp is what really tells you when the frame was captured (well, sort of, as well as possible). The truth is that ros2 topic hz sucks for capturing frequencies of large or high frequency messages. Run a "top" and you'll see that the command itself sucks up 100% CPU. It tries to read the whole message, but is very slow doing so, so it cannot keep up with the image stream, and drops the messages. Then it under reports the frequency. It can be quite useless for the large frames you are having. Oh, and you are using BGR8 image format. I believe that is an uncompressed format. You may get much better performance by switching to the Bayer image, and doing the unbayering later in post-processing. The ROS2 image viewer e.g. does it for you transparently.

berndpfrommer commented 3 months ago

Try setting "frame_rate_enable" to True on the master camera. This should make the "AcquisitionControl/AcquisitionFrameRate" node writable.

jjc-sri commented 2 months ago

es, I'm able to adjust the frame_rate after setting frame_rate_enable to True.

Okay, I'm able to reproduce your conclusion that the header timestamps align in the low res rosbag. And yes, many do align in the high res bag. And if I decrease the high res frequency to 5Hz, those header timestamps all line up as well.

Clearly the main issue I was facing is an artifact of the rosbags library, not the sync driver. Thanks for helping me realize that.

(I don't see any timestamp other than the header timestamp recorded in the rosbag messages, so I'm not sure where rosbags is getting different timestamps. I know you're suggesting they're recording timestamps, and I understand the difference, but I don't see where the recording timestamps are saved in the sensor_msgs/msg/Image messages saved in the rosbag. Anyway, I'm not asking you to debug the rosbags library.)

(I'll also add that I was able to modify my code that used rosbags to explicitly ask for header timestamps, and those timestamps do indeed align.)

jjc-sri commented 2 months ago

One lingering potential issue is that the sync driver did NOT spit out nasty error messages when recording the high res bag, at least as far as I can tell. (And I've reproduced that result several times.) The frames are dropped silently. Is that a bug in the sync driver?

Here's the log I saved during the recording of the high res bag:

> ros2 launch spinnaker_synchronized_camera_driver primary_secondary.launch.py 
[INFO] [launch]: All log files can be found below /home/ubuntu/.ros/log/2024-07-19-13-56-50-828753-ubuntu22-Precision-7530-396670
[INFO] [launch]: Default logging verbosity is set to INFO
[INFO] [component_container-1]: process started with pid [396682]
[component_container-1] [INFO] [1721411811.168195883] [cam_sync_container]: Load Library: /opt/ros/humble/lib/libsynchronized_camera_driver.so
[component_container-1] [INFO] [1721411811.180539102] [cam_sync_container]: Found class: rclcpp_components::NodeFactoryTemplate<spinnaker_camera_driver::CameraDriver>
[component_container-1] [INFO] [1721411811.180569054] [cam_sync_container]: Found class: rclcpp_components::NodeFactoryTemplate<spinnaker_synchronized_camera_driver::SynchronizedCameraDriver>
[component_container-1] [INFO] [1721411811.180575618] [cam_sync_container]: Instantiate class: rclcpp_components::NodeFactoryTemplate<spinnaker_synchronized_camera_driver::SynchronizedCameraDriver>
[component_container-1] [INFO] [1721411811.183570803] [cam_sync]: created exposure controller: cam0.exposure_controller
[component_container-1] [INFO] [1721411811.183650515] [cam_sync]: created exposure controller: cam1.exposure_controller
[component_container-1] [INFO] [1721411811.183865581] [cam0]: parameter definitions file: /opt/ros/humble/share/spinnaker_camera_driver/config/blackfly_s.yaml
[component_container-1] [INFO] [1721411811.185949771] [cam_sync]: camera calibration URL: file://camera_calibrations/22645262.yaml
[component_container-1] [ERROR] [1721411811.185972755] [cam_sync]: Invalid camera calibration URL: file://camera_calibrations/22645262.yaml
[component_container-1] [INFO] [1721411812.472579536] [cam0]: using spinnaker lib version: 3.1.0.79
[component_container-1] [INFO] [1721411812.473102058] [cam0]: found camera with serial number: 22645262
[component_container-1] [INFO] [1721411812.979958918] [cam0]: camera has pixel format: BGR8
[component_container-1] [INFO] [1721411812.980778948] [cam1]: parameter definitions file: /opt/ros/humble/share/spinnaker_camera_driver/config/blackfly_s.yaml
[component_container-1] [INFO] [1721411812.986088794] [cam_sync]: camera calibration URL: file://camera_calibrations/22567836.yaml
[component_container-1] [ERROR] [1721411812.986173118] [cam_sync]: Invalid camera calibration URL: file://camera_calibrations/22567836.yaml
[component_container-1] [INFO] [1721411812.990969606] [cam1]: using spinnaker lib version: 3.1.0.79
[component_container-1] [INFO] [1721411812.991465345] [cam1]: found camera with serial number: 22567836
[component_container-1] [INFO] [1721411813.139411629] [cam0]: bright 1 at time/gain: [9993 29.8965] new: [9993 29.9]
[component_container-1] [INFO] [1721411813.410053692] [cam0]: bright 1 at time/gain: [9993 29.9] new: [15000 29.9]
[component_container-1] [INFO] [1721411813.520891488] [cam1]: camera has pixel format: BGR8
[INFO] [launch_ros.actions.load_composable_nodes]: Loaded node '/cam_sync' in container '/cam_sync_container'
[component_container-1] [INFO] [1721411813.835381563] [cam1]: bright 1 at time/gain: [9993 29.8965] new: [15000 29.9]
[component_container-1] [INFO] [1721411813.974682232] [cam_sync]: frequency estimator initialized with 6.400 Hz
[component_container-1] [INFO] [1721411818.521188469] [cam_sync]: ------ frequency:      7.418 Hz
[component_container-1] [INFO] [1721411818.521274691] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721411818.521295804] [cam_sync]: cam0        0    0     1.04%    32.44%
[component_container-1] [INFO] [1721411818.521318267] [cam_sync]: cam1        0    0     4.70%    35.99%
[component_container-1] [INFO] [1721411823.521512527] [cam_sync]: ------ frequency:      7.457 Hz
[component_container-1] [INFO] [1721411823.521647604] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721411823.521686297] [cam_sync]: cam0        0    0     6.80%    36.09%
[component_container-1] [INFO] [1721411823.521728829] [cam_sync]: cam1        0    0    -5.15%    36.23%
[component_container-1] [INFO] [1721411828.521098828] [cam_sync]: ------ frequency:      7.468 Hz
[component_container-1] [INFO] [1721411828.521139940] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721411828.521147215] [cam_sync]: cam0        0    0     3.88%    36.35%
[component_container-1] [INFO] [1721411828.521155718] [cam_sync]: cam1        0    0    -6.39%    35.37%
[component_container-1] [INFO] [1721411833.521251397] [cam_sync]: ------ frequency:      7.459 Hz
[component_container-1] [INFO] [1721411833.521443303] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721411833.521489847] [cam_sync]: cam0        0    0     3.31%    36.32%
[component_container-1] [INFO] [1721411833.521534944] [cam_sync]: cam1        0    0    -6.06%    34.87%
[component_container-1] [INFO] [1721411838.521215086] [cam_sync]: ------ frequency:      7.444 Hz
[component_container-1] [INFO] [1721411838.521329882] [cam_sync]: camera   drop icmp    offset    jitter
[component_container-1] [INFO] [1721411838.521364234] [cam_sync]: cam0        0    0     0.19%    34.03%
[component_container-1] [INFO] [1721411838.521426999] [cam_sync]: cam1        0    0    -8.38%    32.74%
berndpfrommer commented 2 months ago

The recording time stamps are indeed not part of the ROS2 message, but are stored in the rosbag2 file. You keep referring to the rosbags library. The relevant code for anything related to rosbags under ROS2 is however the rosbag2 github. I'm stumped as to why the driver does not report dropped messages when in fact you see them missing. It could potentially be the recording node that is dropping the data. If you run under Jazzy you could load the recorder node as a composable node into the same address space as the driver to avoid dropped messages. Will also avoid unnecessary data copying so your whole system will perform better. The jitter >30% is about 10 times larger than what I usually see on USB3, which has very consistent delivery times. But then again I have not had the need yet to push a USB3 camera to the bandwidth limit. I see you are still running BGR3. I think you'd be seeing better performance using a Bayer format.

berndpfrommer commented 2 months ago

OK, closing this issue. Not clear if frames are dropped by the driver (it does not look like that to me). Please reopen if new evidence emerges that frames are dropped by the driver.