Surprising I2C `TimeOut` [ESP32-C3]

lure23 commented 2 weeks ago

Reporting this so we can argue whether it's intended behaviour or not.

I'm taking my first steps with ESP32-C3 and I2C. Here's a log:

[TRACE] Writing: 0x7fff <- 1 bytes
[TRACE] I2C written: 0x7fff <- [0x09]
[TRACE] Writing: 0x0000 <- 252 bytes
[TRACE] I2C written: 0x0000 <- [0xe0, 0x00, 0x03, ...]
[TRACE] Writing: 0x00fc <- 252 bytes
[ERROR] I2C write failed: TimeOut

Here, I'm starting to loop each max. slice (that fits into the I2C FIFO) of a larger (32k) slice. I am somewhat surprised to receive a timeout, since the I2C is created with:

    let i2c = I2C::new(
        peripherals.I2C0,
        io.pins.gpio4,  // SDA
        io.pins.gpio5,  // SCL
        400.kHz(),
        &clocks,
        None
    );

There is the new_with_timeout variant that I'll be soon trying out. Here comes my first question:

Should ::new mean that there are no timeouts? I would expect either that, or a "default" timeout, but the documentation is really scarce on i2c.

Question #2

What is the unit of timeout parameter here: https://github.com/esp-rs/esp-hal/blob/main/esp-hal/src/i2c.rs#L380

I'm kind of fine looking at these things within the esp-hal repo (have it checked out, locally), but this is going elsewhere, without a hint of information what the u32 is. Likely, it'll be milliseconds? But what if I want to not have timeouts? Can I use 0?
A: 0 times out immediately. 10 gives the default (same as with ::new) behaviour, 100 and 1000 panic with:
```
[ERROR] "panicked at /home/ubuntu/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp-hal-0.19.0/src/i2c.rs:1422:57:\ncalled `Result::unwrap()` on an `Err` value: TryFromIntError(())"
```

Question #3

I noticed, going through the code that internal SDA & SCL pull-ups are enabled for the bus. I have external ones - how should I not have them within the chip?

The documentation states:

"[...] the usual setting such as frequency, timeout, and SDA/SCL pins can easily be configured."

I hope it's that way. Only, I don't know where to look for how easy it would be. Let's fix this!

Edit:

When coming to the TimeOut, the bus has already taken care of 30..40 1-byte reads and writes. It is the cumulative size of transferred data that seems to trigger the timeout. If I vary the size of the written chunks (tried 254, 100 and 50), I get more chunks through, but roughly the same overall data (400..500 bytes).

This is weird. I would expect a timeout to apply separately for each I2C transaction.

Same behaviour with both 100kHz and 400kHz bus speeds.

Versions:

esp-hal 0.19.0 with features "defmt", "esp32c3", "embedded-hal"

lure23 commented 2 weeks ago

The repo is here. See vl53l5cx_uld/WIRING.md for how to wire (SDA, SCL, PWR_EN). Since you will need the particular device boards, I'm not really expecting people to be able to replicate this, easily.

I will next:

try injecting delays between longer writes

No effect.
steer I2C_RST as part of the board setup, after it's been powered on
🤞 🙂

lure23 commented 2 weeks ago

Tried with @liebman 's PR. While it's undoubtably good for other purposes, it does not change the timeout behaviour I'm observing. Thus, I hope it's not used to "close this issue".

bjoernQ commented 2 weeks ago

I happen to own such a sensor but I'm unable to get your code to build (I already spent a bit too much time on that).

However, I started an attempt to port the C driver to Rust some time ago (never finished that - but at least it downloads the FW to the sensor and can read the device-id etc.) and I don't run into those timeouts

Have you tried your setup with known working code (e.g. Arduino, MicroPython or ESP-IDF code)? Just to rule out any HW problems

lure23 commented 2 weeks ago

@bjoernQ This is nice to hear!

Have you tried your setup with known working code (e.g. Arduino, MicroPython or ESP-IDF code)? Just to rule out any HW problems

I haven't. The reason is a bit like your "already spent a bit too much". I don't have interest in C or ESP-IDF but you are right. That can be one way further.

I offer to help you get the code compiling, and obviously I'd be interested to learn about your C/Rust attempt.

Until then, I plan to check this out on an ESP32-C6. Which MCU did you use?

What kind of resetting do you do in your setup?
Is your SATEL PCB revision "PCB4109A" (printed on the down side of the PCB)?

bjoernQ commented 2 weeks ago

I tried on C3 and C6

I also verified things with this C code: https://github.com/RJRP44/VL53L5CX-Library (just had to increase the stack size, change the I2C port to 0 and just in case I lowered the frequency to 100kHz for the example to work)

What kind of resetting do you do in your setup?

I just power-on the thing - my breakout board doesn't even have a reset pin. It's some generic thing from AliExpress not made by ST

lure23 commented 2 weeks ago

This just came in: #2045

He's done a bit more digging but it's certainly the same issue.

the number is limited to 8 bits value, but not verified in the code

This explains why in my tests I got panics with 1000.

The new issue is clearer and deeper, in my opinion than this one. I'm fine closing this in favor of it. In the mean time,

I moved to C6 (ESP32-C6-DevKitM-01) and am not receiving the TimeOut.

Same wiring.

yanshay commented 2 weeks ago

The below tables are from the ESP32 Technical Reference Manual:

It looks like ESP32 timeout is 20 bits, not 8bit, but at one point I received an error when trying to change the hal code, to avoid the panic (removed the into().unwrap()), stating that I'm trying to put u32 where u8 is expected. Maybe that has to do with why timeout doesn't behave as expected, maybe not all bits are set properly? That's beyond my level of understanding though.
It is timeout in ABP Clock. I would guess (but that's really a guess) that it would usually be the CPU_Clock as ususually configured at program start.

liebman commented 2 weeks ago

Any chance you have access to a logic analyzer or a scope where you can capture the end of the transaction?

lure23 commented 2 weeks ago

Seems I cannot repeat this problem any more.

I had moved to using ESP32-C6-DevKitM-01, developed further, and something must have fixed it also for ESP32-C3-DevKitC-02. Tried a bit to tease it back, but didn't succeed.

Any chance you have access to a logic analyzer or a scope where you can capture the end of the transaction?

I would, once a week at a hacklab, but since things now work it's pointless for me.

@yanshay You still have the problem?

~~I am ready to close the issue.~~

lure23 commented 3 days ago

I started seeing this again.

Steps to reproduce

clone https://github.com/lure23/VL53L5CX_rust
git checkout 72a8b3995343528ba2b2b0e81b48cd3dd8c01c12
set up according to the docs
- you don't need to use Multipass VMs, it's just my way to keep the toolchains reproducible; Debian/Ubuntu will do

$ DEFMT_LOG=trace make z
EXAMPLE=multiboard \
  FEATURES= \
  make --no-print-directory _build _run
DEFMT_LOG=trace cargo build --timings --release --features=,defmt --example multiboard
   Compiling defmt-macros v0.3.9
   Compiling vl53l5cx_uld v0.0.0 (/home/ubuntu/VL53L5CX_rs.cifs/vl53l5cx_uld)
   Compiling defmt v0.3.8
   Compiling embedded-hal v1.0.0
   Compiling esp32c3 v0.25.0
   Compiling riscv v0.11.1
   Compiling embedded-hal-nb v1.0.0
   Compiling embedded-io v0.6.1
   Compiling esp-riscv-rt v0.9.0
   Compiling fugit v0.3.7
   Compiling esp-backtrace v0.14.1
   Compiling defmt-rtt v0.4.1
   Compiling esp-hal v0.20.1
[...]
      Erasing ✔ [00:00:02] [########################] 256.00 KiB/256.00 KiB @ 105.48 KiB/s (eta 0s )
  Programming ✔ [00:00:35] [##########################] 103.59 KiB/103.59 KiB @ 2.94 KiB/s (eta 0s )
    Finished in 35.249584s
0.808223 [INFO ] Target powered off and on again.
0.808274 [INFO ] Selecting board 0
0.808608 [TRACE] I2C written: 0x7fff <- [0x00]
0.810902 [TRACE] I2C read: 0x0000 -> [0xf0, 0x02]
0.811061 [TRACE] I2C written: 0x7fff <- [0x02]
0.812110 [DEBUG] Ping succeeded: 0xf0,0x02
0.812286 [TRACE] I2C written: 0x7fff <- [0x00]
0.813436 [TRACE] I2C written: 0x0009 <- [0x04]
0.814582 [TRACE] I2C written: 0x000f <- [0x40]
0.815728 [TRACE] I2C written: 0x000a <- [0x03]
0.817906 [TRACE] I2C read: 0x7fff -> [0x00]
0.818053 [TRACE] I2C written: 0x000c <- [0x01]
0.819201 [TRACE] I2C written: 0x0101 <- [0x00]
0.820348 [TRACE] I2C written: 0x0102 <- [0x00]
0.821495 [TRACE] I2C written: 0x010a <- [0x01]
0.822643 [TRACE] I2C written: 0x4002 <- [0x01]
0.823790 [TRACE] I2C written: 0x4002 <- [0x00]
0.824934 [TRACE] I2C written: 0x010a <- [0x03]
0.826084 [TRACE] I2C written: 0x0103 <- [0x01]
0.827233 [TRACE] I2C written: 0x000c <- [0x00]
0.828377 [TRACE] I2C written: 0x000f <- [0x43]
0.829430 [TRACE] 🔸 1ms
0.830575 [TRACE] I2C written: 0x000f <- [0x40]
0.831720 [TRACE] I2C written: 0x000a <- [0x01]
0.832761 [TRACE] 🔸 100ms
1.085132 [TRACE] I2C written: 0x7fff <- [0x00]
1.106619 [TRACE] I2C read: 0x0006 -> [0x01]
1.106664 [TRACE] 🔸 10ms
1.116832 [TRACE] I2C written: 0x000e <- [0x01]
1.134966 [TRACE] I2C written: 0x7fff <- [0x02]
1.136119 [TRACE] I2C written: 0x0003 <- [0x0d]
1.137269 [TRACE] I2C written: 0x7fff <- [0x01]
1.139453 [TRACE] I2C read: 0x0021 -> [0x10]
1.139495 [TRACE] 🔸 10ms
1.167184 [TRACE] I2C written: 0x7fff <- [0x00]
1.169366 [TRACE] I2C read: 0x7fff -> [0x00]
1.169515 [TRACE] I2C written: 0x000c <- [0x01]
1.170665 [TRACE] I2C written: 0x7fff <- [0x00]
1.171814 [TRACE] I2C written: 0x0101 <- [0x00]
1.319349 [TRACE] I2C written: 0x0102 <- [0x00]
1.320497 [TRACE] I2C written: 0x010a <- [0x01]
1.321650 [TRACE] I2C written: 0x4002 <- [0x01]
1.322803 [TRACE] I2C written: 0x4002 <- [0x00]
1.323955 [TRACE] I2C written: 0x010a <- [0x03]
1.325107 [TRACE] I2C written: 0x0103 <- [0x01]
1.326259 [TRACE] I2C written: 0x400f <- [0x00]
1.327409 [TRACE] I2C written: 0x021a <- [0x43]
1.328560 [TRACE] I2C written: 0x021a <- [0x03]
1.346836 [TRACE] I2C written: 0x021a <- [0x01]
1.347986 [TRACE] I2C written: 0x021a <- [0x00]
1.349135 [TRACE] I2C written: 0x0219 <- [0x00]
1.350283 [TRACE] I2C written: 0x021b <- [0x00]
1.351433 [TRACE] I2C written: 0x7fff <- [0x00]
1.353614 [TRACE] I2C read: 0x7fff -> [0x00]
1.353763 [TRACE] I2C written: 0x000c <- [0x00]
1.354910 [TRACE] I2C written: 0x7fff <- [0x01]
1.356061 [TRACE] I2C written: 0x0020 <- [0x07]
1.357210 [TRACE] I2C written: 0x0020 <- [0x06]
1.358358 [TRACE] I2C written: 0x7fff <- [0x09]
1.365204 [TRACE] I2C written: 0x0000 <- [0xe0, 0x00, 0x03, 0x08, 0xe0, 0x00, 0x0a, 0xc8, 0xe0, 0x00, 0x05, 0x08, 0xe0, 0x64, 0x08, 0x48, 0xe0, 0x00, 0x0a, 0x88]... (252 bytes)
1.390391 [ERROR] I2C write to 0x00fc (252 bytes) failed: TimeOut
1.390465 [ERROR] I2C write to 0x7fff (1 bytes) failed: ExecIncomplete
1.390586 [ERROR] I2C write to 0x0000 (252 bytes) failed: AckCheckFailed
1.390659 [ERROR] I2C write to 0x7fff (1 bytes) failed: AckCheckFailed
1.390788 [ERROR] I2C write to 0x0000 (252 bytes) failed: AckCheckFailed
1.390861 [ERROR] I2C write to 0x7fff (1 bytes) failed: AckCheckFailed

The first block of 252 bytes (+ 2 for an index) = 254 writes well.

The second one gets the TimeOut.

I'll be moving to ESP32-C6 (which fixed the situation last time; for an unknown change that happened). Just reporting this since... still happening.

Also ESP32-C3 in this case (as was last time). esp-hal 0.20.1

lure23 commented 3 days ago

As before, ESP32-C6 does not suffer from this (same code works there).

MabezDev commented 1 hour ago

There have been two I2C related bugfix PRs since 0.20.1 - could you try the main branch and see if it makes a difference?

esp-rs / esp-hal

Surprising I2C `TimeOut` [ESP32-C3] #2026

Steps to reproduce