ESP32-S3 Intermittent 30ms I2C Delay

[EricNRS]

I am seeing an I2C timeout when making a series of I2C requests to collect the voltage and current from INA237 current sensors.

Whenever the timeout occurs, it stalls the transfer for 29 to 30 milliseconds which is an issue with a 100ms update loop and around 24 I2C transactions during this time. The SDA line is high and the SCL line is low. I added a resistor between the ESP32-S3 and the INA237 it proved that the ESP32-S3 is holding the SCL line low.

I added debug messages to i2c_esp32_transmit, and the delay is when waiting for the ISR to give the cmd_sem.

zephyr/drivers/i2c/i2c_esp32.c

Line 325 in a6adaed

ret = k_sem_take(&data->cmd_sem, K_MSEC(I2C_TRANSFER_TIMEOUT_MSEC));

I added delay checks to i2c_esp32_isr for the calls to i2c_hal_master_handle_tx_event() and i2c_hal_master_handle_rx_event() and neither were the issue, so the problem seems to be a delay in the ESP32-S3 HAL in processing the event and calling the ISR.

zephyr/drivers/i2c/i2c_esp32.c

Line 670 in a6adaed

k_sem_give(&data->cmd_sem);

Key question is does the 30ms delay match anything in the HAL code? That might provide a clue as to where the issue is located. I have been unable to find it after spending several hours looking through the code.

[EricNRS]

@sylvioalves Could you please comment on this when you are back in the office on Monday?

Cheers,
Eric

[sylvioalves]

@EricNRS, can you repeat this test disabling usb console interface and use only uart port?

[EricNRS]

@sylvioalves Same problem with USB which was surprising since I have been having issues with USB dropping characters randomly in addition to the I2C failures, so I figured there could be an issue there. I also recently enabled Modbus and am experiencing timeout failures there as well even though it is only running at 9600 baud.

I will setup a fresh test app and start adding things in until it fails.

[EricNRS]

@sylvioalves Success! Thanks for your help with this!

I setup a semi-automated test to bisect the issue and finally narrowed it down to the tracing framework. The root cause is the RAM backend for the trace framework where tracing_backend_ram_output() is setup to stop logging when the trace buffer is full (see https://github.com/zephyrproject-rtos/zephyr/blob/main/subsys/tracing/tracing_backend_ram.c#L26-L29). I had some local modifications to clear the buffer and restart logging which took 30ms with a 1MB trace buffer. With CONFIG_TRACING_SYNC=y, it does the clearing after calling irq_lock(), so that explains the delay. This also explains why there was never any trace data covering the delay event when I looked at it. :-/

Disabling CONFIG_TRACING_SYNC=y has resolved the 30ms delays and I have had zero I2C and Modbus failures after several hours of testing.

I'll follow-up with the tracing framework team to see if there are some better options to having the RAM backend use a true circular buffer instead of just stopping when the buffer is full.

[EricNRS]

Disabling CONFIG_TRACING_SYNC=y has resolved the 30ms delays and I have had zero I2C (in addition to Modbus and USB) failures after an overnight test run.

[sylvioalves]

@EricNRS, Nice to hear that. I didn't see any mention before about CONFIG_TRACING_SYNC being enabled. I considered you were using some very basic sample without any additional features. That make sense now. Thanks for bringing all those information. This might be useful in future cases/references.

[EricNRS]

@sylvioalves Yes, sorry about that. I went the other way and disabled everything to create the equivalent to the blinky sample, but I left the TRACING framework on since I wanted to compare traces with the full system. Luckily the bisect test yesterday took the thinking out of it.