ArduPilot / ArduPilot/MAVProxy

Mysterious FC performance penalty on MAVLink streaming

Open
#698 3 comments 0 reactions 0 assignees View on GitHub
Dominant language
Python
Stars
595
Forks
773
Avg merge
2d 6h
Merged PRs (30d)
18

Description

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.

Contributor guide

No contributing guide indexed for this repository

Research direction

Reproduce the reported behavior with MAVProxy, a Cube Black, and the listed SR1 settings, comparing performance before and after `param fetch` and an FC reboot. Start by tracing MAVProxy's default stream requests and parameter-fetch handling; done means the source of the unexpected stream behavior is identified and the performance difference is explained or corrected.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
cli, performance
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.