Linux SPI read and write may occasionally be slow?

Question

I am testing the read and write speed of SPI, and I am using the Linux kernel v3.10. The following IOCTL driver code is from Linux kernel v3.10, and I only added a few lines of printing. I have found through dmesg that occasionally the execution time from enter IOCTL to the end can be very long, usually around 500 us, and occasionally around 3ms(as printed in the dmesg section below). May I ask the reason for this difference and what is the general reason?

My processor is A40i, and its architecture is ARM v7.In my system, there is only one process that reads and writes to this SPI interface.

A part of dmesg:

[73365.845761] enter ioctl
[73365.845775] add lock
[73365.848729] write end
[73365.848744] end ioctl

SPI driver code:

static long
spidev_ioctl(struct file *filp, unsigned int cmd, unsigned long arg)
{
        int                     err = 0;
        int                     retval = 0;
        struct spidev_data      *spidev;
        struct spi_device       *spi;
        u32                     tmp;
        unsigned                n_ioc;
        struct spi_ioc_transfer *ioc;
        printk("enter ioctl\n");
        /* Check type and command number */
        if (_IOC_TYPE(cmd) != SPI_IOC_MAGIC)
                return -ENOTTY;

        /* Check access direction once here; don't repeat below.
         * IOC_DIR is from the user perspective, while access_ok is
         * from the kernel perspective; so they look reversed.
         */
        if (_IOC_DIR(cmd) & _IOC_READ)
                err = !access_ok(VERIFY_WRITE,
                                (void __user *)arg, _IOC_SIZE(cmd));
        if (err == 0 && _IOC_DIR(cmd) & _IOC_WRITE)
                err = !access_ok(VERIFY_READ,
                                (void __user *)arg, _IOC_SIZE(cmd));
        if (err)
                return -EFAULT;

        /* guard against device removal before, or while,
         * we issue this ioctl.
         */
        spidev = filp->private_data;
        spin_lock_irq(&spidev->spi_lock);
        spi = spi_dev_get(spidev->spi);
        spin_unlock_irq(&spidev->spi_lock);

        if (spi == NULL)
                return -ESHUTDOWN;

        /* use the buffer lock here for triple duty:
         *  - prevent I/O (from us) so calling spi_setup() is safe;
         *  - prevent concurrent SPI_IOC_WR_* from morphing
         *    data fields while SPI_IOC_RD_* reads them;
         *  - SPI_IOC_MESSAGE needs the buffer locked "normally".
         */

        printk("add lock\n");
        mutex_lock(&spidev->buf_lock);

        switch (cmd) {
        /* read requests */
        case SPI_IOC_RD_MODE:
                retval = __put_user(spi->mode & SPI_MODE_MASK,
                                        (__u8 __user *)arg);
                break;
        case SPI_IOC_RD_LSB_FIRST:
                retval = __put_user((spi->mode & SPI_LSB_FIRST) ?  1 : 0,
                                        (__u8 __user *)arg);
                break;
        case SPI_IOC_RD_BITS_PER_WORD:
                retval = __put_user(spi->bits_per_word, (__u8 __user *)arg);
                break;
        case SPI_IOC_RD_MAX_SPEED_HZ:
                retval = __put_user(spi->max_speed_hz, (__u32 __user *)arg);
                break;
        /* write requests */
        case SPI_IOC_WR_MODE:
                retval = __get_user(tmp, (u8 __user *)arg);
                if (retval == 0) {
                        u8      save = spi->mode;

                        if (tmp & ~SPI_MODE_MASK) {
                                retval = -EINVAL;
                                break;
                        }

                        tmp |= spi->mode & ~SPI_MODE_MASK;
                        spi->mode = (u8)tmp;
                        retval = spi_setup(spi);
                        if (retval < 0)
                                spi->mode = save;
                        else
                                dev_dbg(&spi->dev, "spi mode %02x\n", tmp);
                }
                break;
        case SPI_IOC_WR_LSB_FIRST:
                retval = __get_user(tmp, (__u8 __user *)arg);
                if (retval == 0) {
                        u8      save = spi->mode;

                        if (tmp)
                                spi->mode |= SPI_LSB_FIRST;
                        else
                                spi->mode &= ~SPI_LSB_FIRST;
                        retval = spi_setup(spi);
                        if (retval < 0)
                                spi->mode = save;
                        else
                                dev_dbg(&spi->dev, "%csb first\n",
                                                tmp ? 'l' : 'm');
                }
                break;
        case SPI_IOC_WR_BITS_PER_WORD:
                retval = __get_user(tmp, (__u8 __user *)arg);
                if (retval == 0) {
                        u8      save = spi->bits_per_word;

                        spi->bits_per_word = tmp;
                        retval = spi_setup(spi);
                        if (retval < 0)
                                spi->bits_per_word = save;
                        else
                                dev_dbg(&spi->dev, "%d bits per word\n", tmp);
                }
                break;
        case SPI_IOC_WR_MAX_SPEED_HZ:
                retval = __get_user(tmp, (__u32 __user *)arg);
                if (retval == 0) {
                        u32     save = spi->max_speed_hz;

                        spi->max_speed_hz = tmp;
                        retval = spi_setup(spi);
                        if (retval < 0)
                                spi->max_speed_hz = save;
                        else
                                dev_dbg(&spi->dev, "%d Hz (max)\n", tmp);
                }
                break;

        default:
                /* segmented and/or full-duplex I/O request */
                if (_IOC_NR(cmd) != _IOC_NR(SPI_IOC_MESSAGE(0))
                                || _IOC_DIR(cmd) != _IOC_WRITE) {
                        retval = -ENOTTY;
                        break;
                }

                tmp = _IOC_SIZE(cmd);
                if ((tmp % sizeof(struct spi_ioc_transfer)) != 0) {
                        retval = -EINVAL;
                        break;
                }
                n_ioc = tmp / sizeof(struct spi_ioc_transfer);
                if (n_ioc == 0)
                        break;

                /* copy into scratch area */
                ioc = kmalloc(tmp, GFP_KERNEL);
                if (!ioc) {
                        retval = -ENOMEM;
                        break;
                }
                if (__copy_from_user(ioc, (void __user *)arg, tmp)) {
                        kfree(ioc);
                        retval = -EFAULT;
                        break;
                }

                /* translate to spi_message, execute */
                retval = spidev_message(spidev, ioc, n_ioc);
                kfree(ioc);
                break;
        }

        mutex_unlock(&spidev->buf_lock);
        printk("write end\n");
        spi_dev_put(spi);
        printk("end ioctl\n");
        return retval;
}