HID: ft260: fix wake up device from power saving mode

[enrikb]

During testing from within a KVM based virtual machine, it was found that the wakeup implementation was not working in all cases.

By moving the extra ft260_xfer_status() to ft260_hid_output_report_check_status(), it can be placed after sending the output report. This change seems to fix the issue or at least to be more stable. No more bogus responses after power save have been noticed during my tests, both on real hardware and through the VM.

I tested both with debug messages enabled and disabled.

If this is still not enough for other hardware / timing constellations, adding a small additional delay for the wake-up case should be considered.

Signed-off-by: Enrik Berkhan Enrik.Berkhan@inka.de

[MichaelZaidman]

Hi @enrikb,

I cannot reproduce the issue in my VM (Virtual box Version 6.1.32, Ubuntu 22.04.1 LTS, kernel 5.15.0-52)

michael@michael-VirtualBox:~/sw/hid-ft260$ sudo i2cset -y 1 0x8 1 1
Error: Write failed
michael@michael-VirtualBox:~/sw/hid-ft260$ sudo i2cset -y 1 0x8 1 1
Error: Write failed

[Nov 1 11:17] ft260_smbus_xfer: smbus size 2
[  +0.025891] ft260_xfer_status: bus_status 0x20, clock 100
[  +0.000005] ft260_smbus_write: device wakeup
[  +0.000001] ft260_smbus_write: rep 0xd1 addr 0x8 cmd 0x1 datlen 2 replen 6
[  +0.010851] ft260_xfer_status: bus_status 0x2e, clock 100
[  +0.000012] ft260 0003:0403:6030.0002: i2c bus error: 0x2e
[  +0.006429] ft260_i2c_reset: done
[  +6.123998] ft260_smbus_xfer: smbus size 2
[  +0.012182] ft260_xfer_status: bus_status 0x20, clock 100
[  +0.000005] ft260_smbus_write: device wakeup
[  +0.000002] ft260_smbus_write: rep 0xd1 addr 0x8 cmd 0x1 datlen 2 replen 6
[  +0.009987] ft260_xfer_status: bus_status 0x2e, clock 100
[  +0.000007] ft260 0003:0403:6030.0002: i2c bus error: 0x2e
[  +0.007225] ft260_i2c_reset: done

Can you add the issued commands and logs?

Thanks, Michael

[enrikb]

Hi @MichaelZaidman, just managed to reproduce the issue using i2cset:

debian@debian:~/src/hid-ft260$ sudo i2cset -y 1 0x8 0x55
Error: Write failed
debian@debian:~/src/hid-ft260$ sudo i2cset -y 1 0x8 0x55
debian@debian:~/src/hid-ft260$

[Nov 1 13:02] ft260_smbus_xfer: smbus size 1
[  +0,016738] ft260_xfer_status: bus_status 0x20, clock 100
[  +0,002957] ft260_smbus_write: device wakeup
[  +0,000008] ft260_smbus_write: rep 0xd1 addr 0x8 cmd 0x55 datlen 1 replen 5
[  +0,011168] ft260_xfer_status: bus_status 0x2e, clock 100
[  +0,002934] ft260 0003:0403:6030.0002: i2c bus error: 0x2e
[  +0,007591] ft260_i2c_reset: done
[  +8,461596] ft260_smbus_xfer: smbus size 1
[  +0,012298] ft260_xfer_status: bus_status 0x20, clock 100
[  +0,001078] ft260_smbus_write: device wakeup
[  +0,000002] ft260_smbus_write: rep 0xd1 addr 0x8 cmd 0x55 datlen 1 replen 5
[  +0,004820] ft260_xfer_status: bus_status 0x20, clock 100

To get more insight, I hooked a scope to the bus. The signal has no issues. What is interesting: the FT260 blindly sends all the bytes requested even though no single ACK can be seen. (Of course, it is expected in this case that no ACK can be seen, there is still no device at 0x8. But is it normal that the I2C controller keeps on transmitting after a NACK?)

Anyway, the FT260 behavior of sending all data in spite of NACKs could explain different timing depending on the amount of data written.

After applying the change in this PR, I can easily run a test loop like this:

debian@debian:~/src/hid-ft260$  n=0; while [[ $n -lt 100 ]] ; do sudo i2cset -y 1 0x8 0x55 && break; let ++n; sleep 6 ; done ; echo "runs: $n result $?"
runs: 100 result 0

Without the change, the same tests usually fails after just a few rounds (single digit number). You may have noticed that I'm only writing a single byte in the i2cset command. However, this test loop also fails quickly when using two bytes.

[MichaelZaidman]

Hi @enrikb,

Thanks for the details.

I run the 100 iterations loop on HW and VM setups with the UMFT260EV1A evaluation module. Strange, but I cannot reproduce the issue you reported. The test timing on my VM resembles yours, but the test always succeeds.

michael@michael-VirtualBox:~/sw/hid-ft260$ n=0; while [[ $n -lt 100 ]] ; do sudo i2cset -y 1 0x8 0x55 && break; let ++n; sleep 6 ; done ; echo "runs: $n result $?"
Error: Write failed
Error: Write failed
[...]
Error: Write failed
Error: Write failed
Error: Write failed
runs: 100 result 0

  +0.000005] ft260 0003:0403:6030.0005: uart interface is not supported
[ +34.405501] ft260_smbus_xfer: smbus size 1
[  +0.013794] ft260_xfer_status: bus_status 0x20, clock 100
[  +0.000009] ft260_smbus_write: device wakeup
[  +0.000002] ft260_smbus_write: rep 0xd1 addr 0x8 cmd 0x55 datlen 1 replen 5
[  +0.008254] ft260_xfer_status: bus_status 0x2e, clock 100
[  +0.000011] ft260 0003:0403:6030.0004: i2c bus error: 0x2e
[  +0.007607] ft260_i2c_reset: done
[  +6.030081] ft260_smbus_xfer: smbus size 1
[  +0.018770] ft260_xfer_status: bus_status 0x20, clock 100
[  +0.000006] ft260_smbus_write: device wakeup
[  +0.000002] ft260_smbus_write: rep 0xd1 addr 0x8 cmd 0x55 datlen 1 replen 5
[  +0.009761] ft260_xfer_status: bus_status 0x2e, clock 100
[  +0.000008] ft260 0003:0403:6030.0004: i2c bus error: 0x2e
[  +0.006888] ft260_i2c_reset: done
[Nov 1 17:01] ft260_smbus_xfer: smbus size 1
[  +0.019014] ft260_xfer_status: bus_status 0x20, clock 100
[  +0.000006] ft260_smbus_write: device wakeup
[  +0.000001] ft260_smbus_write: rep 0xd1 addr 0x8 cmd 0x55 datlen 1 replen 5
[  +0.009501] ft260_xfer_status: bus_status 0x2e, clock 100
[  +0.000006] ft260 0003:0403:6030.0004: i2c bus error: 0x2e
[  +0.006579] ft260_i2c_reset: done
[  +6.030850] ft260_smbus_xfer: smbus size 1
[  +0.021210] ft260_xfer_status: bus_status 0x20, clock 100
[  +0.000006] ft260_smbus_write: device wakeup
[  +0.000001] ft260_smbus_write: rep 0xd1 addr 0x8 cmd 0x55 datlen 1 replen 5
[  +0.009712] ft260_xfer_status: bus_status 0x2e, clock 100
[  +0.000008] ft260 0003:0403:6030.0004: i2c bus error: 0x2e
[  +0.005630] ft260_i2c_reset: done

To get more insight, I hooked a scope to the bus. The signal has no issues. What is interesting: the FT260 blindly sends all the bytes requested even though no single ACK can be seen. (Of course, it is expected in this case that no ACK can be seen, there is still no device at 0x8. But is it normal that the I2C controller keeps on transmitting after a NACK?)

Generally, the i2c slave device is allowed not to acknowledge the address byte. In contrast, for the SMBus, it is the requirement. Since the ft260 is an i2c bus controller, it is less restrictive with this. I have no scope at the moment to try to reproduce the experiment, but from the log you shared, I see that you sent one data byte only. So should we expect the controller to report NACK on this byte only? Does it make sense?

Initially, I rejected the FTDI's suggestion of querying the status twice in the ft260_xfer_status() due to the expected performance penalty. "The workaround of querying the status twice will work, but it may degrade the performance since every status query takes 200us on average", was my response. But we can improve it in the way shown below. Since _need_wakeupat is accessed in an atomic way, it is safe to access it from different execution contexts. The rationale for doing it this way is to minimize the overhead associated with the extra ft260_xfer_status call and make it more generic by covering all xfer cases. What do you think?

diff --git a/hid-ft260.c b/hid-ft260.c
index da8ea0d..70e44ab 100644
--- a/hid-ft260.c
+++ b/hid-ft260.c
@@ -309,6 +309,12 @@ static int ft260_xfer_status(struct ft260_device *dev, u8 bus_busy)
    struct ft260_get_i2c_status_report report;
    int ret;

+   if (time_is_before_jiffies(dev->need_wakeup_at)) {
+       ret = ft260_hid_feature_report_get(hdev, FT260_I2C_STATUS,
+                       (u8 *)&report, sizeof(report));
+       ft260_dbg("device wakeup");
+   }
+
    ret = ft260_hid_feature_report_get(hdev, FT260_I2C_STATUS,
                       (u8 *)&report, sizeof(report));
    if (unlikely(ret < 0)) {
@@ -411,11 +417,6 @@ static int ft260_i2c_write(struct ft260_device *dev, u8 addr, u8 *data,
    if (len < 1)
        return -EINVAL;

-   if (time_is_before_jiffies(dev->need_wakeup_at)) {
-       (void)ft260_xfer_status(dev, 0);
-       ft260_dbg("device wakeup");
-   }
-
    rep->flag = FT260_FLAG_START;

    do {
@@ -465,11 +466,6 @@ static int ft260_smbus_write(struct ft260_device *dev, u8 addr, u8 cmd,
    if (data_len >= sizeof(rep->data))
        return -EINVAL;

-   if (time_is_before_jiffies(dev->need_wakeup_at)) {
-       (void)ft260_xfer_status(dev, 0);
-       ft260_dbg("device wakeup");
-   }
-
    rep->address = addr;
    rep->data[0] = cmd;
    rep->length = data_len + 1;

[enrikb]

Hi @MichaelZaidman, Yes, moving the 'wakeup' to ft260_xfer_status() makes sense. A quick test here shows no issues.

[enrikb]

JFTR, I have dumped a few waveforms from the scope:

Write to non-existing device: i2c_set ... 0x08 0x55 0xaa 0x55 0xaa

Even though no single ACK can be seen, the FT260 continues writing all bytes. The protocol decoder shows '?' for the missing ACK (i.e. NACK).

detail of the above clearly showing NACKs both on address and first byte

To confirm plausible test setup, write address 0 to the EEPROM on the FTDI eval board: i2c_set ... 0x50 0x0.

The ACKs from the EEPROM are clearly visible due to slightly different level. No more '?' from the protocol decoder.

[enrikb]

I changed the PR following your suggestion.

[MichaelZaidman]

Hi @enrikb,

Thanks for the wave forms.

Write to non-existing device: i2c_set ... 0x08 0x55 0xaa 0x55 0xaa Even though no single ACK can be seen, the FT260 continues writing all bytes. The protocol decoder shows '?' for the missing ACK (i.e. NACK). ...clearly showing NACKs both on address and first byte...

I can explain the ? sign after the address byte shown by the protocol analyzer with the analyzer's ability to decode both i2c and SMBus protocols. The SMBus spec emphasizes the differences between I2C and SMBus in the B.3: The I2C specification does not require that a device always acknowledge its address. This can confuse a system controller. If a device does not acknowledge its address how does the system controller know if it is because the device is busy, has failed, or has been removed?. And, the I2C spec 2.1 in 7.2 says: When a slave doesn’t acknowledge the slave address (for example, it’s unable to receive or transmit because it’s performing some real-time function), the data line must be left HIGH by the slave.

Regarding the rest of the bytes, the I2C spec says: Usually, a receiver which has been addressed is obliged to generate an acknowledge after each byte has been received. I will check it with FTDI and update you.

Thanks, Michael

[enrikb]

Hi @MichaelZaidman, thanks for the pointers to the specs, which I haven't read for a while to be honest ... Even though the I2C spec allows a slave device, that is actually present to not acknowledge the address in case it's e.g. not ready, it also says that in this case the master can either generate a STOP to abort or a REPEATED START to start a new transaction. It looks as if the FT260 does neither, right? It just continues to clock out the 0x55 after W:08 in the example above. I don't think this does any harm or is in any way related to the root cause of the issue we're observing here. It's just a waste of time on the bus ...

[MichaelZaidman]

Hi @enrikb,

Even though the I2C spec allows a slave device, that is actually present to not acknowledge the address in case it's e.g. not ready, it also says that in this case the master can either generate a STOP to abort or a REPEATED START to start a new transaction.

No, it is correct when "If a slave-receiver does acknowledge the slave address", but in our case, there is no device at the slave address. The controller cannot know it since, according to the spec, the data line should be left in HIGH, which is also valid for ghost devices.

The related quotes from I2C spec:

"When a slave doesn’t acknowledge the slave address (for example, it’s unable to receive or transmit because it’s performing some real-time function), the data line must be left HIGH by the slave".

"If a slave-receiver does acknowledge the slave address but, some time later in the transfer cannot receive any more data bytes, the master must again abort the transfer. This is indicated by the slave generating the not-acknowledge on the first byte to follow. The slave leaves the data line HIGH and the master generates a STOP or a repeated START condition."

To summarize:

1. It's OK not to respond with NACK status for a ghost device address, since NACK is communicated as HIGH on the data line, which is the default data line state.
2. It seems like the I2C spec does not define the controller behavior when it writes a sequence of bytes to the ghost device.

[enrikb]

"The slave leaves the data line HIGH and the master generates a STOP or a repeated START condition."

Yes, exactly. And the FT260, as far as I can see, continues to send data before generating a STOP or repeated START.

[MichaelZaidman]

"The slave leaves the data line HIGH and the master generates a STOP or a repeated START condition."

Perhaps, I was not clear. It is for the REAL devices that acknowledged the address first. It is not for the GHOST devices, as in our case.

[MichaelZaidman]

Hi @enrikb,

I changed the PR following your suggestion.

Thanks for this. I did more testing. It works. We can see multiple wake-up messages during the first write into EEPROM since the status is polled in the loop before the need_wakeup_at get updated. It causes up to 200us penalty on the first write, but I think we can cope with it.

sudo ./i2cperf -f 2 -o 2 -s 16 -r 0-0xff 13 0x51 -S

[Nov 1 21:26] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.004575] ft260_xfer_status: bus_status 0x20, wakeup
[  +0.000235] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000144] ft260_xfer_status: bus_status 0x40, wakeup
[  +0.000192] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000228] ft260_xfer_status: bus_status 0x41, wakeup
[  +0.000182] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000181] ft260_xfer_status: bus_status 0x41, wakeup
[  +0.000228] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000183] ft260_xfer_status: bus_status 0x40, wakeup
[  +0.000181] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000226] ft260_xfer_status: bus_status 0x41, wakeup
[  +0.000140] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000214] ft260_xfer_status: bus_status 0x20, wakeup           
[  +0.000170] ft260_xfer_status: bus_status 0x20, clock 100     <-- Penalty. The status was ready at one iteration earlier.
[  +0.011534] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001193] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000172] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000217] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000180] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000174] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000172] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000179] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000215] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000182] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000173] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000203] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000223] ft260_xfer_status: bus_status 0x20, clock 100
[  +0.012565] ft260_i2c_write: rep 0xd4 addr 0x51 off 0 len 18 wlen 18 flag 0x6 d[0] 0x0
[  +0.001403] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000198] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000201] ft260_xfer_status: bus_status 0x41, clock 100
[  +0.000147] ft260_xfer_status: bus_status 0x40, clock 100
[  +0.000203] ft260_xfer_status: bus_status 0x41, clock 100

I suggest replacing the

+       ft260_dbg("device wakeup");

with

+       ft260_dbg("bus_status %#02x, wakeup\n", report.bus_status);

So the log will look like this

[Nov 1 21:12] ft260_smbus_xfer: smbus size 1
[  +0.000004] ft260_smbus_write: rep 0xd1 addr 0x8 cmd 0x0 datlen 1 replen 5
[  +0.004436] ft260_xfer_status: bus_status 0x20, wakeup
[  +0.000221] ft260_xfer_status: bus_status 0x47, clock 100
[  +0.000169] ft260_xfer_status: bus_status 0x2e, wakeup
[  +0.000241] ft260_xfer_status: bus_status 0x2e, clock 100
[  +0.000003] ft260 0003:0403:6030.0006: i2c bus error: 0x2e

Thanks, Michael

[enrikb]

Hi @MichaelZaidman,

log message changed in the latest force push (the one before only rebases to the updated main). I'm also checking the return code of the 'wakeup' status request now as the result will be used in the log.

This way, the log also nicely confirms (again) the bogus first status, as can be seen in your dump.

[MichaelZaidman]

Hi @enrikb,

I fixed the check patch warnings and modified the code by gathering the wake-up handling in a single place. It implies an extra status query every 5 seconds during the I2C traffic but removes jiffies calculation per I2C transfer request.

What do you think?

diff --git a/hid-ft260.c b/hid-ft260.c
index da8ea0d..d5b092b 100644
--- a/hid-ft260.c
+++ b/hid-ft260.c
@@ -309,6 +309,20 @@ static int ft260_xfer_status(struct ft260_device *dev, u8 bus_busy)
    struct ft260_get_i2c_status_report report;
    int ret;

+   if (time_is_before_jiffies(dev->need_wakeup_at)) {
+       ret = ft260_hid_feature_report_get(hdev, FT260_I2C_STATUS,
+                       (u8 *)&report, sizeof(report));
+       if (unlikely(ret < 0)) {
+           hid_err(hdev, "failed to retrieve status: %d, no wakeup\n",
+               ret);
+       } else {
+           dev->need_wakeup_at = jiffies +
+               msecs_to_jiffies(FT260_WAKEUP_NEEDED_AFTER_MS);
+           ft260_dbg("bus_status %#02x, wakeup\n",
+                 report.bus_status);
+       }
+   }
+
    ret = ft260_hid_feature_report_get(hdev, FT260_I2C_STATUS,
                       (u8 *)&report, sizeof(report));
    if (unlikely(ret < 0)) {
@@ -411,11 +425,6 @@ static int ft260_i2c_write(struct ft260_device *dev, u8 addr, u8 *data,
    if (len < 1)
        return -EINVAL;

-   if (time_is_before_jiffies(dev->need_wakeup_at)) {
-       (void)ft260_xfer_status(dev, 0);
-       ft260_dbg("device wakeup");
-   }
-
    rep->flag = FT260_FLAG_START;

    do {
@@ -465,11 +474,6 @@ static int ft260_smbus_write(struct ft260_device *dev, u8 addr, u8 cmd,
    if (data_len >= sizeof(rep->data))
        return -EINVAL;

-   if (time_is_before_jiffies(dev->need_wakeup_at)) {
-       (void)ft260_xfer_status(dev, 0);
-       ft260_dbg("device wakeup");
-   }
-
    rep->address = addr;
    rep->data[0] = cmd;
    rep->length = data_len + 1;
@@ -640,8 +644,6 @@ static int ft260_i2c_xfer(struct i2c_adapter *adapter, struct i2c_msg *msgs,

    ret = num;
 i2c_exit:
-   dev->need_wakeup_at =
-       jiffies + msecs_to_jiffies(FT260_WAKEUP_NEEDED_AFTER_MS);
    hid_hw_power(hdev, PM_HINT_NORMAL);
    mutex_unlock(&dev->lock);
    return ret;
@@ -742,8 +744,6 @@ static int ft260_smbus_xfer(struct i2c_adapter *adapter, u16 addr, u16 flags,
    }

 smbus_exit:
-   dev->need_wakeup_at =
-       jiffies + msecs_to_jiffies(FT260_WAKEUP_NEEDED_AFTER_MS);
    hid_hw_power(hdev, PM_HINT_NORMAL);
    mutex_unlock(&dev->lock);
    return ret;

[enrikb]

Thanks @MichaelZaidman, I followed your suggestion after a quick verification using my test hardware. No issues so far. (Actually, I also reasoned about doing it in a similar way.) I do hope that I got the formatting right this time ;-)

[MichaelZaidman]

Thanks @enrikb! Merged.