4.3 RC3 major latency issue while in dshot600/8k with FOXEERF722V2

[FeisarFPV]

Describe the bug

Hi there,

I had zero issue while beeing in both 4.3 RC1 and RC2 in a short time for this last. Currently I'm on RC3 which still have the same problem.

Since I updated my ELRS to 2.2.0 (coming from 2.0.1 previously), I have a big latency issue (like half a second, near a full second) in my sticks input controlling my quad.

I had the same issue in both of my quads (not the third one based in another FC), which are both equiped with Foxeer F722 V2.
After having a long conversations from the ELRS Discord with various admins, telling me and concluding it was not fault of ELRS at all. I tried to go back to ELRS 2.0.1 with same major latency issues. While I flashed back 2.2.0, one of the admins from ELRS told me to try to go back to dshot300 and 4k pidloop (I was at 600 and 8k/8k before), this successfully solved my issue.

Strangely, a friend of me which also have the same Foxeer F722 V2 FC, just recently updated to 2.2.0 without any issue at all staying in dshot600/8k.

So now I’m wondering why in both my Foxeer F722 V2 I’m now forced to stay at dshot300 and 4k pidloop to avoid this major latency issue ? for now I’m opening this ticket and will be glad to flash any test version that could fix the problem.
If it can help, the CPU never reached more than 58% as shown from the configurator, same story in my second quad with the Foxeer FC too.

Let me know if you guys needs any further information.
Many thanks in advance for watching this case.

To Reproduce

Be on ELRS 2.2.0
BF 4.3 RC2 or RC3
Having Foxeer F722 V2 FC
stay on dshot600 8k/8k

Expected behavior

no major latency issue (like simply returning in dshot300/4k)

Flight controller configuration

diff

# version
# Betaflight / STM32F7X2 (S7X2) 4.3.0 Feb  1 2022 / 20:14:54 (3267f0417) MSP API: 1.44
# config: manufacturer_id: FOXE, board_name: FOXEERF722V2, version: baa1d34a, date: 2021-08-16T07:35:36Z

# start the command batch
batch start

board_name FOXEERF722V2
manufacturer_id FOXE

# name: AK-47 6p

# resources
resource MOTOR 1 C08
resource MOTOR 2 C09
resource MOTOR 3 A08
resource MOTOR 4 A09

# feature
feature -RX_PARALLEL_PWM
feature RX_SERIAL
feature TELEMETRY

# serial
serial 1 64 115200 57600 0 115200
serial 2 1 115200 57600 0 115200

# beeper
beeper -GYRO_CALIBRATED
beeper -RX_LOST
beeper -RX_LOST_LANDING
beeper -ARMING_GPS_FIX
beeper -BAT_CRIT_LOW
beeper -BAT_LOW
beeper -GPS_STATUS
beeper -ACC_CALIBRATION
beeper -ACC_CALIBRATION_FAIL
beeper -READY_BEEP
beeper -DISARM_REPEAT
beeper -ARMED
beeper -SYSTEM_INIT
beeper -ON_USB
beeper -BLACKBOX_ERASE
beeper -CRASH_FLIP
beeper -CAM_CONNECTION_OPEN
beeper -CAM_CONNECTION_CLOSE
beeper -RC_SMOOTHING_INIT_FAIL

# map
map TAER1234

# aux
aux 0 0 0 1975 2050 0 0
aux 1 1 2 1475 1525 0 0
aux 2 13 1 950 1025 0 0
aux 3 35 1 1975 2050 0 0
aux 4 36 3 1975 2050 0 0

# master
set gyro_lpf1_static_hz = 0
set gyro_lpf2_static_hz = 400
set dyn_notch_count = 1
set dyn_notch_q = 400
set dyn_notch_min_hz = 100
set dyn_notch_max_hz = 580
set gyro_lpf1_dyn_min_hz = 0
set gyro_lpf1_dyn_max_hz = 0
set acc_calibration = -19,-77,-133,1
set mag_hardware = NONE
set baro_hardware = NONE
set min_check = 1015
set max_check = 2000
set rssi_channel = 15
set rc_smoothing_auto_factor = 50
set serialrx_provider = CRSF
set blackbox_sample_rate = 1/2
set dshot_bidir = ON
set motor_pwm_protocol = DSHOT300
set align_board_yaw = 180
set vbat_warning_cell_voltage = 360
set vbat_scale = 114
set ibata_scale = 127
set beeper_dshot_beacon_tone = 4
set yaw_motors_reversed = ON
set small_angle = 180
set deadband = 2
set yaw_deadband = 2
set pid_process_denom = 2
set simplified_gyro_filter = OFF
set simplified_gyro_filter_multiplier = 110
set osd_warn_core_temp = OFF
set osd_warn_launch_control = OFF
set osd_warn_no_gps_rescue = OFF
set osd_warn_gps_rescue_disabled = OFF
set osd_warn_rssi = ON
set osd_rssi_alarm = 75
set osd_rssi_dbm_alarm = -98
set osd_cap_alarm = 0
set osd_vbat_pos = 436
set osd_rssi_pos = 2497
set osd_flymode_pos = 58
set osd_current_pos = 2483
set osd_mah_drawn_pos = 405
set osd_craft_name_pos = 15
set osd_gps_speed_pos = 491
set osd_gps_lon_pos = 0
set osd_gps_lat_pos = 32
set osd_gps_sats_pos = 64
set osd_home_dir_pos = 160
set osd_home_dist_pos = 161
set osd_altitude_pos = 128
set osd_warnings_pos = 47
set osd_avg_cell_voltage_pos = 2516
set osd_stat_tim_2 = OFF
set osd_stat_max_spd = OFF
set osd_stat_min_batt = OFF
set osd_stat_min_rssi = OFF
set osd_stat_max_curr = OFF
set osd_stat_used_mah = OFF
set osd_stat_bbox = OFF
set osd_stat_bb_no = OFF
set debug_mode = GYRO_SCALED
set gyro_1_align_yaw = 2700
set rpm_filter_fade_range_hz = 100
set name = AK-47 6p

profile 0

# profile 0
set dterm_lpf1_dyn_min_hz = 95
set dterm_lpf1_dyn_max_hz = 120
set dterm_lpf1_dyn_expo = 8
set dterm_lpf1_type = BIQUAD
set dterm_lpf1_static_hz = 0
set dterm_lpf2_static_hz = 0
set anti_gravity_gain = 3800
set pidsum_limit = 1000
set pidsum_limit_yaw = 1000
set yaw_lowpass_hz = 0
set throttle_boost = 0
set p_pitch = 62
set i_pitch = 110
set d_pitch = 39
set f_pitch = 164
set p_roll = 53
set i_roll = 95
set d_roll = 33
set f_roll = 143
set p_yaw = 53
set i_yaw = 95
set f_yaw = 143
set d_min_roll = 33
set d_min_pitch = 39
set motor_output_limit = 81
set thrust_linear = 25
set feedforward_averaging = 2_POINT
set feedforward_smooth_factor = 70
set feedforward_jitter_factor = 8
set dyn_idle_min_rpm = 20
set simplified_d_gain = 110
set simplified_pi_gain = 120
set simplified_dmax_gain = 0
set simplified_feedforward_gain = 120
set simplified_pitch_d_gain = 105
set simplified_pitch_pi_gain = 110
set simplified_dterm_filter = OFF
set simplified_dterm_filter_multiplier = 105

rateprofile 0

# rateprofile 0
set rates_type = BETAFLIGHT
set roll_rc_rate = 100
set pitch_rc_rate = 100
set yaw_rc_rate = 100
set roll_expo = 15
set pitch_expo = 15
set yaw_expo = 15
set roll_srate = 77
set pitch_srate = 77
set yaw_srate = 71

# end the command batch
batch end

# 

resource show all
Currently active IO resource assignments:
(reboot to update)
--------------------
A00: FREE
A01: FREE
A02: SERIAL_TX 2
A03: SERIAL_RX 2
A04: BEEPER
A05: SPI_SCK 1
A06: SPI_MISO 1
A07: SPI_MOSI 1
A08: MOTOR 3
A09: MOTOR 4
A10: FREE
A11: USB
A12: USB
A13: SWD
A14: SWD
A15: FREE
B00: FREE
B01: FREE
B02: GYRO_CS 1
B03: CAMERA_CONTROL
B04: FREE
B05: SPI_MOSI 3
B06: FREE
B07: FREE
B08: I2C_SCL 1
B09: I2C_SDA 1
B10: SERIAL_TX 3
B11: SERIAL_RX 3
B12: FLASH_CS
B13: SPI_SCK 2
B14: SPI_MISO 2
B15: SPI_MOSI 2
C00: ADC_BATT
C01: FREE
C02: ADC_CURR
C03: OSD_CS
C04: GYRO_EXTI
C05: FREE
C06: FREE
C07: FREE
C08: MOTOR 1
C09: MOTOR 2
C10: SPI_SCK 3
C11: SPI_MISO 3
C12: FREE
C13: FREE
C14: FREE
C15: LED 1
D00: FREE
D01: FREE
D02: FREE
D03: FREE
D04: FREE
D05: FREE
D06: FREE
D07: FREE
D08: FREE
D09: FREE
D10: FREE
D11: FREE
D12: FREE
D13: FREE
D14: FREE
D15: FREE
E00: FREE
E01: FREE
E02: FREE
E03: FREE
E04: FREE
E05: FREE
E06: FREE
E07: FREE
E08: FREE
E09: FREE
E10: FREE
E11: FREE
E12: FREE
E13: FREE
E14: FREE
E15: FREE
F00: FREE
F01: FREE
F02: FREE
F03: FREE
F04: FREE
F05: FREE
F06: FREE
F07: FREE
F08: FREE
F09: FREE
F10: FREE
F11: FREE
F12: FREE
F13: FREE
F14: FREE
F15: FREE

Currently active Timers:
-----------------------
TIM1: FREE
TIM2:
    CH2 : CAMERA_CONTROL
TIM3: FREE
TIM4: FREE
TIM5: FREE
TIM6: FREE
TIM7: FREE
TIM8:
    CH3 : DSHOT_BITBANG 3
    CH4 : DSHOT_BITBANG 1
TIM9: FREE
TIM10: FREE
TIM11: FREE
TIM12: FREE
TIM13: FREE
TIM14: FREE

Currently active DMA:
--------------------
DMA1 Stream 0: SPI_MISO 3
DMA1 Stream 1: FREE
DMA1 Stream 2: FREE
DMA1 Stream 3: SPI_MISO 2
DMA1 Stream 4: SPI_MOSI 2
DMA1 Stream 5: SPI_MOSI 3
DMA1 Stream 6: FREE
DMA1 Stream 7: FREE
DMA2 Stream 0: ADC
DMA2 Stream 1: FREE
DMA2 Stream 2: SPI_MISO 1
DMA2 Stream 3: SPI_MOSI 1
DMA2 Stream 4: DSHOT_BITBANG 3
DMA2 Stream 5: FREE
DMA2 Stream 6: FREE
DMA2 Stream 7: DSHOT_BITBANG 1

# 

Flight controller

FOXEERF722V2 (Foxeer F722 V2)

Other components

ESC 4IN1 Tekko32 45A (1st quad) & Mamba F50 Pro 4IN1 (2nd quad)
both ELRS 2.2.0 for now.

How are the different components wired up

classic vista setup, directly soldered. I generally make over clean builds with best gyro place not touching anything, etc.

Add any other context about the problem that you think might be relevant here

No response

[SteveCEvans]

What receiver do you use? I have two F722 based DJI equipped quads using Crossfire with no such issues. For there to be half a second lag something would have to buffer up half a second’s worth of RC commands and nothing in Betaflight does that!

[FeisarFPV]

What receiver do you use? I have two F722 based DJI equipped quads using Crossfire with no such issues. For there to be half a second lag something would have to buffer up half a second’s worth of RC commands and nothing in Betaflight does that!

Currently using same Happymodel EP1 ELRS RX's in all my quads, and Happymodel ES24TX Pro TX.
Agree, looks like a "buffer" issue or something, but the ELRS devs are sure about that, this issue is definitely adressed from BF since it can be recovered when getting back to dshot300/4k, worth contacting them if neded (or I can maybe invite them in this ticket if needed, its easier since its also opensource projet, of course 👍)

[ctzsnooze]

Please make a log and share it here.

[AllTheNamesWereTaken-EvenThisOne]

Just want to chime in that i am also having this same issue, with an iflight f7 twing and BetaFPV rx on elrs 2.2

dshot600 + 8k pid results in a half second delay to input on the quad. Switching to dshot 300 +4k fix's it.

[FeisarFPV]

Please make a log and share it here.

I stay in gyro_scaled for the logging mode ? Or anything else maybe ?

[SteveCEvans]

What packet rate are you using on the RX?

The following logs would be useful. Only a few seconds of each, taken both in the working and non working case.

SCHEDULER_DETERMINISM
TIMING_ACCURACY
RX_STATE_TIME

[FeisarFPV]

What packet rate are you using on the RX?

The following logs would be useful. Only a few seconds of each, taken both in the working and non working case.

SCHEDULER_DETERMINISM TIMING_ACCURACY RX_STATE_TIME

Ok I will do that 👍
I am on 500Hz and 100mW.
I already tried in 250Hz and various output too, without any success.

[FeisarFPV]

Ok just did 2 batteries in my both quads which had the issue to take log records and no more latency issue in dshot600/8k ! weird...
Not sure why, but be sure I'll keep this ticket updated if I'm facing the issue again and hopefully will get the proper BBLs for analysis.
@AllTheNamesWereTaken-EvenThisOne AllTheNamesWereTaken-EvenThisOne can you maybe grab the demanded logs for the devs to debug if you problem still persist in your quad ?

[hydra]

@AndroidGX any update on this issue?

[FeisarFPV]

@AndroidGX any update on this issue?

Was about to update today, yup.
Just wanted to make a new log with gyro_scaled for today with another props on my 5 inch quad and the issue appeared again !
I had no issue at all since, until today.
So, I turned off again blackbox logging and the NO issue again.
So the weird thing is that when I turn ON logging (probably with gyro_scaled) now, the issue appears, and no loggin : the issue disappear...
I will try to make the requested logs if I have the issue back trying to log with "SCHEDULER_DETERMINISM", "TIMING_ACCURACY", and "RX_STATE_TIME".

[AllTheNamesWereTaken-EvenThisOne]

I went to get the requested logs and my issue was also resolved. I switched back to gyro_scaled and no longer had the issue that AndroidGX still has so i am unable to reproduce.

[FeisarFPV]

Hi guys, some fresh updates from today.

I recorded all the requested logs for debugging :
latency issue logs.zip

The main issue of the logs is that I NEVER faced the latency issue while I recorded all the logs from both DSHOT600 and DSHOT300 folders. BUT, I felt some slight latency issue again when I recorded on gyro_scaled and 4kHz (but not in 8kHz).
Both logs can be found in the zip if needed.

So to sum-up, in my case the latency appeared only when I record blackbox in 4kHz and in gyro_scaled mode.
Let me know if you guys needs anything else.

[github-actions]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs within a week.

[FeisarFPV]

Any news of this issue ?

[hydra]

No-one appears to be investigating this. I suspect no-one will until a method to reliably re-produce the issue is found. Can you confirm that one of the logs your recorded DOES have evidence of the latency or not, and if so which log file and at what time index so that when someone does investigate this they will not have to trawl the history and logs as much. i.e. make it easy for someone to help investigate this.

[FeisarFPV]

As previously said, all the recorded logs above can't show any latency issue, but sometimes it still appears in 2 of my quads while on dshot600 and when I try to record gyro_scaled. I can't do anything else but for me this issue is still present then. I'm now obliged to set dshot300 in my F7 cpus (which is sad), unfortunately.

[klutvott123]

so this happens when logging? you're logging at a 1/1 rate and that's probably the reason. You shouldn't need to log at more than 1/4 at 8K unless you have very special needs. If you really need to log at such a high rate, you can have a look at the new blackbox_disable_ options in cli that allow you to disable logging of the things you aren't interested in.

[hydra]

@klutvott123 I think @Quick-Flash was also having latency issues with logging even on a H743. Probably related to #11485

[Quick-Flash]

@klutvott123 I think @Quick-Flash was also having latency issues with logging even on a H743. Probably related to #11485

no latency issues, flies fine, just stuttering in the logs. Just missing parts of the logs

[hydra]

I'm guessing that the latency issue is likely with the scheduler not servicing the blackbox logging code like it used to, or that the there is some other issue with the updated spi code that uses the flash to log. would be interesting to see if there is a difference between 1-bit spi, octo-spi flash, 1-bit sdio or 4-bit sdio. certainly 4 bit quad-spi and 4-bit sdio on my H750 FC's worked at 8k(gyro)/8k(pid)/8k(logging). Seems like someone needs to do a bit of investigation on a variety of MCUs and logging systems and report their findings comparing BF 4.2, BF 4.3 pre-spi changes, 4.3 post-SPI changes and 4.3 current master with scheduler changes. Seems like a lot of work...

[klutvott123]

@hydra Looks like a completely different issue to me. The issue described by @Quick-Flash has been a problem forever. My matekF722 has always had gaps in logs like that

[hydra]

@klutvott123 even on 4.2?

[klutvott123]

@hydra I don't remember, but it was like that on 4.0 and 4.1

[SteveCEvans]

@hydra Good grief man. Quit with the unfounded digs at the scheduler. The scheduler doesn't "service" the blackbox logging code. That's called, as it ever was, from the PID task, which is called with better regularity now than it ever was.

Gaps in the log are caused by the FLASH not responding fast enough. Prior to every write the device's status register must be polled in case it is busy and the FLASH driver passes this to the SPI driver to handle using the m25p16_callbackReady() callback as per the below from m25p16_pageProgramContinue().

Some FLASH devices just take too long on each write to keep up. It's got nothing to do with the transfer of data into the device over SPI. We don't buffer up blackbox data beyond a sensible limit; excess data just gets dropped.

    static busSegment_t segments[] = {
            {.u.buffers = {readStatus, readyStatus}, sizeof(readStatus), true, m25p16_callbackReady},
            {.u.buffers = {writeEnable, NULL}, sizeof(writeEnable), true, m25p16_callbackWriteEnable},
            {.u.buffers = {pageProgram, NULL}, 0, false, NULL},
            {.u.link = {NULL, NULL}, 0, true, NULL},
            {.u.link = {NULL, NULL}, 0, true, NULL},
            {.u.link = {NULL, NULL}, 0, true, NULL},
    };

[hydra]

@hydra Good grief man. Quit with the unfounded digs at the scheduler. The scheduler doesn't "service" the blackbox logging code. That's called, as it ever was, from the PID task, which is called with better regularity now than it ever was.

My apologies, yes it was a guess. I stand corrected. Thanks for refreshing my memory on where the BB logging was called from, I wasn't remembering correctly. That code has 'just worked' for me for a number of years so have not had to look at it recently. @thenickdude did such a great job on it!

Yes, I'm aware of the differences between write speeds, that's usually more of an issue on SD cards which have much more variable latency.

Can you think of anything else that's changed recently which might be affecting the logging performance? I'm struggling to think of anything other than my previous guesses.

[FeisarFPV]

I did another 2 lipos today to test recording blackbox in 2kHz mode (GYRO_SCALED) and no issue so far.
This confirms then I have issue only when I record in 4kHz.

[dinesh21400]

Not sure if this is related but after I updated my Crossfire to 6.17 I am having a 1s latency on my sticks to quad movements as well. I have two quads with this same issue. I'm using a TBS Tango 2 and have a Nano RX in both quads. Both have the same flight controller (Speedybee F7) and running BF 4.3 RC3. I wonder if it's related to the OPs issue?

I'm downgrading my crossfire firmware down to 6.07 to see if issue goes away.

[haslinghuis]

@dinesh21400 please try CRSF 6.17 with latest development firmware. Details:

https://github.com/betaflight/betaflight/pull/11472

[dinesh21400]

@dinesh21400 please try CRSF 6.17 with latest development firmware. Details:

https://github.com/betaflight/betaflight/pull/11472

This happened to me only after upgrading to 6.17. I did this yesterday using Agent M so I'm assuming it's latest firmware. Should I also do something else?

[haslinghuis]

Yes it needs the firmware in the link above available as development build.
Using 10.8RC3 or above please try flashing:

to see if latency is resolved with 6.17

[dinesh21400]

Yes it needs the firmware in the link above available as development build. Using 10.8RC3 or above please try flashing:

to see if latency is resolved with 6.17

Ok ill give it a try.

[haslinghuis]

Save your diff and use detect button to detect right target

[klutvott123]

#11472 doesn't rely on a particular firmware version, and 6.17 doesn't need the PR to work. The PR and firmware 6.17 will both make the RX use CRSF V2. But I don't know if there are other issues with 6.17

[dinesh21400]

Save your diff and use detect button to detect right target

I just tried with the build you said and used 6.07. It seemed to work fine on that. I'm now going back to 6.17 and going to try again.

[dinesh21400]

#11472 doesn't rely on a particular firmware version, and 6.17 doesn't need the PR to work. The PR and firmware 6.17 will both make the RX use CRSF V2. But I don't know if there are other issues with 6.17

Ok so that's what I thought. If I reproduce the issue with 6.17 again then I know foe certain that's what's happening. Hopefully I don't destroy my quad in the meantime.

[haslinghuis]

TBS is very safe (using over 3 years) - even while bench testing. Awaiting interesting results on going back to 6.17 as the new firmware should already enforce CRSF V2

[dinesh21400]

TBS is very safe (using over 3 years) - even while bench testing. Awaiting interesting results on going back to 6.17 as the new firmware should already enforce CRSF V2

Ok just did the test with 6.17. Have the issue. There is a ton of latency. Most noticable on flips. I almost crashed a couple times but was able to bring it safely down. I'm downgrading till this issue is resolved.

[haslinghuis]

Thanks for testing. @klutvott123 please take note.

[Quick-Flash]

TBS is very safe (using over 3 years) - even while bench testing. Awaiting interesting results on going back to 6.17 as the new firmware should already enforce CRSF V2

Ok just did the test with 6.17. Have the issue. There is a ton of latency. Most noticable on flips. I almost crashed a couple times but was able to bring it safely down. I'm downgrading till this issue is resolved.

The reason is that the bf4.3 has very aggressive scheduler code that will prioritize pid and gyro over everything else. Meaning that your rc command will not be processed because the scheduler is deciding to instead run the pid/gyro, and it won't run the rc command code even if it has time to, but thinks it would be to close to another gyro read. I'm hoping that these issues get resolved.

[dinesh21400]

TBS is very safe (using over 3 years) - even while bench testing. Awaiting interesting results on going back to 6.17 as the new firmware should already enforce CRSF V2

Ok just did the test with 6.17. Have the issue. There is a ton of latency. Most noticable on flips. I almost crashed a couple times but was able to bring it safely down. I'm downgrading till this issue is resolved.

The reason is that the bf4.3 has very aggressive scheduler code that will prioritize pid and gyro over everything else. Meaning that your rc command will not be processed because the scheduler is deciding to instead run the pid/gyro, and it won't run the rc command code even if it has time to, but thinks it would be to close to another gyro read. I'm hoping that these issues get resolved.

Thanks for that but how come it was running fine with RC3 on v 6.07? Shouldn't it affect both versions equally?

[dinesh21400]

Just curious but I noticed force telemetry was turned on after FW update. I had turned this off in the past. Could having that on cause extra latency?

[klutvott123]

@dinesh21400 Yes. It means it can switch down to 4Hz update rate. It's a likely explanation for the latency you're seeing.

[dinesh21400]

@dinesh21400 Yes. It means it can switch down to 4Hz update rate. It's a likely explanation for the latency you're seeing.

I hate myself. Thanks. I wish it wouldn't default to that after a FW update.

[haslinghuis]

Everybody in this room please keep testing with latest development firmware and report back please.

[FeisarFPV]

Everybody in this room please keep testing with latest development firmware and report back please.

OK will do, I stay you guys tuned.
Thanks

[FeisarFPV]

Hey, forgot to report back but I did tried with latest development firmware 3 days ago (before RC4) and feel like there is much less latency, but still a bit so I still can't really freestyle with logging in 4kHz, but I feel the improvement.
I wll try with latest RC4 and report back soon 👍

[FeisarFPV]

Ok finally tested in RC4 (in one of my two yet quads) and guess what ? problem finally gone !
No more issue while recording in 4kHz in GYRO_SCALED and dshot600 (8k/8k) ! 👍
What a very good news! very happy
I will try tomorrow in my second quad just to confirm but I feel confident.

Do someone else in this room did tried RC4 and please report if also resolved from you sides ?
'laters

[haslinghuis]

Fixed in RC4