Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Monitored planning scene sync issues #3174

Open
MarqRazz opened this issue Dec 19, 2024 · 5 comments
Open

Monitored planning scene sync issues #3174

MarqRazz opened this issue Dec 19, 2024 · 5 comments
Labels
bug Something isn't working

Comments

@MarqRazz
Copy link
Contributor

Description

Previously I have been running my robot on Iron binaries and only see this issue when running MoveIt from source on the main branch. As I have been debugging this I updated everything to Jazzy with MoveIt main (commit f91a650) and MTC ros2 (commit 8b4aa43) from source just to make sure I was not fighting some underlying compatibility issue.

The problem I noticed is that sometimes the PlanningScene display in Rviz will sometimes fail to update the robots pose at the end of trajectory execution. When this this update fails the objects that I am attaching will have an offset because the stored start state for the next move is out of date. I also noticed that on the next trajectory execution the command will jump to the old joint angles stored in the planning_scene_monitor and start moving from there as seen in the plot below around the 3.5 second mark.
Image

From my understanding the planning_scene_monitor runs at 2Hz and only updates it's internal copy of the robots state when it is in motion. My question is how does the planning_scene_monitor get updated at the end of trajectory execution if it happens to fall between the 2Hz update cycle?

I have been trying to debug the issue but am falling short, so I'm hoping someone here can help point me in the right direction. I have changed several of the DEBUG messages in the planning_scene_monitor and below is the output when the trajectory executes as expected and the planning scene finishes with the same state as the values reported on the /joint_states topic. Notice the final print where the robot stamp: 0.648387 has a recent value compared to the scene update time. You can also see when it prints scene update / robot stamp that it does it once from the planning_scene_monitor as it publishes and a second time when Rviz receives the update.

[taskset-1] [arm_controller 1734640527.846920936]: Accepted new action goal
[move_group-5] [moveit.simple_controller_manager.follow_joint_trajectory_controller_handle 1734640527.846949904]: arm_controller started execution
[move_group-5] [moveit.simple_controller_manager.follow_joint_trajectory_controller_handle 1734640527.846951886]: Goal request accepted!
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640528.311406225]: Publishing planning scene. Joint State time stamp: '1734640528'
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640528.311562017]: Published full planning scene: '(noname)++++++++++++'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640528.311633342]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640528.311643364]: scene update 8.311642 robot stamp: 8.306387
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640528.519160292]: performPendingStateUpdate: 8.519160
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640528.519206448]: performPendingStateUpdate done
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640528.811421472]: Publishing planning scene. Joint State time stamp: '1734640528'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640528.811541636]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640528.811554874]: scene update 8.811554 robot stamp: 8.790388
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640529.311477685]: Publishing planning scene. Joint State time stamp: '1734640529'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640529.311577417]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640529.311586224]: scene update 9.311585 robot stamp: 9.308389
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640529.811536955]: Publishing planning scene. Joint State time stamp: '1734640529'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640529.811645162]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640529.811653738]: scene update 9.811653 robot stamp: 9.791387
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.311601919]: Publishing planning scene. Joint State time stamp: '1734640530'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640530.311778219]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640530.311792577]: scene update 0.311791 robot stamp: 0.310389
[taskset-1] [arm_controller 1734640530.618392231]: Goal reached, success!
[move_group-5] [moveit.simple_controller_manager.follow_joint_trajectory_controller_handle 1734640530.647074009]: Controller 'arm_controller' successfully finished
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640530.647110483]: apply effect of 8/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.647131665]: scene update 0.647131 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640530.647320202]: Returned 1 controllers in list
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640530.647331517]: Returned 1 controllers in list
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640530.647337079]: apply effect of 9/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.647340708]: scene update 0.647341 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640530.647445290]: Returned 1 controllers in list
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640530.647453481]: Returned 1 controllers in list
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640530.647458610]: apply effect of 10/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.647461184]: scene update 0.647461 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640530.647499484]: Returned 1 controllers in list
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640530.647504783]: Returned 1 controllers in list
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640530.647507728]: apply effect of 11/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.647509339]: scene update 0.647509 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640530.647520848]: Returned 1 controllers in list
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640530.647525538]: Returned 1 controllers in list
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640530.647528568]: apply effect of 12/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.647529960]: scene update 0.647530 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.ros.trajectory_execution_manager 1734640530.647592415]: Waiting for trajectory completion with a tolerance of: 0.001000
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.649157312]: performPendingStateUpdate: 0.649157
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.649176530]: performPendingStateUpdate done
[move_group-5] [move_group.moveit.moveit.ros.trajectory_execution_manager 1734640530.650510407]: Completed trajectory execution with status SUCCEEDED ...
[pick_execution_node-9] [pick_execution_node 1734640530.791149948]: Goal succeeded
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.811722498]: Publishing planning scene. Joint State time stamp: '1734640530'
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640530.811823133]: Published full planning scene: '(noname)+++++++++++++++'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640530.811895618]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640530.811908023]: scene update 0.811907 robot stamp: 0.648387

Here is the output when the planning scene fails to update at the end of trajectory execution.

[taskset-1] [arm_controller 1734640637.828714035]: Accepted new action goal
[move_group-5] [moveit.simple_controller_manager.follow_joint_trajectory_controller_handle 1734640637.828746500]: arm_controller started execution
[move_group-5] [moveit.simple_controller_manager.follow_joint_trajectory_controller_handle 1734640637.828750633]: Goal request accepted!
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640638.266359625]: Publishing planning scene. Joint State time stamp: '1734640638'
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640638.266494875]: Published full planning scene: '(noname)++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640638.266555835]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640638.266565910]: scene update 8.266565 robot stamp: 8.256387
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640638.349157376]: performPendingStateUpdate: 8.349157
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640638.349188442]: performPendingStateUpdate done
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640638.379157694]: performPendingStateUpdate: 8.379158
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640638.379188718]: performPendingStateUpdate done
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640638.409160727]: performPendingStateUpdate: 8.409160
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640638.409208786]: performPendingStateUpdate done
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640638.766359757]: Publishing planning scene. Joint State time stamp: '1734640638'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640638.766463710]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640638.766473811]: scene update 8.766473 robot stamp: 8.742387
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640639.266422623]: Publishing planning scene. Joint State time stamp: '1734640639'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640639.266526737]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640639.266536486]: scene update 9.266536 robot stamp: 9.261387
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640639.766479251]: Publishing planning scene. Joint State time stamp: '1734640639'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640639.766579763]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640639.766589558]: scene update 9.766588 robot stamp: 9.745387
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.266541743]: Publishing planning scene. Joint State time stamp: '1734640640'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640640.266642522]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640640.266651663]: scene update 0.266651 robot stamp: 0.265388
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.599160602]: performPendingStateUpdate: 0.599160
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.599207481]: performPendingStateUpdate done
[taskset-1] [arm_controller 1734640640.658391448]: Goal reached, success!
[move_group-5] [moveit.simple_controller_manager.follow_joint_trajectory_controller_handle 1734640640.678874477]: Controller 'arm_controller' successfully finished
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640640.678907191]: apply effect of 8/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.678924139]: scene update 0.678924 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640640.679120555]: Returned 1 controllers in list
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640640.679131891]: Returned 1 controllers in list
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640640.679138110]: apply effect of 9/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.679141119]: scene update 0.679141 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640640.679236746]: Returned 1 controllers in list
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640640.679244907]: Returned 1 controllers in list
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640640.679249592]: apply effect of 10/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.679251673]: scene update 0.679251 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640640.679301897]: Returned 1 controllers in list
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640640.679307325]: Returned 1 controllers in list
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640640.679310551]: apply effect of 11/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.679312280]: scene update 0.679312 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640640.679323235]: Returned 1 controllers in list
[move_group-5] [move_group.moveit.moveit.plugins.simple_controller_manager 1734640640.679327858]: Returned 1 controllers in list
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734640640.679331421]: apply effect of 12/12
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.679333355]: scene update 0.679333 robot stamp: 0.000000
[move_group-5] [move_group.moveit.moveit.ros.trajectory_execution_manager 1734640640.679385866]: Waiting for trajectory completion with a tolerance of: 0.001000
[move_group-5] [move_group.moveit.moveit.ros.trajectory_execution_manager 1734640640.682703618]: Completed trajectory execution with status SUCCEEDED ...
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.766675965]: Publishing planning scene. Joint State time stamp: '0'
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734640640.766784684]: Published full planning scene: '(noname)+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++'
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640640.766894386]: newPlanningSceneMessage received
[rviz2-10] [rviz2.moveit.ros.planning_scene_monitor 1734640640.766904161]: scene update 0.766903 robot stamp: 0.000000

ROS Distro

Jazzy

OS and version

Ubuntu 22.04 with Jazzy in Docker

Source or binary build?

Source

If binary, which release version?

No response

If source, which branch?

main

Which RMW are you using?

CycloneDDS

Steps to Reproduce

I can't post my code and can't reproduce the issue with the Panda/MTC demo.

Expected behavior

Planning scene updates at the end of trajectory execution

Actual behavior

The robot state fails to update and gives incorrect start state for the next motion.

Backtrace or Console output

No response

@MarqRazz MarqRazz added the bug Something isn't working label Dec 19, 2024
@mikeferguson
Copy link
Contributor

Is #3019 possibly related? (not sure why this would be more of an issue in Jazzy than Iron, but there is a noted PR in MoveIt 1 that has yet to be ported to ROS 2)

@MarqRazz
Copy link
Contributor Author

I'm not using the Octomap so I don't think that is related, but thanks for taking a look @mikeferguson! To verify I tried to disable and enable the scene and it still has out of date information. I have also double checked the topic /monitored_planning_scene can see out of date joint state information is published as the final message after a trajectory completes.

@MarqRazz
Copy link
Contributor Author

MarqRazz commented Dec 23, 2024

So I have started a debug branch here that includes additional print messages as the planning scene is updated.

Here is what I have found/debugged so far...

  • In the planning_scene I am printing the current value of the robots first joint poisition in getCurrentStateNonConst(). Right now I am grabbing the value with robot_state_.value().getVariablePosition(0) (this works on my custom robot). I also tried to get it by using the joint's name but it only prints zeros when I do this for my custom robot and the Panda (example: robot_state_.value().getJointPositions("panda_joint1")). For some reason when I test both approaches out on the MTC pick and place demo with the Panda robot it never reports the value of joint 1 🤷. Any suggestion on how I can improve this output would be appreciated! Edit... fixed, I was printing the value of the pointer 🙄
  • As MTC executes the trajectory it applies planning scene diffs according to the task you setup but never publishes joint_states as part of its messages because that is done by the trajectory execution itself.
  • When processing Attached Collision Objects the updated robot_state_ is frequently out of date compared to the values reported by getCurrentStateNonConst()
    For example:
[move_group-5] [move_group.moveit.moveit.core.planning_scene 1734990499.656706724]: getCurrentStateNonConst(), joint 1: 0.687060
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734990499.656713884]: performPendingStateUpdate done
[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734990499.671182139]: apply effect of 8/12
[move_group-5] [move_group.moveit.moveit.core.planning_scene 1734990499.671291084]: Updated robot_state_ has joint 1: 0.622864
  • In the run I include below the final value for joint 1 should be 0.687060 but the last value reported by the planning_scene_monitor is 0.622864.
    As the robot is executing you can see the planning_scene_monitor updates at 2Hz. You will notice that the last value published while the robot is moving happens to match the the outdated scene info at the end of execution even though the current_state_monitor continues to receive updated information. It prints...
[move_group-5] [move_group.moveit.moveit.ros.planning_scene_monitor 1734990499.454272314]: Publishing planning scene. Joint 1: 0.622864
[rviz2-10] [rviz2.moveit.core.planning_scene 1734990499.454390323]: getCurrentStateNonConst(), joint 1: 0.622864

Then joint_states continue to update till the arm_controller reports [taskset-1] [arm_controller 1734990499.624470912]: Goal reached, success!

Once the trajectory has completed MTC applies changes to the planning scene to delete the attached collision object. These steps are reported by the prints apply effect 8-12. For example below you can see that the joint position is out of date compared to the desired end of the trajectory.

[move_group-5] [moveit_task_constructor_visualization.execute_task_solution 1734990499.671540159]: apply effect of 10/12
[move_group-5] [move_group.moveit.moveit.core.planning_scene 1734990499.671543193]: Adding planning scene diff
[move_group-5] [move_group.moveit.moveit.core.planning_scene 1734990499.671555514]: getCurrentStateNonConst(), joint 1: 0.622864
[move_group-5] [move_group.moveit.moveit.core.planning_scene 1734990499.671560217]: Updated robot_state_ has joint 1: 0.622864
[move_group-5] [move_group.moveit.moveit.core.planning_scene 1734990499.671568458]: Updated robot_state_ has joint 1: 0.622864

Here is the raw terminal output for inspection

@MarqRazz
Copy link
Contributor Author

Okay I kind of have a reproducible example with the Panda robot and the MTC demo.
To run it grab this MoveIt2 branch and this MTC branch. Build and ....

ros2 launch moveit_task_constructor_demo demo.launch.py
ros2 launch moveit_task_constructor_demo run.launch.py exe:=pick_place_demo

The issue is not as bad when running the Panda robot but you can see below that the /monitored_planning_scene finishes with joint state data that is out of date compared to where the robot finishes. On this run the last waypoint in the trajectory has Joint 1 at 0.087734 but the final value sent from the planning_scene_monitor is 0.091339.

[move_group-4] [move_group.moveit.moveit.ros.planning_scene_monitor 1735057702.233369461]: robot state update 2.233119
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.233385765]: getCurrentStateNonConst, joint 1: 0.088266
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.233393892]: getCurrentStateNonConst, joint 1: 0.087853
[ros2_control_node-5] [panda_arm_controller 1735057702.259123015]: Goal reached, success!
[move_group-4] [move_group.moveit.moveit.ros.planning_scene_monitor 1735057702.271188788]: performPendingStateUpdate: 2.271188
[move_group-4] [move_group.moveit.moveit.ros.planning_scene_monitor 1735057702.271199205]: robot state update 2.270118
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.271205921]: getCurrentStateNonConst, joint 1: 0.087853
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.271213249]: getCurrentStateNonConst, joint 1: 0.087734
[move_group-4] [move_group.moveit.moveit.ros.planning_scene_monitor 1735057702.271216665]: performPendingStateUpdate done
[move_group-4] [moveit.simple_controller_manager.follow_joint_trajectory_controller_handle 1735057702.274862627]: Controller 'panda_arm_controller' successfully finished
[move_group-4] [moveit_task_constructor_visualization.execute_task_solution 1735057702.274890492]: apply effect of 12/16
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.274958474]: Setting new planning scene: '(noname)+++++++++++'
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.274978653]: Updated robot_state_ has joint 1: 0.091339
[move_group-4] [move_group.moveit.moveit.plugins.simple_controller_manager 1735057702.275054174]: Returned 2 controllers in list
[move_group-4] [move_group.moveit.moveit.plugins.simple_controller_manager 1735057702.275070145]: Returned 2 controllers in list
[move_group-4] [moveit_task_constructor_visualization.execute_task_solution 1735057702.275081922]: apply effect of 13/16
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.275097042]: Setting new planning scene: '(noname)+++++++++++'
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.275106899]: Updated robot_state_ has joint 1: 0.091339
[move_group-4] [move_group.moveit.moveit.plugins.simple_controller_manager 1735057702.275145921]: Returned 2 controllers in list
[move_group-4] [move_group.moveit.moveit.plugins.simple_controller_manager 1735057702.275157561]: Returned 2 controllers in list
[move_group-4] [moveit_task_constructor_visualization.execute_task_solution 1735057702.275165978]: apply effect of 14/16
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.275173393]: Adding planning scene diff
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.275198720]: getCurrentStateNonConst, joint 1: 0.091339
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.275209494]: Updated robot_state_ has joint 1: 0.091339
[move_group-4] [move_group.moveit.moveit.plugins.simple_controller_manager 1735057702.275244799]: Returned 2 controllers in list
[move_group-4] [move_group.moveit.moveit.plugins.simple_controller_manager 1735057702.275256454]: Returned 2 controllers in list
[move_group-4] [moveit_task_constructor_visualization.execute_task_solution 1735057702.275264726]: apply effect of 15/16
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.275277191]: Adding planning scene diff
[move_group-4] [move_group.moveit.moveit.plugins.simple_controller_manager 1735057702.275294367]: Returned 2 controllers in list
[move_group-4] [move_group.moveit.moveit.plugins.simple_controller_manager 1735057702.275305111]: Returned 2 controllers in list
[move_group-4] [moveit_task_constructor_visualization.execute_task_solution 1735057702.275313101]: apply effect of 16/16
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.275319822]: Adding planning scene diff
[move_group-4] [move_group.moveit.moveit.ros.trajectory_execution_manager 1735057702.275346110]: Waiting for trajectory completion with allowed_start_tolerance: 0.010
[move_group-4] [move_group.moveit.moveit.ros.trajectory_execution_manager 1735057702.278293010]: Completed trajectory execution with status SUCCEEDED ...
[move_group-4] [move_group.moveit.moveit.ros.planning_scene_monitor 1735057702.372531828]: pushDiffs(parent_scene_)
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.372549484]: getCurrentStateNonConst, joint 1: 0.091339
[move_group-4] [move_group.moveit.moveit.ros.planning_scene_monitor 1735057702.372566550]: ------------
[move_group-4] [move_group.moveit.moveit.core.planning_scene 1735057702.372587549]: getPlanningSceneMsg() Joint 1 state: 0.091339
[move_group-4] [move_group.moveit.moveit.ros.planning_scene_monitor 1735057702.372601712]: Publishing planning scene. Joint 1: 0.091339
[move_group-4] [move_group.moveit.moveit.ros.planning_scene_monitor 1735057702.372672821]: Published full planning scene: '(noname)++++++++++++++'
[rviz2-1] [rviz2.moveit.core.planning_scene 1735057702.372774933]: Setting new planning scene: '(noname)++++++++++++++'
[rviz2-1] [rviz2.moveit.core.planning_scene 1735057702.372864202]: getCurrentStateNonConst, joint 1: 0.091339

The results very from run to run and you can execute the solutions multiple times without restarting the demo by selecting solutions and clicking the Exec button in the MTC solution panel.
Image

@MarqRazz
Copy link
Contributor Author

So when I run my custom robot I noticed that performPendingStateUpdate is not periodic and randomly runs every 1 to 3 seconds. When I test this on the Panda robot example it runs every 30-300mSec.

I can see that this if statement logic goes all the way back to a ROS1 bug but don't get why dt.count() >= dt_state_update_.count() makes a good trigger. last_robot_state_update_wall_time_ gets updated with every state update message so the chances of dt being greater than dt_state_update_ seems like a roll of the dice and very dependent on the system load and CPU.
@rhaschke would you have any suggestions on how frequently updateSceneWithCurrentState should run? FYI I tried changing the frequency that updateSceneWithCurrentState runs to match dt_state_update_ but I still have issues with my setup. Note dt_state_update_ is hard coded to 30mSec even though the header file says 1Hz.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants