I2C issues, what are best practices for multiple I2C devices running in different tasks

[I-Connect]

Hi,

We have a custom PCB with multiple I2C devices:
-BMP280 (barometer) getting values every 10 S
-2x SX1509 (IO-multiplexer) getting/sending values when needed
-ICM-20948 (9 axis motion tracking) getting values every 500 mS
-AB0805 (RTC) getting values every 10 S

16mB ESP32-D0WD
platform IO
espressif32@~3.2.0
4K7 pull ups on SCL and SDA
I2C speed 100Khz

Next to the I2C devices we are running:
-DHT22 (temp/humidity) via onewire, getting values every 10 S
-Several analog sensors, getting values every 10-30 S
-SIM7000 (GSM) via HW serial, values sent when changed (via MQTT), checking connection every 10 S
-Nextion (display) via HW serial, values are sent/received when changed or action is done on display
-Victron VE-Direct via software serial, values are read every 5 S
-ESP CAN, values are sent/received when changed or action is required
-BLE (NimBle) sending data to an app when values change or there is action on the app

We use several tasks for reading data and controlling outputs.
Some data handling/logic is timed but mostly using an observer pattern.

We have put a semaphore around all I2C actions in our code/libraries to prevent I2C actions from different tasks to occur simultaneously

Issue is that we are getting (seems random) I2C errors like:
-i2cProcQueue(): Bus busy, reinit
-emptyRxFifo(): no Storage location for 1
-division by 0 which seems to be related to I2C
below some different log outputs.

Frequency of errors varies, sometimes it runs without errors for several minutes, sometimes we get 1 "set" of I2C error data, sometimes three "sets" in a row. 
I2C bus mostly recovers, sometimes with erroneous data being received from barometer (ie Node [28]: P: 744 hPa T: 33.2 C in stead of Node [28]: P: 1019 hPa T: 33.2 C). This would be acceptable.
But what is not acceptable is that it also happens that reading of the ICM-20948 keeps on failing (I2C is still working because correct BMP values are still being read/displayed)
The division by 0 obviously crashes the ESP.  

We are unable to structurally reproduce the error
Pinning tasks to different cores seems to influence the error frequency/type
Adding logging seems to influence error frequency/type.

So we suspect timing to influence the issue...

Are there any best practices for I2C wrt
-Task priority
-Core pinning
-Using semaphores around I2C calls/blocks 
-Need to separate interrupt heavy tasks (Software serial is a heavy interrupt user, could this interfere)
-Polling of I2C sensors
-Troubleshooting (how can I pinpoint if there is a specific I2C ic/sensor that is causing this

Is there a way to streamline I2C bus usage in a better way than using semaphores?

@stickbreaker , I have seen loads of great advice/help from you wrt I2C, would appreciate if you could give some advice on how to troubleshoot this. 

Thx!!

Used I2C related HW libraries:
https://github.com/curransinha/AB0805_lib/blob/master/AB0805.cpp (we made a fork and refactored to not having to use external I2C lib)
https://github.com/adafruit/Adafruit_BMP280_Library
https://github.com/sparkfun/SparkFun_ICM-20948_ArduinoLibrary.git
https://github.com/sparkfun/SparkFun_SX1509_Arduino_Library

[I][esp32-hal-i2c.c:1138] i2cProcQueue(): Bus busy, reinit
[E][esp32-hal-i2c.c:760] emptyRxFifo(): no Storage location for 15
[D][esp32-hal-i2c.c:1353] i2cProcQueue():  Gross Timeout Dead start=0x82376, end=0x823a8, =50, max=50 error=1
[E][esp32-hal-i2c.c:318] i2cDumpI2c(): i2c=0x3ffbdcec
[I][esp32-hal-i2c.c:319] i2cDumpI2c(): dev=0x60013000 date=0x16042000
[I][esp32-hal-i2c.c:321] i2cDumpI2c(): lock=0x3ffbae98
[I][esp32-hal-i2c.c:323] i2cDumpI2c(): num=0
[I][esp32-hal-i2c.c:324] i2cDumpI2c(): mode=1
[I][esp32-hal-i2c.c:325] i2cDumpI2c(): stage=3
[I][esp32-hal-i2c.c:326] i2cDumpI2c(): error=1
[I][esp32-hal-i2c.c:327] i2cDumpI2c(): event=0x3ffd48f0 bits=0
[I][esp32-hal-i2c.c:328] i2cDumpI2c(): intr_handle=0x3ffd48d8
[I][esp32-hal-i2c.c:329] i2cDumpI2c(): dq=0x3ffe2598
[I][esp32-hal-i2c.c:330] i2cDumpI2c(): queueCount=1
[I][esp32-hal-i2c.c:331] i2cDumpI2c(): queuePos=1
[I][esp32-hal-i2c.c:332] i2cDumpI2c(): errorByteCnt=0
[I][esp32-hal-i2c.c:333] i2cDumpI2c(): errorQueue=1
[I][esp32-hal-i2c.c:334] i2cDumpI2c(): debugFlags=0x00000000
[I][esp32-hal-i2c.c:311] i2cDumpDqData(): Debug Buffer not Enabled
[I][esp32-hal-i2c.c:354] i2cDumpInts(): Debug Buffer not Enabled
[W][esp32-hal-i2c.c:1419] i2cCheckLineState(): invalid state sda(21)=0, scl(22)=1
[D][esp32-hal-i2c.c:1427] i2cCheckLineState(): Recovered after 1 Cycles
[I][esp32-hal-i2c.c:1138] i2cProcQueue(): Bus busy, reinit
[D][esp32-hal-i2c.c:1344] i2cProcQueue():  Busy Timeout start=0x8240d, end=0x8243f, =50, max=50 error=1
[E][esp32-hal-i2c.c:318] i2cDumpI2c(): i2c=0x3ffbdcec
[I][esp32-hal-i2c.c:319] i2cDumpI2c(): dev=0x60013000 date=0x16042000
[I][esp32-hal-i2c.c:321] i2cDumpI2c(): lock=0x3ffbae98
[I][esp32-hal-i2c.c:323] i2cDumpI2c(): num=0
[I][esp32-hal-i2c.c:324] i2cDumpI2c(): mode=1
[I][esp32-hal-i2c.c:325] i2cDumpI2c(): stage=3
[I][esp32-hal-i2c.c:326] i2cDumpI2c(): error=1
[I][esp32-hal-i2c.c:327] i2cDumpI2c(): event=0x3ffd48f0 bits=0
[I][esp32-hal-i2c.c:328] i2cDumpI2c(): intr_handle=0x3ffd48d8
[I][esp32-hal-i2c.c:329] i2cDumpI2c(): dq=0x0
[I][esp32-hal-i2c.c:330] i2cDumpI2c(): queueCount=0
[I][esp32-hal-i2c.c:331] i2cDumpI2c(): queuePos=0
[I][esp32-hal-i2c.c:332] i2cDumpI2c(): errorByteCnt=0
[I][esp32-hal-i2c.c:333] i2cDumpI2c(): errorQueue=0
[I][esp32-hal-i2c.c:334] i2cDumpI2c(): debugFlags=0x00000000
[I][esp32-hal-i2c.c:354] i2cDumpInts(): Debug Buffer not Enabled
[I][esp32-hal-i2c.c:1138] i2cProcQueue(): Bus busy, reinit

[I][esp32-hal-i2c.c:1138] i2cProcQueue(): Bus busy, reinit
[I][esp32-hal-i2c.c:1138] i2cProcQueue(): Bus busy, reinit
[I][esp32-hal-i2c.c:1138] i2cProcQueue(): Bus busy, reinit
[D][esp32-hal-i2c.c:1344] i2cProcQueue():  Busy Timeout start=0x15df1b, end=0x15df4d, =50, max=50 error=1
[E][esp32-hal-i2c.c:318] i2cDumpI2c(): i2c=0x3ffbdcec
[I][esp32-hal-i2c.c:319] i2cDumpI2c(): dev=0x60013000 date=0x16042000
[I][esp32-hal-i2c.c:321] i2cDumpI2c(): lock=0x3ffbae98
[I][esp32-hal-i2c.c:323] i2cDumpI2c(): num=0
[I][esp32-hal-i2c.c:324] i2cDumpI2c(): mode=1
[I][esp32-hal-i2c.c:325] i2cDumpI2c(): stage=3
[I][esp32-hal-i2c.c:326] i2cDumpI2c(): error=1
[I][esp32-hal-i2c.c:327] i2cDumpI2c(): event=0x3ffd48f0 bits=0
[I][esp32-hal-i2c.c:328] i2cDumpI2c(): intr_handle=0x3ffd48d8
[I][esp32-hal-i2c.c:329] i2cDumpI2c(): dq=0x0
[I][esp32-hal-i2c.c:330] i2cDumpI2c(): queueCount=0
[I][esp32-hal-i2c.c:331] i2cDumpI2c(): queuePos=0
[I][esp32-hal-i2c.c:332] i2cDumpI2c(): errorByteCnt=0
[I][esp32-hal-i2c.c:333] i2cDumpI2c(): errorQueue=0
[I][esp32-hal-i2c.c:334] i2cDumpI2c(): debugFlags=0x00000000
[I][esp32-hal-i2c.c:354] i2cDumpInts(): Debug Buffer not Enabled
[I][esp32-hal-i2c.c:1138] i2cProcQueue(): Bus busy, reinit

[I][esp32-hal-i2c.c:1138] i2cProcQueue(): Bus busy, reinit
Guru Meditation Error: Core  1 panic'ed (IntegerDivideByZero). Exception was unhandled.
Core 1 register dump:
PC      : 0x4012e87b  PS      : 0x00060430  A0      : 0x8012ed7a  A1      : 0x3ffc85d0
A2      : 0x00000020  A3      : 0x00000000  A4      : 0x00000032  A5      : 0x3ffbdcec  
A6      : 0x60013000  A7      : 0x00004e20  A8      : 0x8012e871  A9      : 0x3ffc85b0
A10     : 0x00000000  A11     : 0x00000000  A12     : 0x3ffdd264  A13     : 0x3ffc2460  
A14     : 0x0000000c  A15     : 0x3ffbdcec  SAR     : 0x00000014  EXCCAUSE: 0x00000006
EXCVADDR: 0x00000000  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0x00000000  

ELF file SHA256: 0000000000000000

Backtrace: 0x4012e87b:0x3ffc85d0 0x4012ed77:0x3ffc8610 0x400e26d1:0x3ffc8630 0x400e2725:0x3ffc8650 0x400e2839:0x3ffc8670 0x4011c9f6:0x3ffc8690 0x4011cbe1:0x3ffc86c0 0x4011cc69:0x3ffc86e0 0x4011ceda:0x3ffc8700 0x401b1383:0x3ffc8730 0x40104062:0x3ffc8750 0x40189266:0x3ffc8770 0x4018915b:0x3ffc8790 0x40189175:0x3ffc87b0 0x400e6c57:0x3ffc87d0 0x400e06b5:0x3ffc87f0 0x400e24d5:0x3ffc8810 0x4012ffc5:0x3ffc8830 0x400918f6:0x3ffc8850
  #0  0x4012e87b:0x3ffc85d0 in i2cProcQueue at C:\users\jeroen\.platformio\packages\framework-arduinoespressif32\cores\esp32/esp32-hal-i2c.c:1277
  #1  0x4012ed77:0x3ffc8610 in i2cWrite at C:\users\jeroen\.platformio\packages\framework-arduinoespressif32\cores\esp32/esp32-hal-i2c.c:1629
  #2  0x400e26d1:0x3ffc8630 in TwoWire::writeTransmission(unsigned short, unsigned char*, unsigned short, bool) at C:/users/jeroen/.platformio/packages/framework-arduinoespressif32/libraries/Wire/src/Wire.cpp:379
  #3  0x400e2725:0x3ffc8650 in TwoWire::endTransmission(bool) at C:/users/jeroen/.platformio/packages/framework-arduinoespressif32/libraries/Wire/src/Wire.cpp:379    
  #4  0x400e2839:0x3ffc8670 in TwoWire::endTransmission() at C:/users/jeroen/.platformio/packages/framework-arduinoespressif32/libraries/Wire/src/Wire.cpp:379        
  #5  0x4011c9f6:0x3ffc8690 in Adafruit_BMP280::read24(unsigned char) at .pio/libdeps/debug/Sense_BMP280/src/Adafruit_BMP280.cpp:466
  #6  0x4011cbe1:0x3ffc86c0 in Adafruit_BMP280::readTemperature() at .pio/libdeps/debug/Sense_BMP280/src/Adafruit_BMP280.cpp:466
  #7  0x4011cc69:0x3ffc86e0 in Adafruit_BMP280::readPressure() at .pio/libdeps/debug/Sense_BMP280/src/Adafruit_BMP280.cpp:466
  #8  0x4011ceda:0x3ffc8700 in BMP280BarometerSensor::readRawValue() at c:\users\jeroen\.platformio\packages\toolchain-xtensa32\xtensa-esp32-elf\include\c++\5.2.0\bits/stl_tree.h:1633
  #9  0x401b1383:0x3ffc8730 in Sense::BaseNode<BarometerResult, 1u>::updateState(bool) at .pio/libdeps/debug/SenseFramework/src/BaseNode.h:55
  #10 0x40104062:0x3ffc8750 in Sense::TimedTaskList::execute(void*) at .pio/libdeps/debug/SenseFramework/src/SenseTimedTaskList.cpp:28
  #11 0x40189266:0x3ffc8770 in Event::update(unsigned long) at .pio/libdeps/debug/Sense_Timer/src/Event.cpp:40
  #12 0x4018915b:0x3ffc8790 in Timer::update(unsigned long) at .pio/libdeps/debug/Sense_Timer/src/Timer.cpp:127
  #13 0x40189175:0x3ffc87b0 in Timer::update() at .pio/libdeps/debug/Sense_Timer/src/Timer.cpp:127
  #14 0x400e6c57:0x3ffc87d0 in Sense::Base::loop() at .pio/libdeps/debug/SenseFramework/src/Base.cpp:158
  #15 0x400e06b5:0x3ffc87f0 in CSense::Main::loop() at .pio/libdeps/debug/SenseFramework/src/BaseNode.h:161
  #16 0x400e24d5:0x3ffc8810 in loop() at src/main.cpp:24
  #17 0x4012ffc5:0x3ffc8830 in loopTask(void*) at C:\users\jeroen\.platformio\packages\framework-arduinoespressif32\cores\esp32/main.cpp:23
  #18 0x400918f6:0x3ffc8850 in vPortTaskWrapper at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/port.c:355 (discriminator 1) 

[me-no-dev]

we have been looking onto ways to make this work for everyone, but unfortunately the Arduino API for I2C is really designed to never be used in multitasking environment. I would say, your best bet is to implement a semaphore yourself and use that to ensure that two tasks will not try to use I2C at the same time. Something like the code below would work:

xSemaphoreHandle wireSemaphore;

void readMPU(){
  xSemaphoreTake(wireSemaphore, portMAX_DELAY);
  Wire.beginTransaction(mpu_addr);
  .......
  Wire.endTransaction();
  Wire.readFrom(mpu_addr, 2);
  uint8_t x = Wire.read();
  uint8_t y = Wire.read();
  xSemaphoreGive(wireSemaphore);
}

void readBMP(){
  xSemaphoreTake(wireSemaphore, portMAX_DELAY);
  Wire.beginTransaction(bmp_addr);
  .......
  Wire.endTransaction();
  Wire.readFrom(bmp_addr, 2);
  uint8_t t = Wire.read();
  uint8_t p = Wire.read();
  xSemaphoreGive(wireSemaphore);
}

void setup(){
  wireSemaphore = xSemaphoreCreateMutex();
}

[I-Connect]

@me-no-dev pitty but clear answer, thx.
I can imagine a lot of work has gone into this...

We are already using the semaphore, but still getting the errors. I will triple check if I missed a wire call somewhere.

Out of curiosity/interest, why is the semaphore not implemented at the lower level in the API?

And before I redesign my pcb... ;-) is the SPI implementation thread safe?

[me-no-dev]

SPI is thread safe as long as you use transactions. The reason why Wire is not on it's own thread safe is because in the case of reading, you first read into a buffer and then you Wire.read() from that buffer. While we can take the semaphore in Wire.readFrom, it is not given that all bytes will be read to give back the semaphore when the buffer is empty. Also in cases of write->no stop->read, the whole thing needs to be executed at once by the peripheral, so if there is a chance that some other thread grabs the peripheral in between Wire.endTransaction() and Wire.readFrom(), result will be unknown for both threads.