search

osrf / subt

This repostory contains software for the virtual track of the DARPA SubT Challenge. Within this repository you will find Gazebo simulation assets, ROS interfaces, support scripts and plugins, and documentation needed to compete in the SubT Virtual Challenge.
Other
305 stars 98 forks source link

Timing issues on cloudsim #619

Open realdealneil opened 4 years ago

realdealneil commented 4 years ago

We have been regularly uploading images to cloudsim and testing. Last night, I uploaded a few runs, and most of them went pretty normal, but one of them had some significant timing issues at the beginning of the run that ended up causing our tf trees to not be constructed properly on two vehicles due to initialization order. Our solution consisted of 4 vehicles, 2 of which suffered from unconnected tf trees, and I believe the subt timing was the source of the problem. Here is a sample of the beginning of the log file:

0.000000000 Node Startup 0.000000000 INFO /tf_world_static [/tmp/binarydeb/ros-melodic-tf2-ros-0.6.5/src/static_transform_broadcaster_program.cpp:142(main)] [topics: /rosout, /tf_static] Spinning until killed publishing world to simple_cave_02 21.024000000 INFO /rosbag_robot_data [/tmp/binarydeb/ros-melodic-rosbag-1.14.9/src/recorder.cpp:394(Recorder::startWriting)] [topics: /rosout] Recording to '/home/developer/.ros/robot_data_0.bag'. 0.000000000 INFO /D2/optical_frame_publisher [/home/developer/subt_ws/src/subt/subt_ros/src/OpticalFramePublisher.cc:101(Init)] [topics: /rosout, /D2/front/optical/image_raw, /D2/front/optical/camera_info] Optical Frame Publisher Ready 0.000000000 INFO /D2_static_base [/tmp/binarydeb/ros-melodic-tf2-ros-0.6.5/src/static_transform_broadcaster_program.cpp:142(main)] [topics: /rosout, /tf_static] Spinning until killed publishing D2/base_link to base_link 0.000000000 INFO /D2/passthrough_x [/tmp/binarydeb/ros-melodic-roscpp-1.14.5/src/libros/service.cpp:123(service::waitForService)] [topics: /rosout] waitForService: Service [/D2/pcl_manager/load_nodelet] is now available. 0.000000000 INFO /D2/passthrough_y [/tmp/binarydeb/ros-melodic-roscpp-1.14.5/src/libros/service.cpp:123(service::waitForService)] [topics: /rosout] waitForService: Service [/D2/pcl_manager/load_nodelet] is now available. 0.000000000 INFO /D2/D2_pc2scan [/tmp/binarydeb/ros-melodic-nodelet-1.9.16/src/loader.cpp:233(Loader::Impl::advertiseRosApi)] [topics: /rosout] Initializing nodelet with 16 worker threads. 0.000000000 INFO /D2/D2_pc2scan2 [/tmp/binarydeb/ros-melodic-nodelet-1.9.16/src/loader.cpp:233(Loader::Impl::advertiseRosApi)] [topics: /rosout] Initializing nodelet with 16 worker threads. 0.000000000 INFO /D2/cartographer_node [/home/developer/subt_hello_world/catkin_base_ws/src/cartographer_ros/cartographer_ros/cartographer_ros/ros_log_sink.cc:51(ScopedRosLogSink::send)] [topics: /rosout, /tf, /D2/submap_list, /D2/trajectory_node_list, /D2/landmark_poses_list, /D2/constraint_list, /D2/scan_matched_points2] I0921 17:48:26.000000 97 map_builder_bridge.cc:136] Added trajectory with ID '0'. 0.000000000 ERROR /D2_joy_node [/tmp/binarydeb/ros-melodic-joy-1.13.0/src/joy_node.cpp:289(main)] [topics: /rosout, /diagnostics, /joy] Couldn't open joystick /dev/input/js0. Will retry every second. 0.000000000 INFO /D2/pcl_manager [/tmp/binarydeb/ros-melodic-nodelet-1.9.16/src/loader.cpp:233(Loader::Impl::advertiseRosApi)] [topics: /rosout] Initializing nodelet with 16 worker threads. 0.000000000 INFO /D2/D2_pc2scan3 [/tmp/binarydeb/ros-melodic-nodelet-1.9.16/src/loader.cpp:233(Loader::Impl::advertiseRosApi)] [topics: /rosout] Initializing nodelet with 16 worker threads. 0.000000000 INFO /D2/D2_pc2scan4 [/tmp/binarydeb/ros-melodic-nodelet-1.9.16/src/loader.cpp:233(Loader::Impl::advertiseRosApi)] [topics: /rosout] Initializing nodelet with 16 worker threads. 54.992000000 WARN /D2/D2_tf_to_odom_publisher [/home/developer/subt_ws/src/ssci_src/ssci_control/src/odom_from_tf.cpp:122(main)] [topics: /rosout, /D2/cartographer_odom, /D2/cartographer_telemetry] "artifact" passed to lookupTransform argument target_frame does not exist. 0.000000000 INFO /D2/octomap_server [/home/developer/subt_ws/src/ssci_src/octomap_mapping/octomap_server/src/OctomapServer.cpp:166(OctomapServer::OctomapServer)] [topics: /rosout, /D2/octomap_server/parameter_descriptions, /D2/octomap_server/parameter_updates] Publishing non-latched (topics are only prepared as needed, will only be re-published on map change 0.000000000 WARN /D2/octomap_server [/home/developer/subt_ws/src/ssci_src/octomap_mapping/octomap_server/src/OctomapServer.cpp:488(OctomapServer::publishAll)] [topics: /rosout, /D2/octomap_server/parameter_descriptions, /D2/octomap_server/parameter_updates, /D2/occupied_cells_vis_array, /D2/merged_map, /D2/octomap_full, /D2/octomap_point_cloud_centers, /D2/projected_map, /D2/free_cells_vis_array] Nothing to publish, octree is empty 0.000000000 ERROR /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:61(Controller)] [topics: /rosout] Invalid start time: 0.000000...waiting for valid time! 0.000000000 INFO /D2/darknet_ros [/home/developer/subt_ws/src/ssci_src/darknet_ros/darknet_ros/src/YoloObjectDetector.cpp:85(YoloObjectDetector::init)] [topics: /rosout] [YoloObjectDetector] init(). 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:66(Controller)] [topics: /rosout, /statistics] SETTING VEHICLE START TIME NOW (55.068000) 55.068000000 INFO /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:91(Controller)] [topics: /rosout, /statistics] Sent start signal. 55.068000000 INFO /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:441(LoadParameters)] [topics: /rosout, /statistics] Loading ROS Parameters: 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:449(LoadParameters)] [topics: /rosout, /statistics] first_vehicle_wait_time: 5.000000 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:451(LoadParameters)] [topics: /rosout, /statistics] Go to entrance? YES! 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:471(LoadParameters)] [topics: /rosout, /statistics] Follow LEFT walls!!!! (string = TURN_LEFT) 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:474(LoadParameters)] [topics: /rosout, /statistics] SwitchWallDirAfterReport = true 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:477(LoadParameters)] [topics: /rosout, /statistics] use_steering_field = false 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:480(LoadParameters)] [topics: /rosout, /statistics] use_potential_fields = true 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:483(LoadParameters)] [topics: /rosout, /statistics] enable_room_exploration = false 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:486(LoadParameters)] [topics: /rosout, /statistics] enable_cloud_printing = true 55.068000000 WARN /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:489(LoadParameters)] [topics: /rosout, /statistics] enable_rail_transition = false 55.068000000 INFO /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:512(LoadParameters)] [topics: /rosout, /statistics] Time Limit: 2700.000000 55.068000000 INFO /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:514(LoadParameters)] [topics: /rosout, /statistics] Land Home Distance: 0.000000 55.068000000 INFO /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:515(LoadParameters)] [topics: /rosout, /statistics] Min Speed: 0.500000 55.068000000 INFO /D2_control [/home/developer/subt_ws/src/ssci_src/ssci_control/include/ssci_control/ssci_control.cpp:516(LoadParameters)] [topics: /rosout, /statistics] Max Speed: 3.000000

Note how the timestamps first are set to 0.0, then jump to another value (21.024000000), then BACK TO 0.000. Eventually, the clock settles at a valid value of 55.068000000 and marches on from there. But, it looks like the clock was going back and forth from 0.0 to valid values. This indicates that other nodes that were launched from the same launch file were launched before the clock had really settled, and this indicates to me that some subt processes were still initializing. We use a script that tries to detect instances like this, but 56.0 seconds is much longer than we expected to have to deal with. I think this issue is getting more common as cloudsim gets more congested. We will try to put a work-around in place (using /subt/run_clock), but I don't know that this will behave any better.

nkoenig commented 4 years ago

What groupid produced these logs?

realdealneil commented 4 years ago

This was the run entitled svn872v4s2-d657eecc-f410-4e07-88f0-289ff2cd1413 for Scientific Systems. We launched 4 vehicles, A1, A2, D1, and D2. A1 (UGV) and D2 (UAV) were the ones that had issues with tf not getting initialized correctly. All four vehicle logs show the same clock problems. I'm not sure if this tells you what you need...

nkoenig commented 4 years ago

Thanks, I'll take a look.