Device-os: Random I2C resets caused by non-monotonic HAL_Timer_Get_Micro_Seconds()
Bug Report
Expected Behavior
I2C timeout should work.
Observed Behavior
It doesn't. I did the following observation with my logic analyzer:
You can see the I2C reset happens already after 0.15ms which is very bad for some devices. I further dig into device-os and found this:
It seemed like on some rare occasions the timeout is skipped. I added a debug log like:
#define WAIT_TIMED(timeout_ms, what) ({ \
system_tick_t _micros = HAL_Timer_Get_Micro_Seconds(); \
bool res = true; \
while ((what)) { \
system_tick_t tmp = HAL_Timer_Get_Micro_Seconds(); \
system_tick_t dt = tmp - _micros; \
bool nok = ((timeout_ms * 1000 < dt) && (what)); \
if (nok) { \
LOG_DEBUG(TRACE, "Timed out %lu, %lu, %lu", dt, _micros, tmp); \
res = false; \
break; \
} \
} \
res; \
})
and I got this log: TRACE: Timed out 4294966523, 670721873, 670721100. It seems like HAL_Timer_Get_Micro_Seconds() is not monotonic which results in a negative value which wraps around in system_tick_t and results in an immediate timeout. To proof my point I changed to a signed int like:
#define WAIT_TIMED(timeout_ms, what) ({ \
system_tick_t _micros = HAL_Timer_Get_Micro_Seconds(); \
bool res = true; \
while ((what)) { \
system_tick_t tmp = HAL_Timer_Get_Micro_Seconds(); \
int64_t dt = ((int64_t) tmp - (int64_t)_micros); \
bool nok = ((timeout_ms * 1000 < dt) && (what)); \
if (nok) { \
LOG_DEBUG(TRACE, "Timed out %lu, %lu, %lu", dt, _micros, tmp); \
res = false; \
break; \
} \
} \
res; \
})
and everything runs fine. Any idea why HAL_Timer_Get_Micro_Seconds() is not monotonic? We have 40+ B5SOMs facing the same problem. Tested on device-os 2.0.1 and latest 3.0.0-RC1.
perotom
All 18 comments
@perotom Thanks for the issue report. Could you provide some additional info on how this can be reproduced?
avtolstoy
on 1 Mar 2021
I think it will be quite hard to reproduce for you as we are using several devices via i2c (battery management, gnss receiver, nfc reader, ...).
I think you should be able to reproduce it when you have an i2c device which delays the read operation quite a bit. For us this happens quite often due to our GNSS receiver. With our devices the i2c bus will freeze permanently after several of these wrong timeouts (seems like some devices break when i2c_reset happens too often).
The most important thing is: Is HAL_Timer_Get_Micro_Seconds() a monotonic function at all times? Otherwise the solution will be to simply change dt to int64_t.
perotom
on 1 Mar 2021
Microsecond and millisecond counters should be monotonic. We might have a bug in the logic that extends micros resolution from ~31us using clock cycle counter, so I'm trying to understand the conditions that lead to this behavior e.g. high interrupt pressure, tight loops with interrupts disabled or perhaps it's just very random.
avtolstoy
on 1 Mar 2021
One thing we observed is that it happens most of the time in the same interval (in our case it was 4 minutes, sometimes 8 or 12 minutes too). Keep in mind that we are polling i2c every 25ms so we might miss some cases.
If you got an easy way of testing that we could make these changes and test them on our devices.
perotom
on 1 Mar 2021
If it's easily reproducible for you, would you mind applying the following patch and seeing if there is any difference in behavior? This is just a hunch, but it would be nice if we could confirm at least an approximate source of the problem.
diff --git a/hal/src/nRF52840/timer_hal.cpp b/hal/src/nRF52840/timer_hal.cpp
index c42091003..b51d16647 100644
--- a/hal/src/nRF52840/timer_hal.cpp
+++ b/hal/src/nRF52840/timer_hal.cpp
@@ -326,25 +326,12 @@ extern "C" void RTC_IRQ_HANDLER(void) {
}
uint64_t hal_timer_micros(void* reserved) {
- // Extends the resolution from 31us to about 5us using DWT->CYCCNT
// Make sure that sTickCountAtLastOverflow and current timer values are fetched atomically
uint32_t lastOverflowTicks;
uint64_t lastOverflowMicros;
uint64_t curUs = getCurrentTimeWithTicks(&lastOverflowTicks, &lastOverflowMicros);
- uint32_t usTicks = SYSTEM_US_TICKS;
-
- uint64_t elapsedUs = curUs - lastOverflowMicros;
- uint64_t elapsedTicks = elapsedUs * usTicks;
- uint32_t syncTicks = (uint32_t)((uint64_t)lastOverflowTicks + elapsedTicks);
- uint32_t tickDiff = DWT->CYCCNT - syncTicks;
- // If we are over 10 RTC ticks, we are better off fetching new value
- if (tickDiff > (DWT_US_THRESHOLD * usTicks)) {
- curUs = getCurrentTimeWithTicks(&lastOverflowTicks, &lastOverflowMicros);
- tickDiff = 0;
- }
-
- return sTimerMicrosBaseOffset + curUs + (tickDiff / usTicks);
+ return sTimerMicrosBaseOffset + curUs;
}
uint64_t hal_timer_millis(void* reserved) {
Perfect we tried it on the device and after 1 1/2 hours it still works. Seems like it is it.
perotom
on 1 Mar 2021
Thanks for trying that out! We'll look into this and I'll update this issue.
avtolstoy
on 1 Mar 2021
We are not totally sure if this issue is related to that but we observed some network connection issues as well (we are using TPC). After we see the i2c dying we see these logs:
11:26:29.051 -> 0001005329 [gsm0710muxer] INFO: GSM07.10 muxer thread exiting
11:26:29.051 -> 0001005331 [ncp.client] TRACE: NCP connection state changed: 1
11:26:29.051 -> 0001005330 [net.pppncp] TRACE: NCP event 2
11:26:29.051 -> 0001005330 [net.pppncp] TRACE: State changed event: 1
11:26:29.051 -> 0001005331 [net.ppp.client] TRACE: PPP thread event LOWER_DOWN
11:26:29.051 -> 0001005332 [net.ppp.client] TRACE: State CONNECTED -> DISCONNECT
11:26:29.051 -> 0001005332 [net.ppp.client] TRACE: State DISCONNECT -> DISCONNECTING
11:26:29.051 -> 0001005333 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
11:26:29.051 -> 0001005334 [net.ppp.client] TRACE: PPP phase -> 9
11:26:29.051 -> 0001005334 [net.ppp.client] TRACE: PPP phase -> 6
11:26:29.051 -> 0001005335 [net.ppp.client] TRACE: PPP phase -> 12
11:26:29.051 -> 0001005335 [net.ppp.client] TRACE: PPP phase -> 0
11:26:29.051 -> 0001005337 [net.ppp.client] TRACE: PPP thread event DOWN
11:26:29.084 -> 0001005337 [net.ppp.client] TRACE: State DISCONNECTING -> DISCONNECTED
11:26:29.084 -> 0001005338 [net.ppp.client] TRACE: State DISCONNECTED -> READY
11:26:29.084 -> 0001005339 [wiring] ERROR: recv error = 113
11:26:29.084 -> 0001005348 [ncp.client] TRACE: Try powering modem off using AT command
11:26:30.076 -> 0001006348 [gsm0710muxer] INFO: Stopping GSM07.10 muxer
11:26:30.076 -> 0001006348 [gsm0710muxer] INFO: GSM07.10 muxer stopped
11:26:30.076 -> 0001006349 [net.pppncp] TRACE: NCP event 3
11:26:30.076 -> 0001006349 [net.pppncp] TRACE: NCP power state changed: IF_POWER_STATE_POWERING_DOWN
11:26:30.076 -> 0001006350 [system.nm] TRACE: Interface 4 power state changed: 3
11:26:30.076 -> 0001006350 [ncp.client] TRACE: Powering modem off
I don't know if this could be related to this issue as well but maybe some timeouts happen there as well. I just wanted to mention the strange correlation.
perotom
on 2 Mar 2021
Connection problems are probably also caused by timers getting broken, as 07.10 muxer for example uses millis (powered by micros underneath) for things like retransmissions and keepalive.
@perotom We've done a number of synthetic tests and it's not really easy to reproduce this issue and make some kind of an automated test. Would you mind trying the changes in this branch https://github.com/particle-iot/device-os/compare/fix/gen3-rtc-overflow-cyccnt-sync ?
avtolstoy
on 10 Mar 2021
I flashed just the system-part1.bin for this branch but the device shows the same issues as before.
It seems like this branch won't solve the issue.
perotom
on 11 Mar 2021
Ok I am not quite sure if the build process worked correctly with VS Code for the branch. I will run some more tests this night. I will give you more feedback tomorrow.
Meanwhile I logged some more numbers when non-monotonic action happens. Maybe they will help you:
14:38:15.547 -> 0000710726 [hal] TRACE: Timed out 4294967080, 710726382, 710726166
14:39:14.917 -> 0000770092 [hal] TRACE: Timed out 4294966575, 770092610, 770091889
Now I have some test results: The error occurs less often but still exists. Out of 7 devices 1 has a locked up i2c. (This happens after the error occurs multiple times and some i2c devices are not able to handle multiple i2c resets).
Btw: We are shipping our products right now with your temporary fix. Do you see any issues with that besides the reduced micros resolution?
perotom
on 12 Mar 2021
I created a second hal_timer_micros2 to log some internal values when the bug occurs:
uint64_t hal_timer_micros2(uint32_t *tmp) {
// Extends the resolution from 31us to about 5us using DWT->CYCCNT
// Make sure that sTickCountAtLastOverflow and current timer values are fetched atomically
uint32_t lastOverflowTicks;
uint64_t lastOverflowMicros;
bool inSync = false;
uint64_t curUs = getCurrentTimeWithTicks(&lastOverflowTicks, &lastOverflowMicros, &inSync);
uint32_t usTicks = SYSTEM_US_TICKS;
uint32_t tickDiff = 0;
// NOTE: Ignore DWT->CYCCNT at RTC overflow until such overflow event is properly handled
if (inSync) {
uint64_t elapsedUs = curUs - lastOverflowMicros;
uint64_t elapsedTicks = elapsedUs * usTicks;
uint32_t syncTicks = (uint32_t)((uint64_t)lastOverflowTicks + elapsedTicks);
tickDiff = DWT->CYCCNT - syncTicks;
// If we are over 10 RTC ticks, we are better off fetching new value
if (tickDiff > (DWT_US_THRESHOLD * usTicks)) {
curUs = getCurrentTimeWithTicks(&lastOverflowTicks, &lastOverflowMicros, &inSync);
tickDiff = 0;
}
}
*tmp = (tickDiff / usTicks);
return sTimerMicrosBaseOffset + curUs + (tickDiff / usTicks);
}
and I used my modified WAIT_TIMED:
#define WAIT_TIMED(timeout_ms, what) ({ \
uint32_t t1, t2; \
system_tick_t _micros = HAL_Timer_Get_Micro_Seconds2(&t1); \
bool res = true; \
while ((what)) { \
system_tick_t tmp = HAL_Timer_Get_Micro_Seconds2(&t2); \
system_tick_t dt = tmp - _micros; \
bool nok = ((timeout_ms * 1000 < dt) && (what)); \
if (nok) { \
LOG_DEBUG(TRACE, "Timed out %lu, %lu, %lu\t\t%lu, %lu", dt, _micros, tmp, t1, t2); \
res = false; \
break; \
} \
} \
res; \
})
I was able to log these errors:
11:00:46.446 -> 0001603217 [hal] TRACE: Timed out 4294966746, 1603217561, 1603217011 947, 0
11:00:46.446 -> 0001603271 [hal] TRACE: Timed out 4294966647, 1603271646, 1603270997 955, 0
11:00:46.446 -> 0001603326 [hal] TRACE: Timed out 4294967030, 1603325645, 1603325379 968, 0
11:00:46.446 -> 0001603958 [hal] TRACE: Timed out 4294966398, 1603958815, 1603957917 959, 0
11:00:46.446 -> 0001604471 [hal] TRACE: Timed out 4294966482, 1604471731, 1604470917 966, 0
11:00:46.446 -> 0001604899 [hal] TRACE: Timed out 4294966498, 1604899114, 1604898316 981, 0
11:00:56.479 -> 0001605051 [hal] TRACE: Timed out 4294966360, 1605051077, 1605050141 997, 0
11:00:56.479 -> 0001605103 [hal] TRACE: Timed out 4294966360, 1605103628, 1605102692 997, 0
11:00:56.479 -> 0001605156 [hal] TRACE: Timed out 4294966345, 1605156561, 1605155610 982, 0
11:00:56.479 -> 0001605208 [hal] TRACE: Timed out 4294966390, 1605208609, 1605207703 997, 0
11:00:56.479 -> 0001605286 [hal] TRACE: Timed out 4294966343, 1605286323, 1605285370 983, 0
11:00:56.479 -> 0001605361 [hal] TRACE: Timed out 4294966349, 1605362154, 1605361207 978, 0
11:00:56.479 -> 0001605414 [hal] TRACE: Timed out 4294966334, 1605414567, 1605413605 992, 0
11:00:56.479 -> 0001605466 [hal] TRACE: Timed out 4294966302, 1605466540, 1605465546 994, 0
11:00:56.479 -> 0001605518 [hal] TRACE: Timed out 4294966303, 1605518663, 1605517670 993, 0
11:00:56.479 -> 0001605596 [hal] TRACE: Timed out 4294966315, 1605596166, 1605595185 981, 0
11:00:56.479 -> 0001605648 [hal] TRACE: Timed out 4294966315, 1605648565, 1605647584 981, 0
11:01:00.097 -> 0001605802 [hal] TRACE: Timed out 4294966302, 1605802539, 1605801545 994, 0
11:01:00.097 -> 0001605878 [hal] TRACE: Timed out 4294966301, 1605878528, 1605877533 995, 0
11:01:00.097 -> 0001605930 [hal] TRACE: Timed out 4294966297, 1605930992, 1605929993 999, 0
11:01:00.097 -> 0001605982 [hal] TRACE: Timed out 4294966300, 1605983571, 1605982575 996, 0
11:01:00.097 -> 0001606034 [hal] TRACE: Timed out 4294966300, 1606035573, 1606034577 996, 0
11:01:00.097 -> 0001606160 [hal] TRACE: Timed out 4294966298, 1606161277, 1606160279 998, 0
11:01:00.097 -> 0001606212 [hal] TRACE: Timed out 4294966297, 1606213585, 1606212586 999, 0
11:01:00.097 -> 0001606289 [hal] TRACE: Timed out 4294966302, 1606290911, 1606289917 994, 0
11:01:00.130 -> 0001606392 [hal] TRACE: Timed out 4294966297, 1606393181, 1606392182 999, 0
11:01:00.130 -> 0001606470 [hal] TRACE: Timed out 4294966298, 1606471091, 1606470093 998, 0
11:01:00.130 -> 0001606522 [hal] TRACE: Timed out 4294966297, 1606523613, 1606522614 999, 0
11:01:00.130 -> 0001606626 [hal] TRACE: Timed out 4294966298, 1606627311, 1606626313 998, 0
11:01:00.130 -> 0001606678 [hal] TRACE: Timed out 4294966298, 1606679618, 1606678620 998, 0
Hopefully this will help you even further.
perotom
on 12 Mar 2021
Btw: We are shipping our products right now with your temporary fix. Do you see any issues with that besides the reduced micros resolution?
There shouldn't be any other negative consequences apart from reduced resolution, correct :+1:
Hopefully this will help you even further.
Thanks again for looking into this. The numbers provided are really useful and indicate that this may happen at other points in time, not only at the moment of RTC overflow.
avtolstoy
on 12 Mar 2021
Perfect thanks!
Let me know if you need some more tests.
perotom
on 12 Mar 2021
Are there any plans on fixing this issue?
I think it is quite a severe problem as it affects even TCP connection timeouts.
perotom
on 28 Mar 2021
@perotom I don't think this should be affecting TCP connections. Neither our wiring layer, nor socket layer, nor LwIP socket implementation uses micros/millis/unixtime counters (LwIP uses systick-based counter https://github.com/particle-iot/device-os/blob/develop/hal/src/nRF52840/lwip/sys_arch.c#L136 https://github.com/particle-iot/device-os/blob/develop/hal/src/nRF52840/freertos/FreeRTOSConfig.h#L136).
We have a solution that we are testing out currently under various conditions: https://github.com/particle-iot/device-os/tree/fix/201-i2c-rtc
avtolstoy
on 29 Mar 2021
Thats true. We are using MQTT and the library uses millis which causes problems. Seems like we have to replace all millis() with Systicks to get ride of the issue.
perotom
on 1 Apr 2021
Related issues
ScruffR
路
9Comments
Isawwad
路
5Comments
ScruffR
路
10Comments
ScruffR
路
6Comments
ScruffR
路
5Comments