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.

Sign up for GitHub

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

Jump to bottom

Excessive CPU load (~100% over 8 threads) for APM + MAVROS inside Docker container #1185

Closed
ChrisTimperley opened this issue Feb 27, 2019 · 5 comments
Closed

Excessive CPU load (~100% over 8 threads) for APM + MAVROS inside Docker container #1185

ChrisTimperley opened this issue Feb 27, 2019 · 5 comments
Labels
bug question

Comments

@ChrisTimperley
Copy link

Issue details

I'm trying to run connect MAVROS to the ArduPilot's SITL from inside a Docker container (see attached for Dockerfile). APM runs without any problems inside the container. However, when I launch MAVROS, I observe a recurring error in the node logs, and the MAVROS consumes all available CPU resources.

hot_laptop

Interestingly, CPU usage also appears to be fairly high when only roscore is running.

cpu_roscore

MAVROS version and platform

MAVROS: 0.29.0
ROS: Kinetic / Lunar (occurs on both)
Container OS: Ubuntu 16.04 / 17.04
Host OS: Ubuntu 18.04 / Arch-2019.02.01 (same machine, different OS)
Machine: 14" Razer Blade, 2016. i7-6700HQ (4c/8t), 16GB DDR4, GTX 1060.

Autopilot type and version

[X] ArduPilot
[ ] PX4

Version: 3.6.4 (https://github.com/ArduPilot/ardupilot/releases/tag/Copter-3.6.4)

Node logs

... logging to /root/.ros/log/9d20e3c8-3a3e-11e9-907f-0242ac110002/roslaunch-9d820d31bf83-260.log
Checking log directory for disk usage. This may take awhile.
Press Ctrl-C to interrupt
Done checking log file disk usage. Usage is <1GB.

started roslaunch server http://9d820d31bf83:45085/

SUMMARY
========

CLEAR PARAMETERS
 * /mavros/

PARAMETERS
 * /mavros/cmd/use_comp_id_system_control: False
 * /mavros/conn/heartbeat_mav_type: ONBOARD_CONTROLLER
 * /mavros/conn/heartbeat_rate: 1.0
 * /mavros/conn/system_time_rate: 1.0
 * /mavros/conn/timeout: 10.0
 * /mavros/conn/timesync_rate: 10.0
 * /mavros/distance_sensor/rangefinder_pub/field_of_view: 0.0
 * /mavros/distance_sensor/rangefinder_pub/frame_id: lidar
 * /mavros/distance_sensor/rangefinder_pub/id: 0
 * /mavros/distance_sensor/rangefinder_pub/send_tf: False
 * /mavros/distance_sensor/rangefinder_pub/sensor_position/x: 0.0
 * /mavros/distance_sensor/rangefinder_pub/sensor_position/y: 0.0
 * /mavros/distance_sensor/rangefinder_pub/sensor_position/z: -0.1
 * /mavros/distance_sensor/rangefinder_sub/id: 1
 * /mavros/distance_sensor/rangefinder_sub/orientation: PITCH_270
 * /mavros/distance_sensor/rangefinder_sub/subscriber: True
 * /mavros/fake_gps/eph: 2.0
 * /mavros/fake_gps/epv: 2.0
 * /mavros/fake_gps/fix_type: 3
 * /mavros/fake_gps/geo_origin/alt: 408.0
 * /mavros/fake_gps/geo_origin/lat: 47.3667
 * /mavros/fake_gps/geo_origin/lon: 8.55
 * /mavros/fake_gps/gps_rate: 5.0
 * /mavros/fake_gps/mocap_transform: True
 * /mavros/fake_gps/satellites_visible: 5
 * /mavros/fake_gps/tf/child_frame_id: fix
 * /mavros/fake_gps/tf/frame_id: map
 * /mavros/fake_gps/tf/listen: False
 * /mavros/fake_gps/tf/rate_limit: 10.0
 * /mavros/fake_gps/tf/send: False
 * /mavros/fake_gps/use_mocap: True
 * /mavros/fake_gps/use_vision: False
 * /mavros/fcu_protocol: v2.0
 * /mavros/fcu_url: tcp://127.0.0.1:5...
 * /mavros/gcs_url: 
 * /mavros/global_position/child_frame_id: base_link
 * /mavros/global_position/frame_id: map
 * /mavros/global_position/gps_uere: 1.0
 * /mavros/global_position/rot_covariance: 99999.0
 * /mavros/global_position/tf/child_frame_id: base_link
 * /mavros/global_position/tf/frame_id: map
 * /mavros/global_position/tf/global_frame_id: earth
 * /mavros/global_position/tf/send: False
 * /mavros/global_position/use_relative_alt: True
 * /mavros/image/frame_id: px4flow
 * /mavros/imu/angular_velocity_stdev: 0.000349065850399
 * /mavros/imu/frame_id: base_link
 * /mavros/imu/linear_acceleration_stdev: 0.0003
 * /mavros/imu/magnetic_stdev: 0.0
 * /mavros/imu/orientation_stdev: 1.0
 * /mavros/local_position/frame_id: map
 * /mavros/local_position/tf/child_frame_id: base_link
 * /mavros/local_position/tf/frame_id: map
 * /mavros/local_position/tf/send: False
 * /mavros/local_position/tf/send_fcu: False
 * /mavros/mission/pull_after_gcs: True
 * /mavros/mocap/use_pose: True
 * /mavros/mocap/use_tf: False
 * /mavros/odometry/estimator_type: 3
 * /mavros/odometry/frame_tf/desired_frame: ned
 * /mavros/plugin_blacklist: ['actuator_contro...
 * /mavros/plugin_whitelist: []
 * /mavros/px4flow/frame_id: px4flow
 * /mavros/px4flow/ranger_fov: 0.118682389136
 * /mavros/px4flow/ranger_max_range: 5.0
 * /mavros/px4flow/ranger_min_range: 0.3
 * /mavros/safety_area/p1/x: 1.0
 * /mavros/safety_area/p1/y: 1.0
 * /mavros/safety_area/p1/z: 1.0
 * /mavros/safety_area/p2/x: -1.0
 * /mavros/safety_area/p2/y: -1.0
 * /mavros/safety_area/p2/z: -1.0
 * /mavros/setpoint_accel/send_force: False
 * /mavros/setpoint_attitude/reverse_thrust: False
 * /mavros/setpoint_attitude/tf/child_frame_id: target_attitude
 * /mavros/setpoint_attitude/tf/frame_id: map
 * /mavros/setpoint_attitude/tf/listen: False
 * /mavros/setpoint_attitude/tf/rate_limit: 50.0
 * /mavros/setpoint_attitude/use_quaternion: False
 * /mavros/setpoint_position/mav_frame: LOCAL_NED
 * /mavros/setpoint_position/tf/child_frame_id: target_position
 * /mavros/setpoint_position/tf/frame_id: map
 * /mavros/setpoint_position/tf/listen: False
 * /mavros/setpoint_position/tf/rate_limit: 50.0
 * /mavros/setpoint_velocity/mav_frame: LOCAL_NED
 * /mavros/startup_px4_usb_quirk: False
 * /mavros/sys/disable_diag: False
 * /mavros/sys/min_voltage: 10.0
 * /mavros/target_component_id: 1
 * /mavros/target_system_id: 1
 * /mavros/tdr_radio/low_rssi: 40
 * /mavros/time/time_ref_source: fcu
 * /mavros/time/timesync_avg_alpha: 0.6
 * /mavros/time/timesync_mode: MAVLINK
 * /mavros/vibration/frame_id: base_link
 * /mavros/vision_pose/tf/child_frame_id: vision_estimate
 * /mavros/vision_pose/tf/frame_id: map
 * /mavros/vision_pose/tf/listen: False
 * /mavros/vision_pose/tf/rate_limit: 10.0
 * /mavros/vision_speed/listen_twist: True
 * /mavros/vision_speed/twist_cov: True
 * /mavros/wheel_odometry/child_frame_id: base_link
 * /mavros/wheel_odometry/count: 2
 * /mavros/wheel_odometry/frame_id: map
 * /mavros/wheel_odometry/send_raw: True
 * /mavros/wheel_odometry/send_twist: False
 * /mavros/wheel_odometry/tf/child_frame_id: base_link
 * /mavros/wheel_odometry/tf/frame_id: map
 * /mavros/wheel_odometry/tf/send: True
 * /mavros/wheel_odometry/use_rpm: False
 * /mavros/wheel_odometry/vel_error: 0.1
 * /mavros/wheel_odometry/wheel0/radius: 0.05
 * /mavros/wheel_odometry/wheel0/x: 0.0
 * /mavros/wheel_odometry/wheel0/y: -0.15
 * /mavros/wheel_odometry/wheel1/radius: 0.05
 * /mavros/wheel_odometry/wheel1/x: 0.0
 * /mavros/wheel_odometry/wheel1/y: 0.15
 * /rosdistro: lunar
 * /rosversion: 1.13.7

NODES
  /
    mavros (mavros/mavros_node)

ROS_MASTER_URI=http://localhost:11311

process[mavros-1]: started with pid [278]
[ INFO] [1551238038.673401191]: FCU URL: tcp://127.0.0.1:5760@5760
[ INFO] [1551238038.676633756]: tcp0: Server address: 127.0.0.1:5760
setup:307: bad header in setup - erasing
[ INFO] [1551238038.676971256]: GCS bridge disabled
bind port 5762 for 2
Serial port 2 on TCP port 5762
bind port 5763 for 3
Serial port 3 on TCP port 5763
Smoothing reset at 0.001
[ INFO] [1551238038.691776790]: Plugin 3dr_radio loaded
[ INFO] [1551238038.694401517]: Plugin 3dr_radio initialized
[ INFO] [1551238038.694450754]: Plugin actuator_control blacklisted
[ INFO] [1551238038.698711092]: Plugin adsb loaded
[ INFO] [1551238038.703476691]: Plugin adsb initialized
[ INFO] [1551238038.703549727]: Plugin altitude blacklisted
[ INFO] [1551238038.703852012]: Plugin cam_imu_sync loaded
[ INFO] [1551238038.704992032]: Plugin cam_imu_sync initialized
[ INFO] [1551238038.705247989]: Plugin command loaded
[ INFO] [1551238038.713219804]: Plugin command initialized
[ INFO] [1551238038.713465686]: Plugin companion_process_status loaded
[ INFO] [1551238038.716864057]: Plugin companion_process_status initialized
[ INFO] [1551238038.716908735]: Plugin debug_value blacklisted
[ INFO] [1551238038.717170319]: Plugin distance_sensor loaded
[ INFO] [1551238038.729157899]: Plugin distance_sensor initialized
[ INFO] [1551238038.729485832]: Plugin fake_gps loaded
[ INFO] [1551238038.748460824]: Plugin fake_gps initialized
[ INFO] [1551238038.748517318]: Plugin ftp blacklisted
[ INFO] [1551238038.748862769]: Plugin global_position loaded
[ INFO] [1551238038.771534506]: Plugin global_position initialized
[ INFO] [1551238038.771776232]: Plugin gps_rtk loaded
[ INFO] [1551238038.775434848]: Plugin gps_rtk initialized
[ INFO] [1551238038.775479226]: Plugin hil blacklisted
[ INFO] [1551238038.775745992]: Plugin home_position loaded
[ INFO] [1551238038.781335293]: Plugin home_position initialized
[ INFO] [1551238038.781709465]: Plugin imu loaded
[ INFO] [1551238038.792540416]: Plugin imu initialized
[ INFO] [1551238038.793310967]: Plugin local_position loaded
[ INFO] [1551238038.802639732]: Plugin local_position initialized
[ INFO] [1551238038.802936049]: Plugin log_transfer loaded
[ INFO] [1551238038.807073810]: Plugin log_transfer initialized
[ INFO] [1551238038.807425940]: Plugin manual_control loaded
[ INFO] [1551238038.812396519]: Plugin manual_control initialized
[ INFO] [1551238038.812695793]: Plugin mocap_pose_estimate loaded
[ INFO] [1551238038.818711985]: Plugin mocap_pose_estimate initialized
[ INFO] [1551238038.818949805]: Plugin obstacle_distance loaded
[ INFO] [1551238038.822409954]: Plugin obstacle_distance initialized
[ INFO] [1551238038.822672808]: Plugin odom loaded
[ INFO] [1551238038.830855145]: Plugin odom initialized
[ INFO] [1551238038.831312835]: Plugin param loaded
[ INFO] [1551238038.835820397]: Plugin param initialized
[ INFO] [1551238038.835874173]: Plugin px4flow blacklisted
[ INFO] [1551238038.836133734]: Plugin rangefinder loaded
[ INFO] [1551238038.837210097]: Plugin rangefinder initialized
[ INFO] [1551238038.837615588]: Plugin rc_io loaded
[ INFO] [1551238038.843197955]: Plugin rc_io initialized
[ INFO] [1551238038.843246328]: Plugin safety_area blacklisted
[ INFO] [1551238038.843568719]: Plugin setpoint_accel loaded
[ INFO] [1551238038.848271639]: Plugin setpoint_accel initialized
[ INFO] [1551238038.848726382]: Plugin setpoint_attitude loaded
[ INFO] [1551238038.864069321]: Plugin setpoint_attitude initialized
[ INFO] [1551238038.864449859]: Plugin setpoint_position loaded
[ INFO] [1551238038.884629307]: Plugin setpoint_position initialized
[ INFO] [1551238038.884910213]: Plugin setpoint_raw loaded
[ INFO] [1551238038.898468954]: Plugin setpoint_raw initialized
[ INFO] [1551238038.898819668]: Plugin setpoint_velocity loaded
[ INFO] [1551238038.907267925]: Plugin setpoint_velocity initialized
[ INFO] [1551238038.907788280]: Plugin sys_status loaded
[ INFO] [1551238038.923480041]: Plugin sys_status initialized
[ INFO] [1551238038.923805013]: Plugin sys_time loaded
[ INFO] [1551238038.932515806]: TM: Timesync mode: MAVLINK
[ INFO] [1551238038.934191004]: Plugin sys_time initialized
[ INFO] [1551238038.934481164]: Plugin trajectory loaded
[ INFO] [1551238038.942206535]: Plugin trajectory initialized
[ INFO] [1551238038.942586449]: Plugin vfr_hud loaded
[ INFO] [1551238038.943596888]: Plugin vfr_hud initialized
[ INFO] [1551238038.943659062]: Plugin vibration blacklisted
[ INFO] [1551238038.943878171]: Plugin vision_pose_estimate loaded
[ INFO] [1551238038.954680711]: Plugin vision_pose_estimate initialized
[ INFO] [1551238038.954742768]: Plugin vision_speed_estimate blacklisted
[ INFO] [1551238038.955090938]: Plugin waypoint loaded
[ INFO] [1551238038.961822273]: Plugin waypoint initialized
[ INFO] [1551238038.961872662]: Plugin wheel_odometry blacklisted
[ INFO] [1551238038.962112749]: Plugin wind_estimation loaded
[ INFO] [1551238038.963228186]: Plugin wind_estimation initialized
[ INFO] [1551238038.963326773]: Built-in SIMD instructions: SSE, SSE2
[ INFO] [1551238038.963368089]: Built-in MAVLink package version: 2019.2.2
[ INFO] [1551238038.963401847]: Known MAVLink dialects: common ardupilotmega ASLUAV autoquad icarous matrixpilot paparazzi slugs standard uAvionix ualberta
[ INFO] [1551238038.963437602]: MAVROS started. MY ID 1.240, TARGET ID 1.1
[ WARN] [1551238039.546025179]: TM : RTT too high for timesync: 11.41 ms.
Remaining: 0.250000 litres
Pump: 0.000000 l/s
Spinner: 0.000000 rev/s
position_demand=0.000000 jaw_gap=30.000000 load=0.000000
[ INFO] [1551238039.710580174]: CON: Got HEARTBEAT, connected. FCU: ArduPilot
[ INFO] [1551238040.392155148]: FCU: Barometer calibration complete
[ WARN] [1551238040.650563281]: TM : RTT too high for timesync: 16.31 ms.
[ INFO] [1551238040.715135240]: VER: 1.1: Capabilities         0x0000000000003bcf
[ INFO] [1551238040.715203024]: VER: 1.1: Flight software:     030604ff ( 6c4da9e)
[ INFO] [1551238040.715242910]: VER: 1.1: Middleware software: 00000000 (        )
[ INFO] [1551238040.715277388]: VER: 1.1: OS software:         00000000 (        )
[ INFO] [1551238040.715309213]: VER: 1.1: Board hardware:      00000000
[ INFO] [1551238040.715341533]: VER: 1.1: VID/PID:             0000:0000
[ INFO] [1551238040.715372768]: VER: 1.1: UID:                 0000000000000000
[ WARN] [1551238040.715504926]: CMD: Unexpected command 520, result 0
[ERROR] [1551238041.140563398]: FCU: PreArm: RC Roll not configured
[ERROR] [1551238041.140704227]: FCU: PreArm: RC Pitch not configured
[ERROR] [1551238041.140816538]: FCU: PreArm: RC Throttle not configured
[ERROR] [1551238041.140915085]: FCU: PreArm: RC Yaw not configured
[ INFO] [1551238041.239837152]: FCU: GPS 1: detected as u-blox at 115200 baud
[ WARN] [1551238042.455874978]: TM : RTT too high for timesync: 20.66 ms.
[ INFO] [1551238042.830363858]: FCU: EKF2 IMU0 initial yaw alignment complete
[ INFO] [1551238042.830485660]: FCU: EKF2 IMU1 initial yaw alignment complete
[ WARN] [1551238043.065112795]: TM : RTT too high for timesync: 30.50 ms.
[ WARN] [1551238043.666019666]: TM : RTT too high for timesync: 31.72 ms.
[ INFO] [1551238043.732597316]: FCU: EKF2 IMU0 tilt alignment complete
[ INFO] [1551238043.732748445]: FCU: EKF2 IMU1 tilt alignment complete
[ WARN] [1551238044.254662081]: TM : RTT too high for timesync: 19.55 ms.
[ WARN] [1551238044.845644356]: TM : RTT too high for timesync: 10.53 ms.
[ WARN] [1551238045.450144456]: TM : RTT too high for timesync: 15.58 ms.
[ WARN] [1551238046.059107280]: TM : RTT too high for timesync: 24.25 ms.
[ WARN] [1551238046.659967721]: TM : RTT too high for timesync: 25.26 ms.
[ WARN] [1551238047.253886354]: TM : RTT too high for timesync: 18.90 ms.
[ WARN] [1551238047.853585452]: TM : RTT too high for timesync: 18.71 ms.
[ WARN] [1551238048.458600777]: TM : RTT too high for timesync: 23.40 ms.
[ WARN] [1551238049.055690469]: TM : RTT too high for timesync: 20.76 ms.
[ WARN] [1551238049.653167635]: TM : RTT too high for timesync: 18.43 ms.
[ INFO] [1551238049.710924644]: HP: requesting home position
[ INFO] [1551238049.720476616]: FCU: ArduCopter V3.6.4 (6c4da9e3)
[ INFO] [1551238049.720644223]: FCU: Frame: UNKNOWN
[ INFO] [1551238050.134494016]: PR: parameters list received
[ WARN] [1551238050.260175361]: TM : RTT too high for timesync: 25.18 ms.
[ WARN] [1551238050.855799571]: TM : RTT too high for timesync: 20.95 ms.
[ WARN] [1551238051.454136006]: TM : RTT too high for timesync: 19.78 ms.
[ WARN] [1551238052.058591209]: TM : RTT too high for timesync: 23.88 ms.
[ INFO] [1551238052.258868782]: FCU: EKF2 IMU0 Origin set to GPS
[ INFO] [1551238052.259176201]: FCU: EKF2 IMU1 Origin set to GPS
[ WARN] [1551238052.653949011]: TM : RTT too high for timesync: 19.00 ms.
[ WARN] [1551238053.254802757]: TM : RTT too high for timesync: 19.82 ms.
[ WARN] [1551238053.857933925]: TM : RTT too high for timesync: 22.99 ms.
[ WARN] [1551238054.454018666]: TM : RTT too high for timesync: 19.05 ms.
...

[ERROR] [1551238041.140563398]: FCU: PreArm: RC Roll not configured
[ERROR] [1551238041.140704227]: FCU: PreArm: RC Pitch not configured
[ERROR] [1551238041.140816538]: FCU: PreArm: RC Throttle not configured
[ERROR] [1551238041.140915085]: FCU: PreArm: RC Yaw not configured
[ INFO] [1551238041.239837152]: FCU: GPS 1: detected as u-blox at 115200 baud
[ WARN] [1551238042.455874978]: TM : RTT too high for timesync: 20.66 ms.
[ INFO] [1551238042.830363858]: FCU: EKF2 IMU0 initial yaw alignment complete
[ INFO] [1551238042.830485660]: FCU: EKF2 IMU1 initial yaw alignment complete
[ WARN] [1551238043.065112795]: TM : RTT too high for timesync: 30.50 ms.
[ WARN] [1551238043.666019666]: TM : RTT too high for timesync: 31.72 ms.
[ INFO] [1551238043.732597316]: FCU: EKF2 IMU0 tilt alignment complete
[ INFO] [1551238043.732748445]: FCU: EKF2 IMU1 tilt alignment complete
[ WARN] [1551238044.254662081]: TM : RTT too high for timesync: 19.55 ms.
[ WARN] [1551238044.845644356]: TM : RTT too high for timesync: 10.53 ms.
[ WARN] [1551238045.450144456]: TM : RTT too high for timesync: 15.58 ms.
[ WARN] [1551238046.059107280]: TM : RTT too high for timesync: 24.25 ms.
[ WARN] [1551238046.659967721]: TM : RTT too high for timesync: 25.26 ms.
[ WARN] [1551238047.253886354]: TM : RTT too high for timesync: 18.90 ms.
[ WARN] [1551238047.853585452]: TM : RTT too high for timesync: 18.71 ms.
[ WARN] [1551238048.458600777]: TM : RTT too high for timesync: 23.40 ms.
[ WARN] [1551238049.055690469]: TM : RTT too high for timesync: 20.76 ms.
[ WARN] [1551238049.653167635]: TM : RTT too high for timesync: 18.43 ms.
[ INFO] [1551238049.710924644]: HP: requesting home position
[ INFO] [1551238049.720476616]: FCU: ArduCopter V3.6.4 (6c4da9e3)
[ INFO] [1551238049.720644223]: FCU: Frame: UNKNOWN
[ INFO] [1551238050.134494016]: PR: parameters list received
[ WARN] [1551238050.260175361]: TM : RTT too high for timesync: 25.18 ms.
[ WARN] [1551238050.855799571]: TM : RTT too high for timesync: 20.95 ms.
[ WARN] [1551238051.454136006]: TM : RTT too high for timesync: 19.78 ms.
[ WARN] [1551238052.058591209]: TM : RTT too high for timesync: 23.88 ms.
[ INFO] [1551238052.258868782]: FCU: EKF2 IMU0 Origin set to GPS
[ INFO] [1551238052.259176201]: FCU: EKF2 IMU1 Origin set to GPS
[ WARN] [1551238052.653949011]: TM : RTT too high for timesync: 19.00 ms.
[ WARN] [1551238053.254802757]: TM : RTT too high for timesync: 19.82 ms.
[ WARN] [1551238053.857933925]: TM : RTT too high for timesync: 22.99 ms.
[ WARN] [1551238054.454018666]: TM : RTT too high for timesync: 19.05 ms.
[ INFO] [1551238054.721552400]: WP: mission received
[ WARN] [1551238055.054610004]: TM : RTT too high for timesync: 20.11 ms.
[ WARN] [1551238055.657960017]: TM : RTT too high for timesync: 23.34 ms.
[ERROR] [1551238056.154673748]: FCU: PreArm: check firmware or FRAME_CLASS
[ERROR] [1551238056.154810053]: FCU: PreArm: 3D Accel calibration needed
[ERROR] [1551238056.154917799]: FCU: PreArm: RC Roll not configured
[ERROR] [1551238056.154981850]: FCU: PreArm: RC Pitch not configured
[ERROR] [1551238056.155107840]: FCU: PreArm: RC Throttle not configured
[ERROR] [1551238056.155175305]: FCU: PreArm: RC Yaw not configured
[ WARN] [1551238056.253789332]: TM : RTT too high for timesync: 19.38 ms.
[ WARN] [1551238056.857282455]: TM : RTT too high for timesync: 22.97 ms.
[ WARN] [1551238057.457108594]: TM : RTT too high for timesync: 21.93 ms.
[ WARN] [1551238058.054986989]: TM : RTT too high for timesync: 20.54 ms.
[ WARN] [1551238058.657970075]: TM : RTT too high for timesync: 23.46 ms.
[ WARN] [1551238059.256635346]: TM : RTT too high for timesync: 21.84 ms.
[ WARN] [1551238059.856436421]: TM : RTT too high for timesync: 21.63 ms.
[ WARN] [1551238060.455614084]: TM : RTT too high for timesync: 21.08 ms.
[ WARN] [1551238061.057219254]: TM : RTT too high for timesync: 22.15 ms.
[ WARN] [1551238061.645786884]: TM : RTT too high for timesync: 11.48 ms.
[ WARN] [1551238062.857146529]: TM : RTT too high for timesync: 22.78 ms.
[ WARN] [1551238063.457156431]: TM : RTT too high for timesync: 22.05 ms.
[ WARN] [1551238064.067205969]: TM : RTT too high for timesync: 32.75 ms.
[ WARN] [1551238066.160934907]: TM : RTT too high for timesync: 25.90 ms.
[ WARN] [1551238066.760496669]: TM : RTT too high for timesync: 26.19 ms.
[ WARN] [1551238069.062635448]: TM : RTT too high for timesync: 28.03 ms.
[ WARN] [1551238070.965773375]: TM : RTT too high for timesync: 30.94 ms

Diagnostics

root@9d820d31bf83:/ros_ws# rostopic echo -n1 /diagnostics
header: 
  seq: 149
  stamp: 
    secs: 1551238225
    nsecs: 964653311
  frame_id: ''
status: 
  - 
    level: 0
    name: "mavros: FCU connection"
    message: "connected"
    hardware_id: "tcp://127.0.0.1:5760@5760"
    values: 
      - 
        key: "Received packets:"
        value: "3056"
      - 
        key: "Dropped packets:"
        value: "0"
      - 
        key: "Buffer overruns:"
        value: "0"
      - 
        key: "Parse errors:"
        value: "0"
      - 
        key: "Rx sequence number:"
        value: "239"
      - 
        key: "Tx sequence number:"
        value: "219"
      - 
        key: "Rx total bytes:"
        value: "93737"
      - 
        key: "Tx total bytes:"
        value: "60418"
      - 
        key: "Rx speed:"
        value: "413.000000"
      - 
        key: "Tx speed:"
        value: "500.000000"
  - 
    level: 2
    name: "mavros: GPS"
    message: "No satellites"
    hardware_id: "tcp://127.0.0.1:5760@5760"
    values: 
      - 
        key: "Satellites visible"
        value: "0"
      - 
        key: "Fix type"
        value: "0"
      - 
        key: "EPH (m)"
        value: "Unknown"
      - 
        key: "EPV (m)"
        value: "Unknown"
  - 
    level: 0
    name: "mavros: Heartbeat"
    message: "Normal"
    hardware_id: "tcp://127.0.0.1:5760@5760"
    values: 
      - 
        key: "Heartbeats since startup"
        value: "186"
      - 
        key: "Frequency (Hz)"
        value: "0.999933"
      - 
        key: "Vehicle type"
        value: "Quadrotor"
      - 
        key: "Autopilot type"
        value: "ArduPilot"
      - 
        key: "Mode"
        value: "STABILIZE"
      - 
        key: "System status"
        value: "Standby"
  - 
    level: 0
    name: "mavros: System"
    message: "Normal"
    hardware_id: "tcp://127.0.0.1:5760@5760"
    values: 
      - 
        key: "Sensor present"
        value: "0x00000000"
      - 
        key: "Sensor enabled"
        value: "0x00000000"
      - 
        key: "Sensor helth"
        value: "0x00000000"
      - 
        key: "CPU Load (%)"
        value: "0.0"
      - 
        key: "Drop rate (%)"
        value: "0.0"
      - 
        key: "Errors comm"
        value: "0"
      - 
        key: "Errors count #1"
        value: "0"
      - 
        key: "Errors count #2"
        value: "0"
      - 
        key: "Errors count #3"
        value: "0"
      - 
        key: "Errors count #4"
        value: "0"
  - 
    level: 2
    name: "mavros: Battery"
    message: "No data"
    hardware_id: "tcp://127.0.0.1:5760@5760"
    values: 
      - 
        key: "Voltage"
        value: "-1.00"
      - 
        key: "Current"
        value: "0.0"
      - 
        key: "Remaining"
        value: "0.0"
  - 
    level: 0
    name: "mavros: Time Sync"
    message: "Normal"
    hardware_id: "tcp://127.0.0.1:5760@5760"
    values: 
      - 
        key: "Timesyncs since startup"
        value: "1869"
      - 
        key: "Frequency (Hz)"
        value: "9.999328"
      - 
        key: "Last RTT (ms)"
        value: "14.213008"
      - 
        key: "Mean RTT (ms)"
        value: "15.054268"
      - 
        key: "Last remote time (s)"
        value: "187.091520000"
      - 
        key: "Estimated time offset (s)"
        value: "1551238038.718651533"
---

Check ID

root@9d820d31bf83:/ros_ws# rosrun mavros checkid
OK. I got messages from 1:1.

---
Received 171 messages, from 1 addresses
sys:comp   list of messages
  1:1     0, 253, 111

Bug Reproduction

Using the provided Dockerfile:

$ docker build -t mavros-timing-bug .
$ docker run --rm -it mavros-timing-bug
~ roscore &
...

~ /ros_ws/src/ArduPilot/build/sitl/bin/arducopter --model copter &
Creating model copter at speed 1.0
Home: -35.363261 149.165235 alt=584.000000m hdg=353.000000
Starting sketch 'ArduCopter'
Starting SITL input
Using Irlock at port : 9005
bind port 5760 for 0
Serial port 0 on TCP port 5760
Waiting for connection ....

~ roslaunch mavros apm.launch fcu_url:=tcp://127.0.0.1:5760@5760
...
@ChrisTimperley
Copy link
Author

Possibly related: ros/ros_comm#1343

@vooon
Copy link
Member

vooon commented Feb 27, 2019

Do you use prebuilt packages or from source?
Because roscore also eats CPU, i think that most likely problem in roscpp.
And yes, bug in node::spin may result in high CPU usage.

Can you try older distribution? Mavros shoud still work on Indigo (i don't recommend to use it, but it help with understanding).

@ChrisTimperley
Copy link
Author

ChrisTimperley commented Feb 27, 2019 •
edited
Loading

Do you use prebuilt packages or from source?

Packages are built from source.

Can you try older distribution? Mavros shoud still work on Indigo (i don't recommend to use it, but it help with understanding).

The bug doesn't occur on Indigo. To be more specific, I don't see any TM : RTT too high for timesync warnings and CPU usage is fairly minimal.

cpu_indigo

@hexray-newbee
Copy link

ROS foxy also occurs.

@vooon
Copy link
Member

vooon commented Aug 3, 2021

Closing that issue as stall. ROS2 is completely different story.

@vooon vooon closed this as completed Aug 3, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug question
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@ChrisTimperley @vooon @hexray-newbee