On Fri 4. Sep 2020 at 01:58, Chris Packham <Chris.Packham@alliedtelesis.co.nz<= /a>> wrote:

On 1/09/20 6= :14 pm, Nicholas Piggin wrote:

> Excerpts from Chris Packham'= s message of September 1, 2020 11:25 am:

>> On 1/09/20 12:33 a= m, Heiner Kallweit wrote:

>>> On 30.08.2020 23:59, Chris Pa= ckham wrote:

>>>> On 31/08/20 9:41 am, Heiner Kallweit w= rote:

>>>>> On 30.08.2020 23:00, Chris Packham wrote:=

>>>>>> On 31/08/20 12:30 am, Nicholas Piggin wrot= e:

>>>>>>> Excerpts from Chris Packham's me= ssage of August 28, 2020 8:07 am:

>>>>>> <snip&= gt;

>>>>>>

>>>>>>>>= >>>> I've also now seen the RX FIFO not empty error on the = T2080RDB

>>>>>>>>>>>>

>= ;>>>>>>>>>>> fsl_espi ffe110000.spi: Trans= fer done but SPIE_DON isn't set!

>>>>>>>>= ;>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON isn= 9;t set!

>>>>>>>>>>>> fsl_espi f= fe110000.spi: Transfer done but SPIE_DON isn't set!

>>>= >>>>>>>>> fsl_espi ffe110000.spi: Transfer done = but SPIE_DON isn't set!

>>>>>>>>>>= >> fsl_espi ffe110000.spi: Transfer done but rx/tx fifo's aren= 9;t empty!

>>>>>>>>>>>> fsl_espi= ffe110000.spi: SPIE_RXCNT =3D 1, SPIE_TXCNT =3D 32

>>>>= >>>>>>>>

>>>>>>>>>= ;>>> With my current workaround of emptying the RX FIFO. It seems<= br>
>>>>>>>>>>>> survivable. Interes= tingly it only ever seems to be 1 extra byte in the

>>>>= >>>>>>>> RX FIFO and it seems to be after either a = READ_SR or a READ_FSR.

>>>>>>>>>>>&= gt;

>>>>>>>>>>>> fsl_espi ffe110= 000.spi: tx 70

>>>>>>>>>>>> fsl_= espi ffe110000.spi: rx 03

>>>>>>>>>>&g= t;> fsl_espi ffe110000.spi: Extra RX 00

>>>>>>&= gt;>>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON = isn't set!

>>>>>>>>>>>> fsl_= espi ffe110000.spi: Transfer done but rx/tx fifo's aren't empty!
>>>>>>>>>>>> fsl_espi ffe110000.sp= i: SPIE_RXCNT =3D 1, SPIE_TXCNT =3D 32

>>>>>>>&= gt;>>>> fsl_espi ffe110000.spi: tx 05

>>>>&g= t;>>>>>>> fsl_espi ffe110000.spi: rx 00

>>= ;>>>>>>>>>> fsl_espi ffe110000.spi: Extra RX = 03

>>>>>>>>>>>> fsl_espi ffe1100= 00.spi: Transfer done but SPIE_DON isn't set!

>>>>&g= t;>>>>>>> fsl_espi ffe110000.spi: Transfer done but rx= /tx fifo's aren't empty!

>>>>>>>>>= ;>>> fsl_espi ffe110000.spi: SPIE_RXCNT =3D 1, SPIE_TXCNT =3D 32
>>>>>>>>>>>> fsl_espi ffe110000.s= pi: tx 05

>>>>>>>>>>>> fsl_espi = ffe110000.spi: rx 00

>>>>>>>>>>>>= ; fsl_espi ffe110000.spi: Extra RX 03

>>>>>>>&g= t;>>>>

>>>>>>>>>>>>= =C2=A0 =C2=A0 =C2=A0 From all the Micron SPI-NOR datasheets I've got ac= cess to it is

>>>>>>>>>>>> possi= ble to continually read the SR/FSR. But I've no idea why it

>= >>>>>>>>>>> happens some times and not oth= ers.

>>>>>>>>>>> So I think I'v= e got a reproduction and I think I've bisected the problem

>&= gt;>>>>>>>>> to commit 3282a3da25bd ("power= pc/64: Implement soft interrupt replay in

>>>>>>&g= t;>>>> C"). My day is just finishing now so I haven't = applied too much scrutiny

>>>>>>>>>>&g= t; to this result. Given the various rabbit holes I've been down on thi= s

>>>>>>>>>>> issue already I'd= take this information with a good degree of skepticism.

>>>= ;>>>>>>>>

>>>>>>>>&g= t;> OK, so an easy test should be to re-test with a 5.4 kernel.

&= gt;>>>>>>>>> It doesn't have yet the change = you're referring to, and the fsl-espi driver

>>>>>= ;>>>>> is basically the same as in 5.7 (just two small chang= es in 5.7).

>>>>>>>>> There's 6cc0c16= d82f88 and maybe also other interrupt related patches

>>>&g= t;>>>>> around this time that could affect book E, so it'= ;s good if that exact

>>>>>>>>> patch is = confirmed.

>>>>>>>> My confirmation is basic= ally that I can induce the issue in a 5.4 kernel

>>>>>= ;>>> by cherry-picking 3282a3da25bd. I'm also able to "fi= x" the issue in

>>>>>>>> 5.9-rc2 by rev= erting that one commit.

>>>>>>>>

>= >>>>>>> I both cases it's not exactly a clean cher= ry-pick/revert so I also

>>>>>>>> confirmed = the bisection result by building at 3282a3da25bd (which sees

>>= ;>>>>>> the issue) and the commit just before (which does= not).

>>>>>>> Thanks for testing, that confirm= s it well.

>>>>>>>

>>>>>&= gt;> [snip patch]

>>>>>>>

>>>= ;>>>>> I still saw the issue with this change applied. PPC_I= RQ_SOFT_MASK_DEBUG

>>>>>>>> didn't repor= t anything (either with or without the change above).

>>>&g= t;>>> Okay, it was a bit of a shot in the dark. I still can't = see what

>>>>>>> else has changed.

>&= gt;>>>>>

>>>>>>> What would caus= e this, a lost interrupt? A spurious interrupt? Or

>>>>&= gt;>> higher interrupt latency?

>>>>>>>
>>>>>>> I don't think the patch should cause= significantly worse latency,

>>>>>>> (it's= supposed to be a bit better if anything because it doesn't set

= >>>>>>> up the full interrupt frame). But it's pos= sible.

>>>>>> My working theory is that the SPI_DO= N indication is all about the TX

>>>>>> direction = an now that the interrupts are faster we're hitting an error

>= ;>>>>> because there is still RX activity going on. Heiner d= isagrees with my

>>>>>> interpretation of the SPI_= DON indication and the fact that it doesn't

>>>>>= > happen every time does throw doubt on it.

>>>>>&= gt;

>>>>> It's right that the eSPI spec can be in= terpreted that SPI_DON refers to

>>>>> TX only. Howev= er this wouldn't really make sense, because also for RX

>>= >>> we program the frame length, and therefore want to be notified= once the

>>>>> full frame was received. Also practic= al experience shows that SPI_DON

>>>>> is set also af= ter RX-only transfers.

>>>>> Typical SPI NOR use case= is that you write read command + start address,

>>>>>= ; followed by a longer read. If the TX-only interpretation would be right,<= br>
>>>>> we'd always end up with SPI_DON not being s= et.

>>>>>

>>>>>> I can't= really explain the extra RX byte in the fifo. We know how many

>= >>>>> bytes to expect and we pull that many from the fifo so= it's not as if

>>>>>> we're missing an in= terrupt causing us to skip the last byte. I've been

>>>= >>> looking for some kind of off-by-one calculation but again if i= t were

>>>>>> something like that it'd happen = all the time.

>>>>>>

>>>>> M= aybe it helps to know what value this extra byte in the FIFO has. Is it:
>>>>> - a duplicate of the last read byte

>&g= t;>>> - or the next byte (at <end address> + 1)

>&= gt;>>> - or a fixed value, e.g. always 0x00 or 0xff

>>= ;>> The values were up thread a bit but I'll repeat them here
=
>>>>

>>>> fsl_espi ffe110000.spi: tx 70<= br>
>>>> fsl_espi ffe110000.spi: rx 03

>>>&g= t; fsl_espi ffe110000.spi: Extra RX 00

>>>> fsl_espi ffe= 110000.spi: Transfer done but SPIE_DON isn't set!

>>>&g= t; fsl_espi ffe110000.spi: Transfer done but rx/tx fifo's aren't em= pty!

>>>> fsl_espi ffe110000.spi: SPIE_RXCNT =3D 1, SPIE= _TXCNT =3D 32

>>>> fsl_espi ffe110000.spi: tx 05

= >>>> fsl_espi ffe110000.spi: rx 00

>>>> fsl_= espi ffe110000.spi: Extra RX 03

>>>> fsl_espi ffe110000.= spi: Transfer done but SPIE_DON isn't set!

>>>> fsl_= espi ffe110000.spi: Transfer done but rx/tx fifo's aren't empty!
>>>> fsl_espi ffe110000.spi: SPIE_RXCNT =3D 1, SPIE_TXCNT = =3D 32

>>>> fsl_espi ffe110000.spi: tx 05

>>= ;>> fsl_espi ffe110000.spi: rx 00

>>>> fsl_espi ff= e110000.spi: Extra RX 03

>>>>

>>>>
>>>> The rx 00 Extra RX 03 is a bit concerning. I've o= nly ever seen them with

>>>> either a READ_SR or a READ_= FSR. Never a data read.

>>>>

>>> Just re= membered something about SPIE_DON:

>>> Transfers are always= full duplex, therefore in case of a read the chip

>>> send= s dummy zero's. Having said that in case of a read SPIE_DON means
>>> that the last dummy zero was shifted out.

>>>= ;

>>> READ_SR and READ_FSR are the shortest transfers, 1 by= te out and 1 byte in.

>>> So the issue may have a dependenc= y on the length of the transfer.

>>> However I see no good = explanation so far. You can try adding a delay of

>>> a few= miroseconds between the following to commands in fsl_espi_bufs().

&= gt;>>

>>>=C2=A0 =C2=A0 =C2=A0fsl_espi_write_reg(espi,= ESPI_SPIM, mask);

>>>

>>>=C2=A0 =C2=A0 =C2= =A0/* Prevent filling the fifo from getting interrupted */

>>&= gt;=C2=A0 =C2=A0 =C2=A0spin_lock_irq(&espi->lock);

>>&g= t;

>>> Maybe enabling interrupts and seeing the SPIE_DON in= terrupt are too close.

>> I think this might be heading in the= right direction. Playing about with

>> a delay does seem to m= ake the two symptoms less likely. Although I have

>> to set it= quite high (i.e. msleep(100)) to completely avoid any

>> poss= ibility of seeing either message.

> The patch might replay the in= terrupt a little bit faster, but it would

> be a few microseconds= at most I think (just from improved code).

>

> Would y= ou be able to ftrace the interrupt handler function and see if you

&= gt; can see a difference in number or timing of interrupts? I'm at a bi= t of

> a loss.

I tried ftrace but I really wasn= 9;t sure what I was looking for.

Capturing a "bad" case w= as pretty tricky. But I think I've identified a

fix (I'll s= end it as a proper patch shortly). The gist is

diff --git a/= drivers/spi/spi-fsl-espi.c b/drivers/spi/spi-fsl-espi.c

index 7e7c92= cafdbb..cb120b68c0e2 100644

--- a/drivers/spi/spi-fsl-espi.c

= +++ b/drivers/spi/spi-fsl-espi.c

@@ -574,13 +574,14 @@ static void f= sl_espi_cpu_irq(struct fsl_espi

*espi, u32 events)

=C2=A0=C2= =A0static irqreturn_t fsl_espi_irq(s32 irq, void *context_data)

=C2= =A0=C2=A0{

=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 struct f= sl_espi *espi =3D context_data;

-=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0 u32 events;

+=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 u32 events, ma= sk;

=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 spin_lo= ck(&espi->lock);

=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0= =C2=A0=C2=A0 /* Get interrupt events(tx/rx) */

=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0 events =3D fsl_espi_read_reg(espi, ESPI_SPIE);<= br>
-=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 if (!events) {

+=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 mask =3D fsl_espi_read_reg(espi, ESPI_SPIM);=

+=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 if (!(events & mask)) {
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0=C2=A0=C2=A0 spin_unlock(&espi->lock);

=C2=A0= =C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0 return IRQ_NONE;

=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2= =A0=C2=A0=C2=A0 }

The SPIE register contains the TXCNT so ev= ents is pretty much always

going to have something set. By checking= events against what we've

actually requested interrupts for we= don't see any spurious events.

<= br>

Usually we shouldn=E2=80=99t receive interrupts = we=E2=80=99re not interested in, except the interrupt is shared. This leads= to the question: is the SPI interrupt shared with another device on your s= ystem? Do you see spurious interrupts with the patch under /proc/irq/(irq)/= spurious?

<= br>
I've tested this on the T2080RDB and on our custom hardware and = it seems

to resolve the problem.