<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">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. This leads to the question: is the SPI interrupt shared with another device on your system? Do you see spurious interrupts with the patch under /proc/irq/(irq)/spurious?</div><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>