April 2020 - OvmsDev - Open Vehicles

ESP32 CAN controller hardware bug / interrupt issue
by Michael Balzer 03 Apr '21

03 Apr '21

Second finding & commit: TL;DR: * ESP32 CAN controller is broken, delivers trashed & duplicated RX frames * we need to optimize interrupt latency Users have been reporting occasional false BMS readings on the Twizy for more than a year. The error always trashed the reading of voltage #10 and/or temperature #8, so I initially thought that must be a variant of the SPIRAM/cache bug. But the SPIRAM fix didn't help, and the bug still occured with all BMS data in internal RAM. The issue correlated with high load situations and the SIMCOM UART issue. On testing the latest changes by Marko, my car module began showing that issue regularly, so I could take a closer look. It turned out the wrong data came from the CAN bus. Checking with a CAN logger didn't show any wrong data on the bus. So I scanned our CAN driver for potential issues, found & solved some (even a serious race condition) but that didn't fix it. I then added debug dumps of all frames read, dug into the SJA1000 spec sheet and found this: The SJA1000 RX FIFO has a capacity of 64 bytes. It's supposed to work as a ring buffer, with frames wrapping around as necessary. If no space is left in the FIFO for a new frame coming in, that frame should be discarded completely, not counted, just the overflow indicator should be set & the according interrupt be generated. Reality differs. The frame causing the overflow is added to the FIFO partially. It's also counted both in the RMC register and indicated by RBS as a valid frame when retrieving the FIFO contents. The read buffer delivers the partial frame + some trashed bytes up to the nominal frame length. In the BMS frame sequence it would normally trash bytes 7 & 8 on the sixth frame of length 8 in a sequence. A standard frame needs a 3 byte header + the data bytes in the FIFO, so 6 frames would add up to 66 bytes => 64 + 2 trash. The first trash byte normally is "08", the second "84" or "2a" or sometimes "ab", possibly some internal SJA1000 data. Better yet, if you rely on the indicators of the SJA1000 when reading the FIFO, the SJA1000 will repeat the first frame within the FIFO after the invalid frame. Mostly once or twice, and sometimes 7 times or more: inv_msg: framecnt=13, invindex=6 inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 24 04 00 00 11 40 10 22 37 55 00 37 | 4..?........$....@."7U.7 inv_msg: 25 04 00 00 0a 1b 44 ff fe 4e 01 26 | 4..?........%.....D..N.& inv_msg: 54 05 00 00 37 37 37 37 37 37 37 00 | 4..?........T...7777777. inv_msg: 56 05 00 00 31 63 14 31 53 14 31 4a | 4..?........V...1c.1S.1J inv_msg: 57 05 00 00 31 43 14 31 53 15 *08 2a* | 4..?........W...1C.1S..* ^^^^^ trashed bytes … followed by 7 repetitions of the first frame: inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n inv_msg: 55 01 00 00 07 98 50 54 54 20 00 6e | 4..?........U.....PTT .n If you had occasional strange false readings leading to strange effects, this may be the explanation. Note: the SJA1000 FIFO bug may need specific circumstance to occur in addition to the overflow, maybe the overflow happening on a specific byte position in the FIFO -- I haven't tried to determine that. I've tried clearing the overflow ASAP, looping on the IR indicator and looping on the RMC, the fault is always the same. The workaround I've now done is adding up the message lengths read during a FIFO run and discard all frames exceeding the 64 byte border. Not pretty, but functional. That keeps the trashed frames from being forwarded to the OVMS application level. As with the SIMCOM UART, these overflows wouldn't happen if the interrupt handler would react fast enough. It seems we've got a general interrupt latency issue. And just as with the SIMCOM I saw a reduction of overflows when allocating the CAN IRQ on core #0, another one with raising the IRQ level to 3, so that's also part of my commit. The esp-idf CAN driver apparently has the same issue even in the latest release, I'll contact the author about this or post another issue to Espressif. So our interrupt allocation is now: Task Run# Lvl ISR# Usage Source ---------------------------------------------------------------------------------------- - 0 1 0 RTC Core ETS_RTC_CORE_INTR_SOURCE esp_timer 0 1 0 RTOS esp_timer ETS_TIMER2_INTR_SOURCE ipc0 0 1 0 RTOS Scheduler Core0 ETS_FROM_CPU_INTR0_SOURCE ipc1 1 1 1 RTOS Scheduler Core1 ETS_FROM_CPU_INTR1_SOURCE main 0 1 0 RTOS Watchdog ETS_TG0_WDT_LEVEL_INTR_SOURCE OVMS Events 1 1 1 Peripherals (GPIO ISR) ETS_GPIO_INTR_SOURCE OVMS Events 1 1 1 MAX7317 (spi_nodma) ETS_SPI3_INTR_SOURCE *esp32can init 0 3 0 ESP32 CAN ETS_CAN_INTR_SOURCE** **OVMS SIMCOM 0 2 0 SIMCOM UART ETS_UART1_INTR_SOURCE* OVMS Events 1 1 1 USB console (UART) ETS_UART0_INTR_SOURCE OVMS Events 1 1 1 SD card ETS_SDIO_HOST_INTR_SOURCE ---------------------------------------------------------------------------------------- I think we need to find the source of the interrupt latency and/or find some better scheme to distribute the tasks & interrupts over the cores. I still don't know why core #1 already got an issue with just our 6 interrupts. This may be related to the SPIRAM fix adding overhead, but I've seen the FIFO overflows before applying the fix, and the CAN issue also has been present for over a year. My working hypothesis is some task/driver disabling interrupts for too often / too long, or non-IRAM ISRs getting delayed for too often / too long. And it seems this is an issue especially on core #1. Please verify & comment. Regards, Michael PS: a little side mystery: the netmanager task starts with priority 5, then gets raised to 22 (probably a mutex priority inheritance), but never gets lowered back to 5 afterwards. A FreeRTOS bug? -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

2 11

File logging task
by Michael Balzer 04 Jul '20

04 Jul '20

Everyone, I've pushed the long due refactoring of the file logging into a dedicated task. This removes most of the delays involved in file logging, as the fsync() and log cycling now is done in the logging task and no longer blocks overall log message processing. I stumbled upon a bad thing (tm) though we need to resolve with logging: the esp-idf logging generally involves a semaphore wait of max 10 ms (!). I wasn't aware of this because I didn't look into the source before, there also is no warning about this in the esp-idf documentation (https://docs.espressif.com/projects/esp-idf/en/latest/api-reference/system/…) so I guess I'm not the only one being taken by surprise here. // Maximum time to wait for the mutex in a logging statement. #define *MAX_MUTEX_WAIT_MS 10* #define MAX_MUTEX_WAIT_TICKS ((MAX_MUTEX_WAIT_MS + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS) … void IRAM_ATTR *esp_log_write*(esp_log_level_t level, const char* tag, const char* format, ...) { if (!s_log_mutex) { s_log_mutex = xSemaphoreCreateMutex(); } if (*xSemaphoreTake(s_log_mutex, MAX_MUTEX_WAIT_TICKS*) == pdFALSE) { return; } … That semaphore is needed to secure the log level tag cache against parallel access, so it also affects log messages of currently disabled tags and/or levels. This means we *must not* use the standard logging from timer callbacks, at no verbosity level. But we do, partially caused by my own code serving as a bad example I assume -- sorry. But I've not only found direct log calls in most vehicle timer callbacks, there also are some hidden ones from calling the framework, for example marking a notification as read can produce a log output from Cleanup() if tracing is enabled. We need to change this short to mid term. This may be the cause of those strange timer overflow issues we've seen occasionally. It also means every debug or verbose log output currently in the code involves potentially multiple semaphore waits, that's for example the case for all hex dumps logged by the SIMCOM module. Our primary option is to remove all log calls from all low level framework functions and timer callbacks. A simple & quick workaround could be to extend the ESP_LOGx macros to check if they are executed in the timer task context, if so suppress the message or call the ESP_EARLY log function instead. That will hide these log messages from the logging framework though, if using the _EARLY_ variant they only will be sent to the USB port. For a better solution I thought about adding a dedicated queue & task for the initial log submission as well. That will need quite some rework to the esp-idf (no changes for this in the current master) but would allow to continue logging as we do now. Cons: queue submission involves some overhead & RAM, printf format expansion needs to be done before the tag/level check, messages may need to be dropped if the task starves or RAM gets tight, log output to consoles will depend on a task as well. Opinions / better ideas? Regards, Michael -- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

2 5

What happened to TPMS?
by Greg D. 07 Jun '20

07 Jun '20

6 13

3.2.012 EAP OTA
by Mark Webb-Johnson 02 May '20

02 May '20

I think the tpms bug is serious enough to require a release. So, I’ve built a 3.2.012 and released to EAP at api.openvehicles.com <http://api.openvehicles.com/>. 2020-04-22 MWJ 3.2.012 OTA release - #357 tpms rear left temperature incorrect in v2 protocol - #354 Flush UART buffer when power cycling modem - General stability improvements to CAN logging and playback As usual, for full changelog see: https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/blob/maste… <https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/blob/maste…> This will also allow us to get more feedback on the uart reset approach, and if it makes any difference to those modules that can’t seem to recover from loss of cellular connection. Regards, Mark.

3 5

3.2.012 test
by Michael Eric Menk 29 Apr '20

29 Apr '20

I have downloaded and tested 3.2.012 The C-zero (MiEV clone) charge bug was not included. On 25.04.2020 20:24, Tamás Kovács wrote: > Thanks the log, now i modified the AC charge detection code. > > If you want to try add the following to config / firmware / flash from > web : kommykt-nas.ddns.net:22289/ovms3.bin > <http://kommykt-nas.ddns.net:22289/ovms3.bin> > This is my NAS, the internet speed is not very high. > The changes that Tamás did worked. It tould have been nice that this would be included in 3.2.012 before it goes in prod. As far as I can see, the code is not committed into master yet. A better range_est while fastcharing can worked on later.

2 1

US Stock
by Mark Webb-Johnson 27 Apr '20

27 Apr '20

I’m pleased to say that I’ve come to an agreement with Carl Medlock (at Medlock Tesla Service in Seattle, USA) to stock OVMS US kits (primarily for Tesla Roadster owners in USA). Carl was a long-term Tesla employee, and for the past 10 years has run a garage with his sons looking after Tesla Roadsters in the USA. https://medlockandsons.com/ <https://medlockandsons.com/> Carl’s team will be able to handle local distribution of OVMS in the USA, as well as installation for those users in the Seattle area that need it. He should have his first stock later this week. Regards, Mark

1 0

3.2.011 BUG for MIEV based cars
by Michael Eric Menk 26 Apr '20

26 Apr '20

Charge-status disappeared on update to 3.2.011 . The SOC is read, but it do not know that the car is charging. As you can see from the screenshot, OVMS sees the inncomming charge into the battery, but the state is "Not charging" -- Michael Eric Menk

2 12

make apt-flash destination location?
by Eddy Vromen 22 Apr '20

22 Apr '20

Hi All, Quick question: I am experimenting with some code changes and i am using the sdcard method to get a new .bin file on the device. It will automatically alternate between the 2 OTA image loactions which is great. I would like to make this process a little less labor intensive: When i use "make apt-flash", where does the code get flashed? With this method, how can i pick between the 2 OTA image locations? Thanks, Eddy

2 3

Modem unable to power cycle successfully
by Mark Webb-Johnson 16 Apr '20

16 Apr '20

I’ve seen cases where the modem will not come up correctly, even following a power cycle. But, a reset of the OVMS module (ESP32) solves the problem. This really makes no sense, unless something is getting corrupted inside the UART / EGPIO driver itself. The modem module status is not changed during an ESP32 reset - only the software side of it running in the ESP32. Thomas Heder has reported some success with using uart_flush to flush the UART ring buffer when power cycling the modem. Flushing the buffer would not seem to affect this, as we use ‘AT’ to look for an OK response during power up check anyway; but perhaps something is corrupt in the ring buffer itself, so using uart_flush clears that problem. Note that uart_flush is an alias for uart_flush_input, and the source code does seem to show a complete reset of the ring buffer pointers with interrupts disabled (not just a simple emptying). Anyway, the approach does not seem to do any harm, so I have added it to the latest code and let’s see if it improves the situation. https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/354 <https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/354> Regards, Mark.

1 0

Ready for 3.2.011?
by Mark Webb-Johnson 14 Apr '20

14 Apr '20

It is time for a 3.2.011 OTA release. Things seem stable for me now, and it would be good to get these releases out every month or so. Is there anything else that needs to be in this? If so, please commit and/or pull request. I would like to get this release out to EAP over the weekend. Regards, Mark.

5 15