<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
</head>
<body>
<p><br>
</p>
<div class="moz-cite-prefix">On 5/09/20 5:23 am, Heiner Kallweit wrote:<br>
</div>
<blockquote type="cite" cite="mid:CAFSsGVvRMQoEoBN1hpao_4uM1yF2wwuKPbMkAcwFWyE1X8HDbQ@mail.gmail.com">
<div><br>
</div>
<div><br>
<div class="gmail_quote">
<div dir="ltr" class="gmail_attr">On Fri 4. Sep 2020 at 01:58, Chris Packham <<a href="mailto:Chris.Packham@alliedtelesis.co.nz" moz-do-not-send="true">Chris.Packham@alliedtelesis.co.nz</a>> wrote:<br>
</div>
<blockquote class="gmail_quote" style="margin:0 0 0
.8ex;border-left:1px #ccc solid;padding-left:1ex">
<br>
<br>
On 1/09/20 6:14 pm, Nicholas Piggin wrote:<br>
<br>
> Excerpts from Chris Packham's message of September 1, 2020 11:25 am:<br>
<br>
>> On 1/09/20 12:33 am, Heiner Kallweit wrote:<br>
<br>
>>> On 30.08.2020 23:59, Chris Packham wrote:<br>
<br>
>>>> On 31/08/20 9:41 am, Heiner Kallweit wrote:<br>
<br>
>>>>> On 30.08.2020 23:00, Chris Packham wrote:<br>
<br>
>>>>>> On 31/08/20 12:30 am, Nicholas Piggin wrote:<br>
<br>
>>>>>>> Excerpts from Chris Packham's message of August 28, 2020 8:07 am:<br>
<br>
>>>>>> <snip><br>
<br>
>>>>>><br>
<br>
>>>>>>>>>>>> I've also now seen the RX FIFO not empty error on the T2080RDB<br>
<br>
>>>>>>>>>>>><br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON isn't set!<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON isn't set!<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON isn't set!<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON isn't set!<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Transfer done but rx/tx fifo's aren't empty!<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: SPIE_RXCNT = 1, SPIE_TXCNT = 32<br>
<br>
>>>>>>>>>>>><br>
<br>
>>>>>>>>>>>> With my current workaround of emptying the RX FIFO. It seems<br>
<br>
>>>>>>>>>>>> survivable. Interestingly it only ever seems to be 1 extra byte in the<br>
<br>
>>>>>>>>>>>> RX FIFO and it seems to be after either a READ_SR or a READ_FSR.<br>
<br>
>>>>>>>>>>>><br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: tx 70<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: rx 03<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Extra RX 00<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON isn't set!<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Transfer done but rx/tx fifo's aren't empty!<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: SPIE_RXCNT = 1, SPIE_TXCNT = 32<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: tx 05<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: rx 00<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Extra RX 03<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON isn't set!<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Transfer done but rx/tx fifo's aren't empty!<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: SPIE_RXCNT = 1, SPIE_TXCNT = 32<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: tx 05<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: rx 00<br>
<br>
>>>>>>>>>>>> fsl_espi ffe110000.spi: Extra RX 03<br>
<br>
>>>>>>>>>>>><br>
<br>
>>>>>>>>>>>> From all the Micron SPI-NOR datasheets I've got access to it is<br>
<br>
>>>>>>>>>>>> possible to continually read the SR/FSR. But I've no idea why it<br>
<br>
>>>>>>>>>>>> happens some times and not others.<br>
<br>
>>>>>>>>>>> So I think I've got a reproduction and I think I've bisected the problem<br>
<br>
>>>>>>>>>>> to commit 3282a3da25bd ("powerpc/64: Implement soft interrupt replay in<br>
<br>
>>>>>>>>>>> C"). My day is just finishing now so I haven't applied too much scrutiny<br>
<br>
>>>>>>>>>>> to this result. Given the various rabbit holes I've been down on this<br>
<br>
>>>>>>>>>>> issue already I'd take this information with a good degree of skepticism.<br>
<br>
>>>>>>>>>>><br>
<br>
>>>>>>>>>> OK, so an easy test should be to re-test with a 5.4 kernel.<br>
<br>
>>>>>>>>>> It doesn't have yet the change you're referring to, and the fsl-espi driver<br>
<br>
>>>>>>>>>> is basically the same as in 5.7 (just two small changes in 5.7).<br>
<br>
>>>>>>>>> There's 6cc0c16d82f88 and maybe also other interrupt related patches<br>
<br>
>>>>>>>>> around this time that could affect book E, so it's good if that exact<br>
<br>
>>>>>>>>> patch is confirmed.<br>
<br>
>>>>>>>> My confirmation is basically that I can induce the issue in a 5.4 kernel<br>
<br>
>>>>>>>> by cherry-picking 3282a3da25bd. I'm also able to "fix" the issue in<br>
<br>
>>>>>>>> 5.9-rc2 by reverting that one commit.<br>
<br>
>>>>>>>><br>
<br>
>>>>>>>> I both cases it's not exactly a clean cherry-pick/revert so I also<br>
<br>
>>>>>>>> confirmed the bisection result by building at 3282a3da25bd (which sees<br>
<br>
>>>>>>>> the issue) and the commit just before (which does not).<br>
<br>
>>>>>>> Thanks for testing, that confirms it well.<br>
<br>
>>>>>>><br>
<br>
>>>>>>> [snip patch]<br>
<br>
>>>>>>><br>
<br>
>>>>>>>> I still saw the issue with this change applied. PPC_IRQ_SOFT_MASK_DEBUG<br>
<br>
>>>>>>>> didn't report anything (either with or without the change above).<br>
<br>
>>>>>>> Okay, it was a bit of a shot in the dark. I still can't see what<br>
<br>
>>>>>>> else has changed.<br>
<br>
>>>>>>><br>
<br>
>>>>>>> What would cause this, a lost interrupt? A spurious interrupt? Or<br>
<br>
>>>>>>> higher interrupt latency?<br>
<br>
>>>>>>><br>
<br>
>>>>>>> I don't think the patch should cause significantly worse latency,<br>
<br>
>>>>>>> (it's supposed to be a bit better if anything because it doesn't set<br>
<br>
>>>>>>> up the full interrupt frame). But it's possible.<br>
<br>
>>>>>> My working theory is that the SPI_DON indication is all about the TX<br>
<br>
>>>>>> direction an now that the interrupts are faster we're hitting an error<br>
<br>
>>>>>> because there is still RX activity going on. Heiner disagrees with my<br>
<br>
>>>>>> interpretation of the SPI_DON indication and the fact that it doesn't<br>
<br>
>>>>>> happen every time does throw doubt on it.<br>
<br>
>>>>>><br>
<br>
>>>>> It's right that the eSPI spec can be interpreted that SPI_DON refers to<br>
<br>
>>>>> TX only. However this wouldn't really make sense, because also for RX<br>
<br>
>>>>> we program the frame length, and therefore want to be notified once the<br>
<br>
>>>>> full frame was received. Also practical experience shows that SPI_DON<br>
<br>
>>>>> is set also after RX-only transfers.<br>
<br>
>>>>> Typical SPI NOR use case is that you write read command + start address,<br>
<br>
>>>>> followed by a longer read. If the TX-only interpretation would be right,<br>
<br>
>>>>> we'd always end up with SPI_DON not being set.<br>
<br>
>>>>><br>
<br>
>>>>>> I can't really explain the extra RX byte in the fifo. We know how many<br>
<br>
>>>>>> bytes to expect and we pull that many from the fifo so it's not as if<br>
<br>
>>>>>> we're missing an interrupt causing us to skip the last byte. I've been<br>
<br>
>>>>>> looking for some kind of off-by-one calculation but again if it were<br>
<br>
>>>>>> something like that it'd happen all the time.<br>
<br>
>>>>>><br>
<br>
>>>>> Maybe it helps to know what value this extra byte in the FIFO has. Is it:<br>
<br>
>>>>> - a duplicate of the last read byte<br>
<br>
>>>>> - or the next byte (at <end address> + 1)<br>
<br>
>>>>> - or a fixed value, e.g. always 0x00 or 0xff<br>
<br>
>>>> The values were up thread a bit but I'll repeat them here<br>
<br>
>>>><br>
<br>
>>>> fsl_espi ffe110000.spi: tx 70<br>
<br>
>>>> fsl_espi ffe110000.spi: rx 03<br>
<br>
>>>> fsl_espi ffe110000.spi: Extra RX 00<br>
<br>
>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON isn't set!<br>
<br>
>>>> fsl_espi ffe110000.spi: Transfer done but rx/tx fifo's aren't empty!<br>
<br>
>>>> fsl_espi ffe110000.spi: SPIE_RXCNT = 1, SPIE_TXCNT = 32<br>
<br>
>>>> fsl_espi ffe110000.spi: tx 05<br>
<br>
>>>> fsl_espi ffe110000.spi: rx 00<br>
<br>
>>>> fsl_espi ffe110000.spi: Extra RX 03<br>
<br>
>>>> fsl_espi ffe110000.spi: Transfer done but SPIE_DON isn't set!<br>
<br>
>>>> fsl_espi ffe110000.spi: Transfer done but rx/tx fifo's aren't empty!<br>
<br>
>>>> fsl_espi ffe110000.spi: SPIE_RXCNT = 1, SPIE_TXCNT = 32<br>
<br>
>>>> fsl_espi ffe110000.spi: tx 05<br>
<br>
>>>> fsl_espi ffe110000.spi: rx 00<br>
<br>
>>>> fsl_espi ffe110000.spi: Extra RX 03<br>
<br>
>>>><br>
<br>
>>>><br>
<br>
>>>> The rx 00 Extra RX 03 is a bit concerning. I've only ever seen them with<br>
<br>
>>>> either a READ_SR or a READ_FSR. Never a data read.<br>
<br>
>>>><br>
<br>
>>> Just remembered something about SPIE_DON:<br>
<br>
>>> Transfers are always full duplex, therefore in case of a read the chip<br>
<br>
>>> sends dummy zero's. Having said that in case of a read SPIE_DON means<br>
<br>
>>> that the last dummy zero was shifted out.<br>
<br>
>>><br>
<br>
>>> READ_SR and READ_FSR are the shortest transfers, 1 byte out and 1 byte in.<br>
<br>
>>> So the issue may have a dependency on the length of the transfer.<br>
<br>
>>> However I see no good explanation so far. You can try adding a delay of<br>
<br>
>>> a few miroseconds between the following to commands in fsl_espi_bufs().<br>
<br>
>>><br>
<br>
>>> fsl_espi_write_reg(espi, ESPI_SPIM, mask);<br>
<br>
>>><br>
<br>
>>> /* Prevent filling the fifo from getting interrupted */<br>
<br>
>>> spin_lock_irq(&espi->lock);<br>
<br>
>>><br>
<br>
>>> Maybe enabling interrupts and seeing the SPIE_DON interrupt are too close.<br>
<br>
>> I think this might be heading in the right direction. Playing about with<br>
<br>
>> a delay does seem to make the two symptoms less likely. Although I have<br>
<br>
>> to set it quite high (i.e. msleep(100)) to completely avoid any<br>
<br>
>> possibility of seeing either message.<br>
<br>
> The patch might replay the interrupt a little bit faster, but it would<br>
<br>
> be a few microseconds at most I think (just from improved code).<br>
<br>
><br>
<br>
> Would you be able to ftrace the interrupt handler function and see if you<br>
<br>
> can see a difference in number or timing of interrupts? I'm at a bit of<br>
<br>
> a loss.<br>
<br>
<br>
<br>
I tried ftrace but I really wasn't sure what I was looking for. <br>
<br>
Capturing a "bad" case was pretty tricky. But I think I've identified a <br>
<br>
fix (I'll send it as a proper patch shortly). The gist is<br>
<br>
<br>
<br>
diff --git a/drivers/spi/spi-fsl-espi.c b/drivers/spi/spi-fsl-espi.c<br>
<br>
index 7e7c92cafdbb..cb120b68c0e2 100644<br>
<br>
--- a/drivers/spi/spi-fsl-espi.c<br>
<br>
+++ b/drivers/spi/spi-fsl-espi.c<br>
<br>
@@ -574,13 +574,14 @@ static void fsl_espi_cpu_irq(struct fsl_espi <br>
<br>
*espi, u32 events)<br>
<br>
static irqreturn_t fsl_espi_irq(s32 irq, void *context_data)<br>
<br>
{<br>
<br>
struct fsl_espi *espi = context_data;<br>
<br>
- u32 events;<br>
<br>
+ u32 events, mask;<br>
<br>
<br>
<br>
spin_lock(&espi->lock);<br>
<br>
<br>
<br>
/* Get interrupt events(tx/rx) */<br>
<br>
events = fsl_espi_read_reg(espi, ESPI_SPIE);<br>
<br>
- if (!events) {<br>
<br>
+ mask = fsl_espi_read_reg(espi, ESPI_SPIM);<br>
<br>
+ if (!(events & mask)) {<br>
<br>
spin_unlock(&espi->lock);<br>
<br>
return IRQ_NONE;<br>
<br>
}<br>
<br>
<br>
<br>
The SPIE register contains the TXCNT so events is pretty much always <br>
<br>
going to have something set. By checking events against what we've <br>
<br>
actually requested interrupts for we don't see any spurious events.<br>
<br>
</blockquote>
<div dir="auto"><br>
</div>
<div dir="auto">Usually we shouldn’t receive interrupts we’re not interested in, except the interrupt is shared.</div>
</div>
</div>
</blockquote>
My theory is that we get an interrupt to the core for RXT and another for DON. With the changes to the powerpc interrupt handling and the fact that fsl_espi_cpu_irq() doesn't actually look at the specific event bits means that sometimes both events are handled
in the processing of the first interrupt and the second one trips the SPI_DON not set error.
<p>There's an old comment "SPI bus sometimes got lost interrupts..." which makes me wonder if the interrupt handling change has fixed this original problem.</p>
<p>I still think the change makes sense regardless because the SPIE register has some counter fields in it.<br>
</p>
<blockquote type="cite" cite="mid:CAFSsGVvRMQoEoBN1hpao_4uM1yF2wwuKPbMkAcwFWyE1X8HDbQ@mail.gmail.com">
<div>
<div class="gmail_quote">
<div dir="auto">This leads to the question: is the SPI interrupt shared with another device on your system?</div>
</div>
</div>
</blockquote>
It's not shared on either the custom board or the T2080RDB.<br>
<blockquote type="cite" cite="mid:CAFSsGVvRMQoEoBN1hpao_4uM1yF2wwuKPbMkAcwFWyE1X8HDbQ@mail.gmail.com">
<div>
<div class="gmail_quote">
<div dir="auto">Do you see spurious interrupts with the patch under /proc/irq/(irq)/spurious?</div>
</div>
</div>
</blockquote>
<p>Yes it looks like it</p>
<p>[root@linuxbox ~]# cat /proc/irq/53/spurious<br>
count 3126<br>
unhandled 0<br>
last_unhandled 0 ms</p>
<p>[root@linuxbox ~]# /flash/dd_test.sh </p>
<p>[root@linuxbox ~]# cat /proc/irq/53/spurious<br>
count 1016<br>
unhandled 0<br>
last_unhandled 4294746100 ms</p>
<p>[root@linuxbox ~]# /flash/dd_test.sh </p>
<p>[root@linuxbox ~]# cat /proc/irq/53/spurious<br>
count 88391<br>
unhandled 0<br>
last_unhandled 4294746100 ms</p>
<p>[root@linuxbox ~]# /flash/dd_test.sh </p>
[root@linuxbox ~]# cat /proc/irq/53/spurious<br>
count 72459<br>
unhandled 2<br>
last_unhandled 4294758632 ms<br>
<blockquote type="cite" cite="mid:CAFSsGVvRMQoEoBN1hpao_4uM1yF2wwuKPbMkAcwFWyE1X8HDbQ@mail.gmail.com">
<div>
<div class="gmail_quote">
<div dir="auto"><br>
</div>
<blockquote class="gmail_quote" style="margin:0 0 0
.8ex;border-left:1px #ccc solid;padding-left:1ex">
<br>
<br>
I've tested this on the T2080RDB and on our custom hardware and it seems <br>
<br>
to resolve the problem.<br>
<br>
<br>
<br>
</blockquote>
</div>
</div>
</blockquote>
</body>
</html>