Mysterious FC performance penalty on MAVLink streaming

[RickReeser]

MAVProxy is doing something that is causing flight controller performance slowdowns. It seems to be caused by MAVLink streaming.

I have a system with a Cube Black connected via serial UART to a TX1 running MAVProxy.

This is typical performance on one of my drones in Loiter while inactive (using sched_debug 1):

LOITER> APM: PERF: 42/4000 max=3655 min=2209 F=2521 sd=81
APM: PERF: 43/4000 max=3757 min=2203 F=2527 sd=86

Current streamrate settings:

SR0_ADSB         0.000000
SR0_EXTRA1       0.000000
SR0_EXTRA2       0.000000
SR0_EXTRA3       0.000000
SR0_EXT_STAT     0.000000
SR0_PARAMS       0.000000
SR0_POSITION     0.000000
SR0_RAW_CTRL     0.000000
SR0_RAW_SENS     0.000000
SR0_RC_CHAN      0.000000
SR1_ADSB         0.000000
SR1_EXTRA1       4.000000
SR1_EXTRA2       4.000000
SR1_EXTRA3       4.000000
SR1_EXT_STAT     4.000000
SR1_PARAMS       10.000000
SR1_POSITION     4.000000
SR1_RAW_CTRL     4.000000
SR1_RAW_SENS     4.000000
SR1_RC_CHAN      4.000000
SR2_ADSB         0.000000
SR2_EXTRA1       0.000000
SR2_EXTRA2       0.000000
SR2_EXTRA3       0.000000
SR2_EXT_STAT     0.000000
SR2_PARAMS       0.000000
SR2_POSITION     0.000000
SR2_RAW_CTRL     0.000000
SR2_RAW_SENS     0.000000
SR2_RC_CHAN      0.000000
SR3_ADSB         0.000000
SR3_EXTRA1       0.000000
SR3_EXTRA2       0.000000
SR3_EXTRA3       0.000000
SR3_EXT_STAT     0.000000
SR3_PARAMS       0.000000
SR3_POSITION     0.000000
SR3_RAW_CTRL     0.000000
SR3_RAW_SENS     0.000000
SR3_RC_CHAN      0.000000
APM: PERF: 40/4000 max=3640 min=2202 F=2517 sd=79
APM: PERF: 42/4000 max=3747 min=2188 F=2521 sd=84
APM: PERF: 43/4000 max=3647 min=2207 F=2523 sd=85
APM: PERF: 44/4000 max=3701 min=2221 F=2522 sd=87
APM: PERF: 41/4000 max=3728 min=2206 F=2519 sd=84
APM: PERF: 42/4000 max=3573 min=2165 F=2525 sd=78

As you can see, I set most streamrates to 0 except serial1 which are 4Hz, MAVProxy default. Performance is steady at ~40 loop overruns.

Just to make a point, set SR1 params to existing values

LOITER> param set SR1_EXTRA1       4.000000
LOITER> param set SR1_EXTRA2       4.000000
LOITER> param set SR1_EXTRA3       4.000000
LOITER> param set SR1_EXT_STAT     4.000000
LOITER> param set SR1_PARAMS       10.000000
LOITER> param set SR1_POSITION     4.000000
LOITER> param set SR1_RAW_CTRL     4.000000
LOITER> param set SR1_RAW_SENS     4.000000
LOITER> param set SR1_RC_CHAN      4.000000
APM: PERF: 44/4000 max=3701 min=2215 F=2524 sd=85
LOITER> APM: PERF: 45/4000 max=3718 min=2215 F=2521 sd=87
APM: PERF: 44/4000 max=3780 min=2235 F=2521 sd=88
APM: PERF: 44/4000 max=3697 min=2198 F=2528 sd=90

Performance hasn't changed, of course.

Now set streamrate params to 0

LOITER> param set SR1_ADSB 0
LOITER> param set SR1_EXTRA1 0
LOITER> param set SR1_EXTRA2 0
LOITER> param set SR1_EXTRA3 0
LOITER> param set SR1_EXT_STAT 0
LOITER> param set SR1_PARAMS 0
LOITER> param set SR1_POSITION 0
LOITER> param set SR1_RAW_CTRL 0
LOITER> param set SR1_RAW_SENS 0
LOITER> param set SR1_RC_CHAN 0

7. Issue param fetch to refresh params. Once it's finished, check streamrate params again and observe that some streamrates are reset to 4Hz:

LOITER> param set sr1_*
LOITER> SR1_ADSB         0.000000
SR1_EXTRA1       4.000000
SR1_EXTRA2       4.000000
SR1_EXTRA3       4.000000
SR1_EXT_STAT     4.000000
SR1_PARAMS       10.000000
SR1_POSITION     4.000000
SR1_RAW_CTRL     4.000000
SR1_RAW_SENS     4.000000
SR1_RC_CHAN      4.000000

Params are exactly the same as they were at the start. Mavproxy is requesting these streams at its default rate.

Performance has improved, even though the params are unchanged!

APM: PERF: 1/4000 max=3014 min=2209 F=2513 sd=24
APM: PERF: 0/4000 max=2922 min=2248 F=2512 sd=22
APM: PERF: 1/4000 max=3010 min=2204 F=2513 sd=23
APM: PERF: 1/4000 max=3040 min=2166 F=2513 sd=26

This performance improvement lasts until the FC is rebooted. Restarting MAVproxy doesn't change anything. I tested this on multiple Cubes and TX1s. Changing the SR params one at a time has incremental performance gains, so they all seem involved.

I am trying to find where this performance hit is coming from. It's apparently related to mavlink streaming - maybe MAVProxy is accidentally requesting a very high stream rate on these messages? I do not specify set streamrate, so it defaults to 4.

[peterbarker]

On Wed, 16 Oct 2019, RickReeser wrote:

Interesting!

module load messagerate

play with that command to see if things are actually coming in at different rates....

The parameters reverting would appear to be explained by mavproxy acting according to its streamrate parameter, yes?

[RickReeser]

The parameters reverting would appear to be explained by mavproxy acting according to its streamrate parameter, yes?

Yeah, this is expected behavior - the params get set to whatever streamrate is.

Output from messagerate:

LOITER> messagerate status
LOITER> AHRS: 4.0/s
AHRS2: 4.0/s
AHRS3: 4.0/s
ATTITUDE: 4.0/s
BATTERY_STATUS: 4.0/s
DISTANCE_SENSOR: 4.0/s
EKF_STATUS_REPORT: 4.0/s
GLOBAL_POSITION_INT: 4.0/s
GPS_RAW_INT: 4.0/s
HEARTBEAT: 1.0/s
HWSTATUS: 4.0/s
MEMINFO: 4.0/s
MISSION_CURRENT: 4.0/s
MOUNT_STATUS: 4.0/s
NAV_CONTROLLER_OUTPUT: 4.0/s
POWER_STATUS: 4.0/s
RANGEFINDER: 4.0/s
RAW_IMU: 4.2/s
RC_CHANNELS: 4.0/s
RC_CHANNELS_RAW: 4.0/s
SCALED_IMU2: 4.2/s
SCALED_IMU3: 4.0/s
SCALED_PRESSURE: 4.0/s
SCALED_PRESSURE2: 4.0/s
SENSOR_OFFSETS: 0.4/s
SERVO_OUTPUT_RAW: 4.0/s
STATUSTEXT: 0.4/s
SYSTEM_TIME: 4.0/s
SYS_STATUS: 4.0/s
TIMESYNC: 0.2/s
VFR_HUD: 4.0/s
VIBRATION: 4.0/s

APM: PERF: 37/4000 max=6249 min=2207 F=2551 sd=185
APM: PERF: 41/4000 max=6274 min=2221 F=2554 sd=185

After setting SR params to 0:

messagerate status
LOITER> AHRS: 4.2/s
AHRS2: 4.2/s
AHRS3: 4.2/s
ATTITUDE: 4.2/s
BATTERY_STATUS: 4.2/s
DISTANCE_SENSOR: 4.2/s
EKF_STATUS_REPORT: 4.2/s
GLOBAL_POSITION_INT: 4.4/s
GPS_RAW_INT: 4.2/s
HEARTBEAT: 1.0/s
HWSTATUS: 4.2/s
MEMINFO: 4.2/s
MISSION_CURRENT: 4.2/s
MOUNT_STATUS: 4.2/s
NAV_CONTROLLER_OUTPUT: 4.2/s
POWER_STATUS: 4.2/s
RANGEFINDER: 4.2/s
RAW_IMU: 4.2/s
RC_CHANNELS: 4.2/s
RC_CHANNELS_RAW: 4.2/s
SCALED_IMU2: 4.2/s
SCALED_IMU3: 4.2/s
SCALED_PRESSURE: 4.2/s
SCALED_PRESSURE2: 4.2/s
SENSOR_OFFSETS: 0.4/s
SERVO_OUTPUT_RAW: 4.2/s
SYSTEM_TIME: 4.2/s
SYS_STATUS: 4.2/s
VFR_HUD: 4.2/s
VIBRATION: 4.2/s

APM: PERF: 10/4000 max=6175 min=2289 F=2546 sd=174
APM: PERF: 10/4000 max=6267 min=2345 F=2544 sd=176

So whatever has changed does not appear in the message rates. I'm going to do some more testing with/without MAVProxy and other GCS.

On a related note, how do I get MAVProxy to display the sched_debug 3 overrun and slip messages? It displays them by default on my Windows client, but not on Ubuntu.

[mohammada315]

Can switch --stramrate=1 be used?