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

[Matthew Bettencourt <matthew.bettencourt@gmail.com>]

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.

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.


--- 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
>