Re: [BUG] SPD5118 Intermittent MR11 Corruption During Suspend/Resume

[Guenter Roeck <linux@roeck-us.net>]

On 9/1/26 13:53, Matthew Bettencourt wrote:
> Hello Guenter,
> 
> I updated the piix4_transaction() (code below) to only print when there are failures. I then left the computer idle (~30 mins) while reading i2c info and SPD temps and I never saw any failures.
> 
> I then did some sleep and resume with cycles with spd5118 driver enabled and that is when I started to see the error messages again in dmesg.It appears like there is always a failure but not every failure causes corruption in MR11. From what I observed it seems like any `CMD=1a` cause failures but no corruption while whenever there is a `CMD=0b` there is failure and corruption. Not sure what that might mean be but it is something I observed.
> 

No idea either.

> I then ran sleep and resume cycles with spd5118 disabled but still polling i2c devices and could not produce any errors, however this was just done via my desktop gui console so the script might be getting suspended before whatever it is in the sleep cycle that is causing this issue to occur.
> 

That is not surprising, as there is likely no other I2C device on that bus.

So we know that this only happens during suspend/resume. The corruption
seems to be happening exactly once per suspend/resume cycle, and hit
either the 0x1a read or the 0x0b read operation, but not both. To me this
still looks like there is an unprotected access to the I2C controller.

What log messages do you see when the system starts up ? Is there anything
along the line of "SMBus Host Controller at ..." or "Using register 0xXX for
SMBus port selection" ?

Also, is there any device at address 0x22 of bus 13 or 14 ?

Thanks,
Guenter

> 
> --- sleep/resume #1 ---
> [  179.066004] [   T3736] spd5118 12-0053: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  179.066616] [   T3713] spd5118 12-0051: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  179.068576] [   T3736] i2c i2c-12: [PIIX4 ERROR TRACE TRIGGERED] result=0
>              STEP 1 (PRE-START)    : CNT=08, CMD=1a, ADD=a7, DAT0=00, DAT1=18
>              STEP 2 (START BIT SET): CNT=08, CMD=1a, ADD=a7, DAT0=00, DAT1=18
>              STEP 3 (POST-WAIT)    : STS=00, CNT=08, CMD=1a, ADD=a7, DAT0=00, DAT1=18
>              STEP 4 (POST-CLEANUP) : CNT=08, CMD=01, ADD=45, DAT0=00, DAT1=18
> [  179.068814] [   T3713] spd5118 12-0051: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  179.068888] [   T3736] spd5118 12-0053: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> 
> --- sleep/resume #2 ---
> [  235.947153] [   T3700] spd5118 12-0053: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  235.947827] [   T3699] spd5118 12-0051: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  235.951600] [   T3700] i2c i2c-12: [PIIX4 ERROR TRACE TRIGGERED] result=0
>              STEP 1 (PRE-START)    : CNT=08, CMD=0b, ADD=a7, DAT0=00, DAT1=00
>              STEP 2 (START BIT SET): CNT=08, CMD=0b, ADD=a7, DAT0=00, DAT1=00
>              STEP 3 (POST-WAIT)    : STS=00, CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=00
>              STEP 4 (POST-CLEANUP) : CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=00
> [  235.955119] [   T3699] spd5118 12-0051: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  235.955778] [   T3700] spd5118 12-0053: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x08
> 
> --- sleep/resume #3 ---
> [  298.628115] [   T3703] spd5118 12-0053: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  298.629121] [   T3730] spd5118 12-0051: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  298.631589] [   T3730] i2c i2c-12: [PIIX4 ERROR TRACE TRIGGERED] result=0
>              STEP 1 (PRE-START)    : CNT=08, CMD=0b, ADD=a3, DAT0=00, DAT1=18
>              STEP 2 (START BIT SET): CNT=08, CMD=0b, ADD=a3, DAT0=00, DAT1=18
>              STEP 3 (POST-WAIT)    : STS=00, CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=18
>              STEP 4 (POST-CLEANUP) : CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=18
> [  298.636234] [   T3703] spd5118 12-0053: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  298.637812] [   T3730] spd5118 12-0051: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x08
> 
> --- sleep/resume #4 ---
> [  631.979533] [   T3021] spd5118 12-0053: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  631.980193] [   T3017] spd5118 12-0051: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  631.983008] [   T3021] i2c i2c-12: [PIIX4 ERROR TRACE TRIGGERED] result=0
>              STEP 1 (PRE-START)    : CNT=08, CMD=1a, ADD=a7, DAT0=00, DAT1=18
>              STEP 2 (START BIT SET): CNT=08, CMD=1a, ADD=a7, DAT0=00, DAT1=18
>              STEP 3 (POST-WAIT)    : STS=00, CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=18
>              STEP 4 (POST-CLEANUP) : CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=18
> [  631.985028] [   T3021] spd5118 12-0053: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [  631.987201] [   T3017] spd5118 12-0051: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> 
> --- sleep/resume #5 ---
> [ 1288.503455] [  T10850] spd5118 12-0053: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [ 1288.504462] [  T10813] spd5118 12-0051: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [ 1288.505927] [  T10850] i2c i2c-12: [PIIX4 ERROR TRACE TRIGGERED] result=0
>              STEP 1 (PRE-START)    : CNT=08, CMD=0b, ADD=a7, DAT0=00, DAT1=18
>              STEP 2 (START BIT SET): CNT=08, CMD=0b, ADD=a7, DAT0=00, DAT1=18
>              STEP 3 (POST-WAIT)    : STS=00, CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=18
>              STEP 4 (POST-CLEANUP) : CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=18
> [ 1288.511883] [  T10813] spd5118 12-0051: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [ 1288.512541] [  T10850] spd5118 12-0053: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x08
> 
> 
> --- sleep/resume #6 ---
> [ 1339.566042] [  T10863] spd5118 12-0053: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [ 1339.566679] [  T10887] spd5118 12-0051: PRE BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [ 1339.570157] [  T10887] i2c i2c-12: [PIIX4 ERROR TRACE TRIGGERED] result=0
>              STEP 1 (PRE-START)    : CNT=08, CMD=1a, ADD=a3, DAT0=00, DAT1=18
>              STEP 2 (START BIT SET): CNT=08, CMD=1a, ADD=a3, DAT0=00, DAT1=18
>              STEP 3 (POST-WAIT)    : STS=00, CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=18
>              STEP 4 (POST-CLEANUP) : CNT=08, CMD=01, ADD=45, DAT0=ff, DAT1=18
> [ 1339.572182] [  T10887] spd5118 12-0051: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> [ 1339.573363] [  T10863] spd5118 12-0053: POST BIT UPDATE: SUSPEND MR11 (0x0B) -> Cache: 0x00 | Bus: 0x00
> 
> --- piix4 transaction function ---
> int piix4_transaction(struct i2c_adapter *piix4_adapter, unsigned short piix4_smba)
> {
>      int temp;
>      int result = 0;
>      int timeout = 0;
> 
>      dev_dbg(&piix4_adapter->dev, "Transaction (pre): CNT=%02x, CMD=%02x, "
>      "ADD=%02x, DAT0=%02x, DAT1=%02x\n", inb_p(SMBHSTCNT),
>              inb_p(SMBHSTCMD), inb_p(SMBHSTADD), inb_p(SMBHSTDAT0),
>              inb_p(SMBHSTDAT1));
> 
>      /* Register snapshot variables */
>      u8 pre_cnt, pre_cmd, pre_add, pre_dat0, pre_dat1;
>      u8 start_cnt, start_cmd, start_add, start_dat0, start_dat1;
>      u8 postwait_sts, postwait_cnt, postwait_cmd, postwait_add, postwait_dat0, postwait_dat1;
>      u8 post_cnt, post_cmd, post_add, post_dat0, post_dat1;
> 
>      /* Step 1: Read initial register state before starting */
>      pre_cnt  = inb_p(SMBHSTCNT);
>      pre_cmd  = inb_p(SMBHSTCMD);
>      pre_add  = inb_p(SMBHSTADD);
>      pre_dat0 = inb_p(SMBHSTDAT0);
>      pre_dat1 = inb_p(SMBHSTDAT1);
> 
>      /* Make sure the SMBus host is ready to start transmitting */
>      if ((temp = inb_p(SMBHSTSTS)) != 0x00) {
>          dev_dbg(&piix4_adapter->dev, "SMBus busy (%02x). Resetting...\n", temp);
>          outb_p(temp, SMBHSTSTS);
>          if ((temp = inb_p(SMBHSTSTS)) != 0x00) {
>              dev_err(&piix4_adapter->dev, "Failed! (%02x)\n", temp);
>              return -EBUSY;
>          }
>      }
> 
>      /* Start the transaction by setting bit 6 */
>      outb_p(inb(SMBHSTCNT) | 0x040, SMBHSTCNT);
> 
>      /* Step 2: Snapshot immediately after set start bit */
>      start_cnt  = inb_p(SMBHSTCNT);
>      start_cmd  = inb_p(SMBHSTCMD);
>      start_add  = inb_p(SMBHSTADD);
>      start_dat0 = inb_p(SMBHSTDAT0);
>      start_dat1 = inb_p(SMBHSTDAT1);
> 
>      /* Wait for transaction completion */
>      if (srvrworks_csb5_delay)
>          usleep_range(2000, 2100);
>      else
>          usleep_range(250, 500);
> 
>      while ((++timeout < MAX_TIMEOUT) &&
>          ((temp = inb_p(SMBHSTSTS)) & 0x01))
>          usleep_range(250, 500);
> 
>      /* Step 3: Snapshot right after wait loop */
>      postwait_sts  = temp;
>      postwait_cnt  = inb_p(SMBHSTCNT);
>      postwait_cmd  = inb_p(SMBHSTCMD);
>      postwait_add  = inb_p(SMBHSTADD);
>      postwait_dat0 = inb_p(SMBHSTDAT0);
>      postwait_dat1 = inb_p(SMBHSTDAT1);
> 
>      if (timeout == MAX_TIMEOUT)
>          result = -ETIMEDOUT;
>      if (temp & 0x10)
>          result = -EIO;
>      if (temp & 0x08)
>          result = -EIO;
>      if (temp & 0x04)
>          result = -ENXIO;
> 
>      if (inb_p(SMBHSTSTS) != 0x00)
>          outb_p(inb(SMBHSTSTS), SMBHSTSTS);
> 
>      /* Step 4: Final snapshot */
>      post_cnt  = inb_p(SMBHSTCNT);
>      post_cmd  = inb_p(SMBHSTCMD);
>      post_add  = inb_p(SMBHSTADD);
>      post_dat0 = inb_p(SMBHSTDAT0);
>      post_dat1 = inb_p(SMBHSTDAT1);
> 
>      /*
>       * Dump full diagnostic trace ONLY if:
>       * 1. Hardware registers were mutated (pre vs post mismatch on CMD or ADD)
>       * 2. The bus operation returned an error code
>       */
>      if (pre_cmd != post_cmd || pre_add != post_add || result != 0) {
>          dev_err(&piix4_adapter->dev,
>                  "[PIIX4 ERROR TRACE TRIGGERED] result=%d\n"
>                  "  STEP 1 (PRE-START)    : CNT=%02x, CMD=%02x, ADD=%02x, DAT0=%02x, DAT1=%02x\n"
>                  "  STEP 2 (START BIT SET): CNT=%02x, CMD=%02x, ADD=%02x, DAT0=%02x, DAT1=%02x\n"
>                  "  STEP 3 (POST-WAIT)    : STS=%02x, CNT=%02x, CMD=%02x, ADD=%02x, DAT0=%02x, DAT1=%02x\n"
>                  "  STEP 4 (POST-CLEANUP) : CNT=%02x, CMD=%02x, ADD=%02x, DAT0=%02x, DAT1=%02x\n",
>                  result,
>                  pre_cnt, pre_cmd, pre_add, pre_dat0, pre_dat1,
>                  start_cnt, start_cmd, start_add, start_dat0, start_dat1,
>                  postwait_sts, postwait_cnt, postwait_cmd, postwait_add, postwait_dat0, postwait_dat1,
>                  post_cnt, post_cmd, post_add, post_dat0, post_dat1);
>      }
> 
>      if ((temp = inb_p(SMBHSTSTS)) != 0x00) {
>          dev_err(&piix4_adapter->dev, "Failed reset at end of "
>          "transaction (%02x)\n", temp);
>      }
>      dev_dbg(&piix4_adapter->dev, "Transaction (post): CNT=%02x, CMD=%02x, "
>      "ADD=%02x, DAT0=%02x, DAT1=%02x\n", inb_p(SMBHSTCNT),
>              inb_p(SMBHSTCMD), inb_p(SMBHSTADD), inb_p(SMBHSTDAT0),
>              inb_p(SMBHSTDAT1));
> 
>      return result;
> }
> 
> 
> Thanks,
> Matthew
> 
> On 9/1/26 12:04 PM, Guenter Roeck wrote:
>> Hi Matthew,
>>
>> On 9/1/26 09:31, Matthew Bettencourt wrote:
>>> Hello Guenter,
>>>
>>> I added additional logging into the piix4_transaction(). I will put the function call on the bottom. But as you guessed we are seeing not just MR11 corruption but also can trigger on other addresses as well. I was running the suspend/resume cycle and caught on both MR11 issue and else where. Here is the dmesg log output.
>>>
>>> --- Other PIIX4 transation ---
>> ...
>>> [29287.881787] [ T204580] i2c i2c-12: [PIIX4 REGISTER MUTATION DETECTED] Pre: (CMD=0x1a, ADD=0xa3) -> Post: (CMD=0x01, ADD=0x45) | DAT0=0xff
>> ...
>>> [29312.945873] [ T204570] i2c i2c-12: [PIIX4 REGISTER MUTATION DETECTED] Pre: (CMD=0x0b, ADD=0xa7) -> Post: (CMD=0x01, ADD=0x45) | DAT0=0xff
>>
>> It may be a coincidence, but the two failed accesses are exactly 25 seconds apart.
>>
>> Would it be possible to drop the messages except for the failures and run long-term
>> accesses (for example by reading the temperatures and/or the nvmem continuously) ?
>> You should find the nvmem at /sys/bus/nvmem/devices/0-005[13]/nvmem.
>>
>> It might be useful to know if this only happens during suspend/resume cycles
>> or if it happens all the time, if it happens randomly or in specific intervals,
>> and if the failure pattern is always the same.
>>
>> Thanks,
>> Guenter
>>
>