cvinayak
commented
2 years ago @jakkra Please check if #50022 fixes the event stall problem?
Closed jakkra closed 2 years ago
cvinayak
commented
2 years ago @jakkra Please check if #50022 fixes the event stall problem?
jakkra
commented
2 years ago @cvinayak unfortunately still same issue.
cvinayak
commented
2 years ago @cvinayak unfortunately still same issue.
Ok, my fault that I used simulation and an own sample (https://github.com/zephyrproject-rtos/zephyr/pull/42721) to check whether my changes were covered by trying to sync to 5 other periodic advertisers at 7.5ms interval. I will use your sample instead and try reproducing the issue. Sorry for taking your time on the verification.
cvinayak
commented
2 years ago @jakkra I was able to reproduce the stall using my own sample today when I had 7 advertisers synchronized. What I observed is, the system recovers after 8 minutes which corresponds to the 24-bit RTC rollover.
I was not able to build your attached sample, it overflowed RAM.
Could you please confirm that in your application, after the stall, the system resume after ~8 mins?
jakkra
commented
2 years ago @cvinayak I'm not in office today but will test on monday. Regarding overflow strange, but just decrease to like 10 CONFIG_BT_PER_SYNC_MAX =10 and CONFIG_BT_CTRL_DF_PER_SCAN_CTE_NUM=1
jakkra
commented
2 years ago @cvinayak yes after about 8 minutes I get some events, see log:
Queued: 2 Synced: 8 Num err: 0/0
Running...
TAGS:0,0,0,0,0,sync...,0,sync...,0,0,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 2 Synced: 8 Num err: 0/0
Running...
TAGS:0,0,0,0,0,sync...,0,sync...,0,0,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 2 Synced: 8 Num err: 0/0
Running...
TAGS:0,0,0,0,0,sync...,0,sync...,0,0,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,-,
Queued: 2 Synced: 8 Num err: 0/0
----------------> 8 minutes passed around here <-------------------
--- 4 messages dropped ---
[00:08:17.301,879] <dbg> main: term_cb: Device was synced:
--- 3 messages dropped ---
(497305) PER_ADV_SYNC[5]: [DEVICE]: 0F:D9:D7:94:29:59 (random) sync terminated reason: 31
[00:08:17.306,030] <dbg> main: term_cb: Device was synced:
[00:08:17.306,243] <dbg> main: term_cb: Removed tag from per adv list
(497309) PER_ADV_SYNC[0]: [DEVICE]: 27:FD:B7:9F:15:AC (random) sync terminated reason: 31
[00:08:17.309,356] <dbg> main: term_cb: Device was synced:
[00:08:17.309,570] <dbg> main: term_cb: Removed tag from per adv list
(497311) PER_ADV_SYNC[2]: [DEVICE]: 3C:D3:E5:89:52:D1 (random) sync terminated reason: 31
[00:08:17.311,981] <dbg> main: term_cb: Device was synced:
[00:08:17.312,225] <dbg> main: term_cb: Removed tag from per adv list
(497319) PER_ADV_SYNC[7]: [DEVICE]: 18:DC:19:27:F2:37 (random) sync terminated reason: 31
[00:08:17.319,488] <dbg> main: term_cb: Device was synced:
[00:08:17.319,854] <dbg> main: term_cb: Removed tag from per adv list
(497326) PER_ADV_SYNC[8]: [DEVICE]: 11:B4:6D:C3:AA:D8 (random) sync terminated reason: 62
[00:08:17.326,995] <wrn> main: (497326)___Device not synced cancel sync tmo
[00:08:17.326,995] <wrn> main:
info->reason: 62
[00:08:17.327,026] <inf> main: Creating Sync for tags in list
Scan is running...
Running...@jakkra Thank you. From GPIO pin debugging of the scheduling, the timeouts of each periodic sync and the scanning seem to be running in the ULL context but I do not see any LLL code be invoked. I am continuing to inspect the implementation, so far it has been difficult in not getting to a fix quickly.
cvinayak
commented
2 years ago @jakkra ~I believe to have nailed down the cause of the repeated skip of colliding events in #50231, please verify and revert back so that the fix can make it to the latest release versions.~ Please ignore, the issue still exists even after the change.
cvinayak
commented
2 years ago @jakkra @mtpr-ot
I have concluded that an issue in the implementation of the ticker_resolve_collision() function is causing continuous skipping of all active radio events due to missing information to calculate the age of the radio events since their last successful use of the radio.
@jakkra I will ask you to use CONFIG_BT_TICKER_LOW_LAT=y alongwith a minor fix to enable its use. You will need this PR #50252
jakkra
commented
2 years ago @cvinayak thanks, this seems to resolve the issue, will do a bit more testing but so far so good!
cvinayak
commented
2 years ago CONFIG_BT_TICKER_LOW_LAT=y is the original controller contributions scheduling implementation addressing slow CPUs like nRF51x series. There are limitations of reduced radio utilization due to look ahead based scheduling, but lower CPU use, lower CPU duty cycle and lower CPU latencies on lower priority IRQs.
CONFIG_BT_TICKER_LOW_LAT=n is newer controller scheduling implementation with just-in-time resolution of overlapping radio events, which provided better radio utilization by being able to use free radio time that was un-utilized by the previously done radio events. Drawback of higher CPU use, CPU duty cycle and CPU latencies on lower priority IRQs
In ticker_resolve_collision(), the problem I am trying to understand is (2 tickers of 7.5ms period and 7.5 ms reservation, ticker1 to ticker2 has 5ms to start with):
am I, right? that ticker1 and ticker2 never get to run...
Reply from @mtpr-ot :
Yes, "force" and "age" are breaking normal round-robin. That's how it's always been. Age priority is a Nordic requirement that I reluctantly put in, and force is prevented as much as possible I think the logic in the ticker is OK (?), but the external usage of force may break it We have a condition in ULL to prevent random use of force flag
The CONFIG_BT_TICKER_LOW_LAT=y implementation recovers easily from most stressful multiple simultaneous roles.
Just round-robin scheduling would not handle supervision/sync lost cases, age was required to avoid smaller interval roles from starving larger interval roles, and force was required to break the round-robin.
Will see if I can have a solution for the repeated current ticker loosing to next ticker in ticker_resolve_collision().
cvinayak
commented
2 years ago @jakkra Do let me know if you were able to do more testing and if any issues faced while using CONFIG_BT_TICKER_LOW_LAT=y?
Meanwhile, I have this PR for CONFIG_BT_TICKER_LOW_LAT=n #50311, do switch back and test with this PR (i.e. upstream default new implementation should give higher radio utilization, is the future implementation for new features in Controller).
jakkra
commented
2 years ago @cvinayak
CONFIG_BT_TICKER_LOW_LAT=y works fine.CONFIG_BT_TICKER_LOW_LAT=n and CONFIG_BT_TICKER_PRIORITY_SET=y => Does not work same as before ("hangs")CONFIG_BT_TICKER_LOW_LAT=n and CONFIG_BT_TICKER_PRIORITY_SET=n => Works.There is a difference between 1. and 2. With 1. 25 tags synced I get an average of ~8 CTE's per second (uneven distributed over the tags, some have 5 some 20) Typical angles per second:
11 13 15 11 5 16 11 16 6 5 11 9 13 6 12 12 10 10 11 11 12 15 15 12 6
------------------------------------------------------------------------------------
10 11 16 12 10 14 12 15 5 4 11 12 12 5 14 12 9 10 12 13 10 13 9 13 4
------------------------------------------------------------------------------------
11 10 15 13 13 11 8 13 5 4 11 11 14 4 12 9 9 11 10 10 9 15 9 14 6
------------------------------------------------------------------------------------
10 11 12 11 10 11 8 14 6 7 8 17 9 4 12 13 10 10 11 13 11 11 12 14 4
------------------------------------------------------------------------------------
10 11 12 12 10 20 10 14 5 6 9 9 11 5 15 13 12 11 11 14 12 12 11 15 4With 2. 25 tags synced I get an average of ~4 CTE's per second (however most tags are at ~4 CTE's per second so even dsitribution of CTE's) Typical angles per second:
------------------------------------------------------------------------------------
5 6 6 5 5 6 6 4 4 5 6 6 5 5 5 4 4 5 5 5 6 5 5 6 5
------------------------------------------------------------------------------------
4 4 3 5 3 4 4 5 4 5 4 4 4 5 5 5 5 5 5 5 4 5 5 4 4
------------------------------------------------------------------------------------
5 5 6 4 5 5 6 4 4 4 6 4 6 5 5 5 4 5 5 4 5 5 5 6 6
------------------------------------------------------------------------------------
5 4 4 5 4 5 4 4 5 5 4 5 5 5 5 3 5 5 4 5 3 5 5 4 5
------------------------------------------------------------------------------------
4 5 5 3 5 5 5 4 4 4 5 5 4 5 5 5 4 4 1 5 5 4 4 5 4
------------------------------------------------------------------------------------
4 4 4 4 4 4 4 3 4 4 3 4 4 4 3 4 4 4 4 4 4 4 4 4 4
------------------------------------------------------------------------------------
5 5 5 5 4 5 5 4 5 5 5 5 4 5 5 4 5 5 5 5 5 5 5 5 5 @jakkra Thank you and appreciate your thoroughness in verifying the fix.
Regarding the rate of CTE, I would think of it to depend on both, how much of the advertisers are overlapping over the 7.5ms interval, and how the observer listen window is scheduled. I am not very familiar with the direction finding CTE feature, and would leave it you to decide which 1 or 2 is best for your application.
A suggestion, but you do not have to spend your immediate time to try it, to use continuous scanning say 10 ms interval 10ms window and have CONFIG_BT_CTLR_SCAN_UNRESERVED=y. This will provide most radio time to periodic sync roles and scanning get to use spare time between the periodic sync event.
Thank you again for contributing towards a stable Controller.
jakkra
commented
2 years ago @jakkra Thank you and appreciate your thoroughness in verifying the fix.
Regarding the rate of CTE, I would think of it to depend on both, how much of the advertisers are overlapping over the 7.5ms interval, and how the observer listen window is scheduled. I am not very familiar with the direction finding CTE feature, and would leave it you to decide which 1 or 2 is best for your application.
Less CTE's is pretty much same thing as missed periodic adv. packets (AUX_SYNC_IND), if the radio finds the per. adv. packet, it will also sample the CTE (assuming there is RAM). For us it's a tradeoff around as many CTE's as possible, but also being able to find new tags and re-sync to tags we lost sync to.
The more AUX_SYNC_IND/CTE's the better for us. So the behaviour with CONFIG_BT_TICKER_LOW_LAT=y (more CTEs) is preferred (so with 1.)
Using CONFIG_BT_TICKER_LOW_LAT=y together with https://github.com/zephyrproject-rtos/zephyr/pull/50311 I get this crash pretty much immediately.
ASSERTION FAIL [(ticker_status == 0) || (ticker_status == 2)] @ WEST_TOPDIR/zephyr/subsys/bluetooth/controller/ll_sw/ull_scan_aux.c:699
A suggestion, but you do not have to spend your immediate time to try it, to use continuous scanning say 10 ms interval 10ms window and have
CONFIG_BT_CTLR_SCAN_UNRESERVED=y. This will provide most radio time to periodic sync roles and scanning get to use spare time between the periodic sync event.Thank you again for contributing towards a stable Controller.
CONFIG_BT_CTLR_SCAN_UNRESERVED=y This sounds interesting and I'll try it out. I guess this make it harder to sync to new devices also if already many are synced?
cvinayak
commented
2 years ago Using CONFIG_BT_TICKER_LOW_LAT=y together with #50311 I get this crash pretty much immediately.
ASSERTION FAIL [(ticker_status == 0) || (ticker_status == 2)] @ WEST_TOPDIR/zephyr/subsys/bluetooth/controller/ll_sw/ull_scan_aux.c:699
You need this #50252 in addition.
Describe the bug When using periodic adv. intervals <~10ms then sometimes BT Controller stops reporting any events, including sync termination, CTEs, scan events etc.
To Reproduce Have 10 tags sending per. adv. with 7.5ms interval with adv. train of 5 and CTE enabled. I have not found replicatable way to reproduce, sometimes it's enough to just let all 10 tags sync and then wait a minute and it happens. Sometimes it's easier to reproduce by randomly resetting some tags. I have reproduced without CTE sampling enabled, however may or may not be easier to reproduce with it on. I have also reproduced with only 5-6 tags but I think it's easier with more.
Application: aoa_receiver_multiple_49915.zip
Expected behavior BT controller keeps reporting events.
Impact BT Controller stops generating events, application will be in strange state.
Logs and console output The application prints main: Interval: 6 whenever a device sending per. adv. is seen, as can be seen it's stopped reporting at the end.
Environment (please complete the following information):