High latency in TF propagation

[Myzhar]

I'm porting the Stereolabs ZED 3D camera package to ROS2 and I cannot work with TF because of the high latency.
I'm sure that the TF messages propagates because I can see them using the ros2 topic and the ros2 run tf2_ros tf2_echo CLI commands... but Rviz receives them with many seconds of latency (sometimes I see frame axis move in Rviz after 2 or 3 three seconds after I stopped the node).

I thought that it was a problem with our node until I made a test with the "dummy robot" example and I figured out that the latency is a general problem:

• Run the example:
  $ ros2 launch dummy_robot_bringup dummy_robot_bringup.launch.py
• Open $ rviz2
• Set the fixed frame to world
• Add a TF plugin viewer. You will see the robot link moving
• Add a LaserScan plugin and subscribe to /scan

At this point you will see the simulated laser scan on the oscillating link of the robot and you will notice how it is rendered in late respect to its reference frame.
Furthermore you will notice a lot of errors
Could not transform from [single_rrbot_hokuyo_link] to [world] in the LaserScan plugin
and
[ERROR] [rviz2]: Lookup would require extrapolation into the future. Requested time 1538495387.01342 but the latest data is at time 1538495386.98954, when looking up transform from frame [single_rrbot_hokuyo_link] to frame [world]
in the console where RVIZ2 has been executed

I read that a solution was provided for a similar issue and I updated ROS2 and Rviz2 to the latest version of the master branch, but the issue is still present.
I also tried to change RMW, but each of the three available options have the same problem.

[Martin-Idel-SI]

This is connected to #332.
As far as I can see the problem is the following: the laser scan display currently asks for a transform at specific times - for a laser scan these times are not just one time point, but a range of times. Previously, the message filter made sure that the transform was available by allowing for some tolerance and doing some stuff behind the scene, but since message filters weren't available in ros2 until very recently, they aren't used, yet.

I would expect this bug to persist until #55 is resolved.

[Myzhar]

I read the #332, but it does not explain why I get the TF updates in Rviz2 even after that the node has been stopped. It seems like there is somewhere a queue that is processed very slowly

[Martin-Idel-SI]

Hmm..., I can't reproduce this.

I see the following:

• the laser scan is only very rarely rendered due to missing transforms and therefore it often seems as if it was late but that's only because I don't see the latest scan but an old one (at least in your image, the rendered scan is also not the last scan message you received as that one wasn't rendered due to missing transform).
• When I stop the dummy robot, no new laser scan gets rendered at the same moment that no new tf2 information gets processed. Of course, the last rendered laser scan will rarely be at the head of the robots last position, because it gets rendered only very rarely.
• In other words: I see the same as your screenshot, but I can also see that the laser scan rendered on screen is maybe a second old, but not because of latency but because all updates between then and now failed due to missing transforms.

These issues are related to what type of tf2 information laser_geometry requires and should be fixed by using message filters (might be a second issue, too, but without message filters, it's hard to see).

[Myzhar]

OK, so let's wait for message filters re introduction and let's see if it solves the problem.

[Martin-Idel-SI]

Yes, I believe this will make things much more apparent. But thanks for reporting the issue - maybe it turns out there is another problem.

[wjwwood]

We're waiting on tf message filter.

[mjcarroll]

I've started looking at tf message filter, will update with a PR reference when I've got something.

…

On Thu, Oct 11, 2018 at 12:08 PM William Woodall ***@***.***> wrote: We're waiting on tf message filter. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#359 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AARElXebSWRviEyt4_CwpQyCWEM1f6psks5uj3sNgaJpZM4XR1Pl> .

[wjwwood]

I don't know, I don't have time to do it right now, but if someone did a pr, I might have time to review it. Can't promise when though.

[jacobperron]

@Myzhar Since #375 has been merged, can you check if you still have this issue?

[Myzhar]

@jacobperron I'm currently on another project and I don't know when I have free time to compile ROS2 from source.
I hope I can test it very soon

[allenh1]

@Myzhar I build a daily docker container with ROS 2 from the current master that you could probably use for your tests, should you be interested. It's allenh1/rplidar_ros_demo:latest.

[ymd-stella]

I did some research on this issue.
The summary and my opinions are summarized below.

Summary

• qos of tf2_ros::TransformListener is DynamicListenerQoS(depth=100).
  • tf2_ros/include/tf2_ros/qos.hpp#L42
  • tf2_ros/include/tf2_ros/transform_listener.h#L58-L62

  • rviz/rviz_default_plugins/src/rviz_default_plugins/transformation/tf_wrapper.cpp

    Lines 126 to 127 in c5e6803

    	tf_listener_ = std::make_shared<tf2_ros::TransformListener>(
    	*buffer_, rviz_ros_node.lock()->get_raw_node(), false);

• spin_some(10ms) is processed in the same loop as the rendering process.
  

  rviz/rviz_common/src/rviz_common/visualization_manager.cpp

  Line 390 in c5e6803

  executor_->spin_some(std::chrono::milliseconds(10));

• spin_some(10ms) is called at 30 fps.
• It seems that spin_some(10ms) reads only one message of /tf from the message queue.

The principle of the problem

• If the output frequency of /tf exceeds 30 Hz, the message will accumulate up to depth(=100) in the subscription queue of /tf.
• The maximum delay is 100 times the output period of /tf.

About solutions

• Execute tf2_ros::TransformListener in the other thread.
  • In rviz, tf2_ros::TransformListener's spin_thread was set to true, so this problem did not occur.
  • relevant PR is Make transformation framework pluggable #346 and Pass clock to tf2_ros::buffer #340
  • relevant commit is bosch-io@b27d8f6#diff-a9019488dd7d224ab0d14c8e962c4209R142