(Soft-)I2C instable clock on RPi4

[AndreasFuchsTPM]

Describe the bug

Because of #4884 I switched to soft-i2c. On RPi3 it works stable. On RPi4 the clock does not work consistently. Here is an Osci Trace of this behavior.

It seems like the low signal is not propagated immediately to the GPIO but only after the usleep right before the high signal.

This leads to the chip turning off or bitshift errors in this case. Here is what my logic analyzer shows, which is not high resolution enough to see the way-too-short low phases:

Steps to reproduce the behaviour

Talk to an I2C-TPM using the tpm-slb9273.dtbo for an extended amount of time.

I have only seen this on low-transitions. I assumed that the high-transitions (due to clock-stretching detection) do not have this problem. Thus, I assumed a racy behavior between the GPIO write and the usleep inside the driver.

Device (s)

Raspberry Pi 4 Mod. B

System

pi@piwithtpm:~ $ cat /etc/rpi-issue Raspberry Pi reference 2022-09-22 Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 005a8c73b05a2cab394073150208bf4f069e861a, stage2

pi@piwithtpm:~ $ vcgencmd version Mar 21 2023 17:18:16 Copyright (c) 2012 Broadcom version 3cc1c2dfc5460da9e1a0a4f48b48ab508c48bfe5 (clean) (release) (start)

Several kernel versions, 5.15, 6.0, 6.3, etc

Logs

No response

Additional context

I was able to mitigate this problem with the following patch that adds a double-check on the low-transition. I actually guess that additional time before usleep or the GPIO read actually are enough to reliably propagate the GPIO write to the pin.

I do not know if this qualifies as a fix/quirk. I guess a better in-depth analysis would be better.

From 7d9d6f6ef3730167d9cc0033aed2e828ea02b3f9 Mon Sep 17 00:00:00 2001
From: Andreas Fuchs <andreas.fuchs@infineon.com>
Date: Mon, 22 May 2023 10:30:31 +0200
Subject: [PATCH] I2C-GPIO: Remove CanSleep and Retry on clk-low

Given issues with shortened low-slopes on the i2c clk line,
this patch removes the allowance for sleep (i.e. issue a warning
to dmesg) and also double checks (and writes) the low-clk
signal.
For the high signal, this is done anyways already given the
clock stretching detection.

Signed-off-by: Andreas Fuchs <andreas.fuchs@infineon.com>
---
 drivers/i2c/busses/i2c-gpio.c | 17 +++++++++++++----
 1 file changed, 13 insertions(+), 4 deletions(-)

diff --git a/drivers/i2c/busses/i2c-gpio.c b/drivers/i2c/busses/i2c-gpio.c
index 0a2f02059416..a5ed2e028ee4 100644
--- a/drivers/i2c/busses/i2c-gpio.c
+++ b/drivers/i2c/busses/i2c-gpio.c
@@ -41,7 +41,7 @@ static void i2c_gpio_setsda_val(void *data, int state)
 {
    struct i2c_gpio_private_data *priv = data;

-   gpiod_set_value_cansleep(priv->sda, state);
+   gpiod_set_value(priv->sda, state);
 }

 /*
@@ -54,21 +54,30 @@ static void i2c_gpio_setscl_val(void *data, int state)
 {
    struct i2c_gpio_private_data *priv = data;

-   gpiod_set_value_cansleep(priv->scl, state);
+   gpiod_set_value(priv->scl, state);
+
+   /* Occasionally, the value is not immediately changed to the
+           low state, supposingly be a sleeping GPIO perifial.
+      Double-checking and double-writing for this case. */
+   if (state == 0) {
+       if (gpiod_get_value(priv->scl) != state) {
+           gpiod_set_value(priv->scl, state);
+       }
+   }
 }

 static int i2c_gpio_getsda(void *data)
 {
    struct i2c_gpio_private_data *priv = data;

-   return gpiod_get_value_cansleep(priv->sda);
+   return gpiod_get_value(priv->sda);
 }

 static int i2c_gpio_getscl(void *data)
 {
    struct i2c_gpio_private_data *priv = data;

-   return gpiod_get_value_cansleep(priv->scl);
+   return gpiod_get_value(priv->scl);
 }

 #ifdef CONFIG_I2C_GPIO_FAULT_INJECTOR
-- 
2.34.1

[pelwell]

1. Which GPIOs are you using for SCL and SDA?
2. Are you using any other GPIOs in your system? If yes, which, and how are they driven?

[AndreasFuchsTPM]

1. GPIOs 2 and 3 (here is the specific overlay: https://github.com/raspberrypi/linux/blob/rpi-6.0.y/arch/arm/boot/dts/overlays/tpm-slb9673-overlay.dts)
2. The only other thing would be the I2C-EEPROM for HAT data, but AFAIR also disabling this does not make a difference.

[pelwell]

Testing a Pi 4 with an RTC on a soft I2C on GPIOs 2 & 3 I'm not seeing any instability - it's rock solid in loop running "hwclock -r", which results in constant I2C traffic except for a 26ms gap every second. With a sleep inserted between invocations of hwclock there is a slight pause during the first write access - probably while the ARM increases its clock rate - but that's all.

One of the traces you posted looks like it came from a Saleae - can you upload a capture somewhere demonstrating the problem (ideally multiple times)? I'm suspicious that you might be seeing the effects of clock stretching.

You can also try locking the ARM clock by switching to performance governor:

echo performance | sudo tee /sys/devices/system/cpu/cpufreq/policy0/scaling_governor

[pelwell]

P.S. Are you certain that there is nothing accessing the GPIO controller hardware directly from user-space - something using the pigpio library, perhaps? There is no interlocking between that and the kernel driver, and it is easy for updates to get lost.

[AndreasFuchsTPM]

Thanks a lot for looking into this topic.

P.S. Are you certain that there is nothing accessing the GPIO controller hardware directly from user-space - something using the pigpio library, perhaps? There is no interlocking between that and the kernel driver, and it is easy for updates to get lost.

Yes, there is nothing from userspace accessing the GPIOs

Testing a Pi 4 with an RTC on a soft I2C on GPIOs 2 & 3 I'm not seeing any instability - it's rock solid in loop running "hwclock -r", which results in constant I2C traffic except for a 26ms gap every second. With a sleep inserted between invocations of hwclock there is a slight pause during the first write access - probably while the ARM increases its clock rate - but that's all.

Just a guess here, but I assume that transactions with the hwclock are pretty short, right ? In our usecase, we are writing 120something bytes at a time and about a few thousand of those in a row. So maybe the load profile is a bit different, because of the much longer (120 byte) transactions ? (Note: this load profile was the first time we noticed it; we had not seen it initially)

One of the traces you posted looks like it came from a Saleae - can you upload a capture somewhere demonstrating the problem (ideally multiple times)?

I'll post some more pictures here. The trace file is about 500MB, so no idea where to upload. Also I don't know the exact data over the bus and whether this could be shared.

I'm suspicious that you might be seeing the effects of clock stretching.

I do not think so, as clock stretching would happen on the low-signal, not on the high-signal, right ? Also, at least the rising edge seems to stem from the host, given it's curvature (see the zoomed in version). Falling edge is of course hard to tell. What makes me doubt it further is that the falling edge comes directly before the rising edge. But the device would have no way to figure out when the host will issue the next rise.

Here is a comparison of the signal comparison from the Pi (clock line on top) and the device (data line on bottom) to see the difference in rise characteristics. Fall looks similar though:

I have several more instances recorded. If you like, we could of course scroll over them in a WebEx meeting or such.

[pelwell]

The trace file is about 500MB, so no idea where to upload.

I hope it might compress reasonably, and you should be able to make a copy and trim it down somewhat, then put the result in Google Drive/Dropbox etc.

You're probably right about clock-stretching not being a factor, but humour me on the performance governor and give it a go.

[AndreasFuchsTPM]

I prepared an extract from a multi-minute trace.

I marked a few cases. The shortest is at Marker 12 with only 0.126 low-phase.

Overall 0.126 is the shortest we ever see. Low-Cycles below 0.200 occur about 20 times per second (at 400kHz constant use)

Saleae_Session2_Logic_CAP_Ausschnitt.zip

We will see the if performance governor will help. From memory it was not helping much.

[pelwell]

Thanks. Strangely, the Saleae software fails to see any start events in that trace before marker 12, i.e. only 4 bytes before the end.

[pelwell]

With such long transfers, I think you may have trimmed the trace after the most recent start condition. I don't care about the analogue voltages - they all look healthy - so delete those channels and send a decent sized chunk; you'll probably find it is much smaller.

[pelwell]

OK, I think I understand the situation. ARM processors are allowed to execute instructions out-of-order to quite a surprising degree, which for I/O can be problematic - hardware often expects operations to happen in a particular order. To solve this problem, the ARM architectures (like almost all these days) have a number of memory barrier operations that require the processor to have completed all preceding reads/writes/accesses/instructions before proceeding. While this forces reads to have occurred it only requires that the CPU has put the write on the bus - there is no result of a write that the CPU must wait for. If the I/O bus that write is aimed at is particularly busy you may find that it takes some time before the data reaches its target.

Looking at your modifications to the i2c-gpio driver I suspect there is only one that matters, and that's the read of the GPIO. Although the CPUs are allowed to reschedule the I/O accesses unless barriers are present, the bus fabrics are required to maintain the order (at least as far as the CPU can tell) otherwise execution becomes non-causal. Adding a read of a register (or any other register in the peripheral) after a write, with a scattering of memory barriers, flushes the write out to the peripheral before execution can proceed. The usual readl/writel functions include the necessary memory barriers, and there are implicit barriers in every synchronisation primitive (mutexes, sleeps, etc.), so all we need to do is force the additional read, which in this case is achieved just by inserting a gpiod_get_value after the gpiod_set_value. There is no need to check the result.

The _cansleep variants only make a difference in debug builds, and only force some checks that execution context is allowed to sleep if it needs to, i.e. it's not running in interrupt context or within a spinlock. It's important if the GPIO is (for example) at the other end of an I2C connection and the I2C driver has to sleep while waiting for interrupts, but not for the built-in GPIO interface which just performs a few simple I/O accesses.

Try undoing all of your changes and adding gpiod_get_value(priv->scl, state); after gpiod_set_value(priv->scl, state);. You could do the same for the sda writes as well.

[AndreasFuchsTPM]

Try undoing all of your changes and adding gpiod_get_value(priv->scl, state); after gpiod_set_value(priv->scl, state);. You could do the same for the sda writes as well.

Will do. But won't gcc optimize a get_value() away, if I do not use the result ? That was the reason I added this...

[pelwell]

But won't gcc optimize a get_value() away, if I do not use the result ?

No, it's not allowed to. The I/O locations are marked a volatile, meaning "can change at any moment, may have side effects - don't optimise, do what I say".

[vfazio]

Maybe a dumb question, but does the pinctrl-bcm2835 driver need to be updated to perform the read cycle instead of imposing it on the i2c-gpio software driver?

[pelwell]

But that will have the effect of introducing a stall at a point where in most cases there doesn't need to be one. Think of a driver that wants to set the state of 16 GPIOs. Without the barrier it can just fire them off, one after the other, without waiting for each to arrive. With a barrier in the pinctrl driver it will have to wait for each write (and barrier read) to complete before it can proceed to the next. I can imagine that it might end up taking longer to set one GPIO than it used to take to set all 16.

[vfazio]

I figured it was dumb and i shouldnt ask work related questions at 3am...

But for my own edification, without it, theres no guarantee the writes to set a pin low or high hit the bus? Im just trying to interpret what you were mentioning about how the read is required for the write to be flushed out. If its not done in pinctrl, then other drivers have to account for the behavior; so not just i2c-gpio but also spi-gpio or potentially the gpiod interface in general?

Not saying its related, but it reminded me of some of the fixes that have landed in openocd where delays and memory barriers have been introduced to try to resolve values not being driven as expected. https://github.com/raspberrypi/openocd/commit/ee87f2b4a9cac084903087aed6ff8e3a691c674b

[pelwell]

The flushing is about timing, not about whether the writes actually occur. The patch you link to (by my colleague) is related, but the kernel I/O primitives (readl and writel) already include memory barriers to keep things vaguely sane. There are _raw alternatives that lack the barriers, but they must be used with extreme care.