Espressif: 10ms gap between I2C transactions

[dhalbert]

CircuitPython 7.2.5: tested on FeatherS2 and Adafruit Feather ESP32-S2. Also true as far back as 6.3.0 (did not test further back).

Using the PCA9685 driver, there is at minimum an almost 10ms gap between any two I2C transactions. This causes stepper motor rotations to be very slow, etc. This slowness was first noticed by a user here: https://forums.adafruit.com/viewtopic.php?f=60&t=190046.

I see a similar 10ms gap in some case in the SHT4x library, so I think it is generic to I2C.

[KurtE]

Hi @dhalbert - you might want to also checkout the other IO timings. For example in the issue #6254 I did some testing on trying to get the uarts talking and having the RX data corrupted. I am noticing some good size timing gaps between operations:

The python code included:

        if uart1 == None:
            print("*** initialize the uarts ***")
            # we have not yet tried to iniatialize the uarts
            #uart1 = board.UART()
            #uart1.deinit()
            uart1 = busio.UART(board.TX, board.RX, baudrate=1000000)
            uart2 = busio.UART(board.IO17, board.IO16, baudrate=1000000)
        uart1.write(b'uart1')
        uart1.write(b'second part')
        toggle_pin.value = True
        uart2.write(b'uart2')
        toggle_pin.value = False

Note I had to remove the jumper between RX/TX otherwise it did not show anything...

But notice the gaps, I was hoping that the outputs to Uarts would happen concurrently, but it looks like the code does not return until after the write operation completes, Plus than a gap.

If the timings shown on right side of trace are not readable (P0=294.5us, P1 about 181 and P2 126.5)

[dhalbert]

@Neradoc noted in discord:

I was doing I2C tests using the MCP23017 on a feather ESP32S2, and the 10ms delay disappears if I change the bus speed from the default (code that takes 100 ms drops to ~6 ms like on the feather RP2040) - frequency=200_000 for example (edited)

[KurtE]

Will have to try that when I am doing I2C stuff!

But right now just curious about the basics, like:

       toggle_pin.value = True
        toggle_pin.value = False
        toggle_pin.value = True
        toggle_pin.value = False
        toggle_pin.value = True
        toggle_pin.value = False
        uart2.write(b'uart2')

The bottom red line is the toggle pin and the timings of highs and lows is very inconsistent.

Now back to playing

[Neradoc]

To illustrate what I mentioned on discord, here is a low level test code I've been running, with a couple different I2C devices. It does only 2 reads in this case, I've tried different combinations depending on what the devices support with the same results:

import board
import busio
import time

ADDRESS = 0x20
buffer = bytearray([0] * 10)
def measure_time(frequency = 100_000, nsamples = 10):
    print(f"Frequency @ {frequency:7d}", end="")
    with busio.I2C(scl=board.SCL, sda=board.SDA, frequency=frequency) as i2c:
        times = 0
        for i in range(nsamples):
            i2c.try_lock()
            t0 = time.monotonic_ns()
            i2c.readfrom_into(ADDRESS, buffer)
            i2c.readfrom_into(ADDRESS, buffer)
            # i2c.writeto(ADDRESS, buffer)
            # i2c.writeto_then_readfrom(ADDRESS, buffer, buffer)
            t1 = time.monotonic_ns()
            i2c.unlock()
            times += (t1 - t0)
        mean = times // nsamples // 1000 / 1000
        print(f" {mean:8.3f} ms")

import random
frequencies = [50_000, 80_000, 100_000, 110_000, 120_000, 200_000, 400_000]
# frequencies.sort(key=lambda x: random.random())
for freq in frequencies:
    measure_time(freq)

code.py output:
Frequency @   50000   19.583 ms
Frequency @   80000   19.641 ms
Frequency @  100000   19.641 ms
Frequency @  110000    2.005 ms
Frequency @  120000    1.870 ms
Frequency @  200000    1.193 ms
Frequency @  400000    0.686 ms

Adafruit CircuitPython 7.3.0-beta.1 on 2022-04-07; Adafruit Feather ESP32S2 with ESP32S2

[dhalbert]

Some more findings:

• For the PCA9685, raising the I2C frequency to 125 kHz causes the problem to go away. 110 kHz does not work for the PCA9685: I get errors which I think reflect data errors talking to the device. I tried various frequencies in between, and there are only small ranges that work.
• CONFIG_FREERTOS_HZ is the FreeRTOS tick rate, and the rate at which it can switch between tasks. In CircuitPython it is set to 100, which is a typical default. In MicroPython and Arduino, it is set to 1000. Arduino typically shows 1ms gaps at that rate, though sometimes they are shorter. I did not test MicroPython again to get the gap change. I tried changing the Arduino CONFIG_FREERTOS_HZ to 100, but couldn't get it to work: there are cached compilations which I tried to remove, but even after that I could not get a loaded program to run.

[ladyada]

what if you change it to like 500?

[dhalbert]

what if you change it to like 500?

The gap at 100 kHz bus frequency is the interval defined by CONFIG_FREERTOS_HZ, so 10ms at 100, 2ms at 500, 1ms at 1000. There is still some kind of bug/weirdness, because at, say 125 kHz bus frequency, the gap no longer is proportional to CONFIG_FREERTOS_HZ. For instance, at 125000, the gap reduces from 10ms to 600-700ish microseconds. So there is something unusual about the 100kHz rate compared to higher rates.

I wrote this observation up in https://github.com/espressif/esp-idf/issues/8770 as well.

[dhalbert]

I have reproduced this in a small ESP-IDF example. It is related to clock frequency, and can be ameliorated by a small delay in the ESP-IDF code at a crucial spot. https://github.com/espressif/esp-idf/issues/8770#issuecomment-1103416705 Awaiting further comments in the ESP-IDF issue.

[jepler]

should this really be closed, or should it wait for us to switch to this submodule & ref in main?

[dhalbert]

I did not mean to link the issue.