Re: [PATCH v3 0/7] NXP DSPI bugfixes and support for LS1028A

[Michael Walle <michael@walle.cc>]

Am 2020-03-10 16:22, schrieb Michael Walle:
> Hi Vladimir,
> 
> Am 2020-03-10 15:56, schrieb Vladimir Oltean:
>>> (2) Also, reading the flash, every second time there is 
>>> (reproducibly)
>>> an
>>> IO error:
>>> 
>>> # hexdump -C /dev/mtd0
>>> 00000000  68 75 68 75 0a ff ff ff  ff ff ff ff ff ff ff ff
>>> |huhu............|
>>> 00000010  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff
>>> |................|
>>> *
>>> 01000000
>>> # hexdump -C /dev/mtd0
>>> 00000000  68 75 68 75 0a ff ff ff  ff ff ff ff ff ff ff ff
>>> |huhu............|
>>> 00000010  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff
>>> |................|
>>> *
>>> hexdump: /dev/mtd0: Input/output error
>>> 00dc0000
>>> # hexdump -C /dev/mtd0
>>> 00000000  68 75 68 75 0a ff ff ff  ff ff ff ff ff ff ff ff
>>> |huhu............|
>>> 00000010  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff
>>> |................|
>>> *
>>> 01000000
>>> # hexdump -C /dev/mtd0
>>> 00000000  68 75 68 75 0a ff ff ff  ff ff ff ff ff ff ff ff
>>> |huhu............|
>>> 00000010  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff
>>> |................|
>>> *
>>> hexdump: /dev/mtd0: Input/output error
>>> 00e6a000
>>> 
>> 
>> Just to be clear, issue 2 is seen only after you abort another
>> transaction, right?
> 
> No, just normal uninterrupted reading. Just tried it right after
> reboot. Doesn't seem to be every second time though, just random
> which makes me wonder if that is another problem now. Also the
> last successful reading is random.


Ok I guess I know what the root cause is. This is an extract of
the current code:

> static int dspi_transfer_one_message(struct spi_controller *ctlr,
> 				     struct spi_message *message)
> {
> ..
> 	/* Kick off the interrupt train */
> 	dspi_fifo_write(dspi);
> 
> 	status = wait_event_interruptible(dspi->waitq,
> 					  dspi->waitflags);
> 	dspi->waitflags = 0;
> ..
> }
> 
> static int dspi_rxtx(struct fsl_dspi *dspi)
> {
> 	dspi_fifo_read(dspi);
> 
> 	if (!dspi->len)
> 		/* Success! */
> 		return 0;
> 
> 	dspi_fifo_write(dspi);
> 
> 	return -EINPROGRESS;
> }

dspi_rxtx() is used in the ISR. Both dspi_fifo_write() and dspi_rxtx()
access shared data like, dspi->words_in_flight. In the EIO error case
the following bytes_sent is -1, because dspi->words_in_flight is -1.

> /* Update total number of bytes that were transferred */
> bytes_sent = dspi->words_in_flight * dspi->oper_word_size;

words_in_flight is always -1 after dspi_fifo_read() was called. In
the error case, the ISR kicks in right in the middle of the execution
of dspi_fifo_write() in dspi_transfer_one_message().

> static void dspi_fifo_write(struct fsl_dspi *dspi)
> {
> ..
> 	if (dspi->devtype_data->trans_mode == DSPI_EOQ_MODE)
> 		dspi_eoq_fifo_write(dspi);
> 	 else
> 		dspi_xspi_fifo_write(dspi);

Now if the ISR is executed right here..

> 
> 	/* Update total number of bytes that were transferred */
> 	bytes_sent = dspi->words_in_flight * dspi->oper_word_size;

.. words_in_flight might be -1.

> 	msg->actual_length += bytes_sent;

and bytes_sent is negative. And this causes an IO error because
the returned overall message length doesn't match.

> 	dspi->progress += bytes_sent / DIV_ROUND_UP(xfer->bits_per_word, 8);
> ..
> }

I could not reproduce the issue with the following patch. I don't
know if I got the locking correct though or if there is a better
way to go.


diff --git a/drivers/spi/spi-fsl-dspi.c b/drivers/spi/spi-fsl-dspi.c
index 8b16de9ed382..578fedeb16a0 100644
--- a/drivers/spi/spi-fsl-dspi.c
+++ b/drivers/spi/spi-fsl-dspi.c
@@ -224,6 +224,7 @@ struct fsl_dspi {
         u16                                     tx_cmd;
         const struct fsl_dspi_devtype_data      *devtype_data;

+       spinlock_t lock;
         wait_queue_head_t                       waitq;
         u32                                     waitflags;

@@ -873,14 +874,20 @@ static void dspi_fifo_write(struct fsl_dspi *dspi)

  static int dspi_rxtx(struct fsl_dspi *dspi)
  {
+       unsigned long flags;
+
+       spin_lock_irqsave(&dspi->lock, flags);
         dspi_fifo_read(dspi);

-       if (!dspi->len)
+       if (!dspi->len) {
                 /* Success! */
+               spin_unlock_irqrestore(&dspi->lock, flags);
                 return 0;
+       }

         dspi_fifo_write(dspi);

+       spin_unlock_irqrestore(&dspi->lock, flags);
         return -EINPROGRESS;
  }

@@ -950,7 +957,9 @@ static int dspi_transfer_one_message(struct 
spi_controller *ctlr,
         struct fsl_dspi *dspi = spi_controller_get_devdata(ctlr);
         struct spi_device *spi = message->spi;
         struct spi_transfer *transfer;
+       unsigned long flags;
         int status = 0;
+       int i = 0;

         if (dspi->irq)
                 dspi_enable_interrupts(dspi, true);
@@ -1009,7 +1018,9 @@ static int dspi_transfer_one_message(struct 
spi_controller *ctlr,
                                 goto out;
                 } else if (dspi->irq) {
                         /* Kick off the interrupt train */
+                       spin_lock_irqsave(&dspi->lock, flags);
                         dspi_fifo_write(dspi);
+                       spin_unlock_irqrestore(&dspi->lock, flags);

                         status = wait_event_interruptible(dspi->waitq,
                                                           
dspi->waitflags);
@@ -1301,6 +1312,7 @@ static int dspi_probe(struct platform_device 
*pdev)
         ctlr->cleanup = dspi_cleanup;
         ctlr->slave_abort = dspi_slave_abort;
         ctlr->mode_bits = SPI_CPOL | SPI_CPHA | SPI_LSB_FIRST;
+       spin_lock_init(&dspi->lock);

         pdata = dev_get_platdata(&pdev->dev);
         if (pdata) {



-michael