Spi transfer time

Hi,

I am using Navio2+rpi2 with the following image:

$ uname -a
Linux navio 4.4.36-a7765e7-emlid-v7+ #41 SMP PREEMPT Mon Mar 20 18:48:32 MSK 2017 armv7l GNU/Linux

I was running some spi transfer tests which look like follows:

#include <unistd.h>
#include <fcntl.h>
#include <sys/ioctl.h>
#include <linux/types.h>
#include <linux/spi/spidev.h>
#include <cstring>
#include <cstdio>
#include <time.h>


int transfer(const char *spidev,
                    unsigned char *tx,
                    unsigned char *rx,
                    unsigned int length,
                    unsigned int speed_hz = 10000000,
                    unsigned char bits_per_word = 8,
                    unsigned short delay_usecs = 0)
{
    spi_ioc_transfer spi_transfer;
    
    memset(&spi_transfer, 0, sizeof(spi_ioc_transfer));

    spi_transfer.tx_buf = (unsigned long)tx;
    spi_transfer.rx_buf = (unsigned long)rx;
    spi_transfer.len = length;
    spi_transfer.speed_hz = speed_hz;
    spi_transfer.bits_per_word = bits_per_word;
    spi_transfer.delay_usecs = delay_usecs;

    int spi_fd = ::open(spidev, O_RDWR);
    if (spi_fd < 0 ) {
        printf("Error: Can not open SPI device\n");
        
        return -1;
    }

    int status = ioctl(spi_fd, SPI_IOC_MESSAGE(1), &spi_transfer);
    int speed;
    int ret = ioctl(spi_fd, SPI_IOC_RD_MAX_SPEED_HZ, &speed);

    ::close(spi_fd);

    return status;
}

int main()
{
    struct timespec t_start, t_end;
    int dt_us = 0;
    int tmax = 0;
    float tavg = 0;

    while (dt_us <= 1000) {
        clock_gettime(CLOCK_MONOTONIC_RAW, &t_start);

        // spi transfer
        unsigned char tx[21] = { 0 };
        unsigned char rx[21] = { 0 };
        tx[0] = 0x3B | 0x80;
        transfer("/dev/spidev0.1", tx, rx, 21);

        clock_gettime(CLOCK_MONOTONIC_RAW, &t_end);
        dt_us = t_end.tv_sec * 1000000 + t_end.tv_nsec / 1000 - t_start.tv_sec * 1000000 - t_start.tv_nsec / 1000;
        if (dt_us > tmax) {
            tmax = dt_us;
        }
        tavg = (0.01 * (float)dt_us) + (0.99) * tavg;
        usleep(50);
    }

    printf("Max (us): %d\n",tmax);
    printf("Avg (us): %d\n",(int)tavg);

}

I should mention that I launch this test on a reserved cpu core (with isolcpus=3 at boot and by launching the test with taskset 0x08 chrt --rr 99).
I have noticed that if I wait long enough, this program will stop, i.e. at one point the spi transfer will take more than 1ms. I have typical average transfer times of around 60us, here’s an example of output:

Max (us): 1409
Avg (us): 67

Running following cyclictest I obtain a max latency of about 250us:

$ sudo ./cyclictest -l1000000 -m -n -a0 -t4 -p99 -i400 -q
# /dev/cpu_dma_latency set to 0us
T: 0 ( 2235) P:99 I:400 C:1000000 Min:      7 Act:    9 Avg:   11 Max:     235
T: 1 ( 2236) P:99 I:900 C: 444431 Min:      7 Act:   11 Avg:   11 Max:     224
T: 2 ( 2237) P:99 I:1400 C: 285682 Min:      7 Act:   10 Avg:   10 Max:     194
T: 3 ( 2238) P:99 I:1900 C: 210485 Min:      7 Act:    9 Avg:   11 Max:     109

I don’t really understand why there would be such discrepancies in spi transfer times; maybe I am doing something wrong here…
At one point I suspected the ntp server to interfere with my time measurements, but the results are unchanged when I turn off the ntp updates with sudo /etc/init.d/ntp stop (moreover, from what I’ve read CLOCK_MONOTONIC_RAW is not affected by ntp updates).

I would be happy to read your thoughts !

Cheers

Hi again,

I’m still stuck on this, has anyone ideas ?

Regards

Hello!

Sorry it’s taken us so long to reply.

1ms seems like an acceptable latency for such tests. You can look into cyclictest code and see if there’s more preparations done before launching the benchmark. Like mlock() on the memory.

I can share several thoughts on the issue:

  1. Test it on the 4.9 kernel that is part of our Stretch release

  2. A unfortunate longish context switch to a kernel driver that acquires a spinlock can lead to this. It can be further analyzed by using for example perf and ftrace which have low overhead.

This topic was automatically closed 100 days after the last reply. New replies are no longer allowed.