I use gettimeOfday to calculate the code execution time, The ReadData function consists of two parts: reading /dev/spiio0 and reading/writing
SPI. The test execution time for ReadData is Timer, the test reading time for /dev/spiio0 is Timer1, and the test reading time for SPI is Timer2. In theory, Timer≈(approximately equal to)Timer1+Timer2, but there are occasional occurrences of Timer>>(far greater than)Timer1+Timer2. My current question is why is there a situation where Timer>>(far greater than)Timer1+Timer2?
When I switched to testing with the clock_gettime function, the same goes for me.
For example, pseudocode:
function A
{
operation B;
operation C;
}
The execution time of test function A should be approximately equal to the sum of the execution times of operation B and operation C, but in reality, there may be situations where it is much longer than the sum of times.
Abnormal time:
timer1 = 8242 us
timer2 = 440 us
timer = 95027 us
main.c:
#include "spidev.h"
#include <poll.h>
#include <time.h>
int SpiDevFd = 0;
struct _SPI_Settings spi_settings;
uint8_t tx[256] = {0};
uint8_t rx[256] = {0};
int ReadData(int fd)
{
int ret = 0;
char ch = 0;
struct timeval start1;
struct timeval end1;
unsigned long timer1 = 0;
gettimeofday(&start1, NULL);
ret = read(fd, &ch, sizeof(ch));
gettimeofday(&end1, NULL);
timer1 = 1000000 * (end1.tv_sec - start1.tv_sec) + end1.tv_usec - start1.tv_usec;
printf("timer1 = %ld us\n", timer1);
if (ret) {
struct timeval start2;
struct timeval end2;
unsigned long timer2 = 0;
gettimeofday(&start2, NULL);
TransferSpi(SpiDevFd, &spi_settings, tx, sizeof(tx), rx);
gettimeofday(&end2, NULL);
timer2 = 1000000 * (end2.tv_sec - start2.tv_sec) + end2.tv_usec - start2.tv_usec;
printf("timer2 = %ld us\n", timer2);
hex_dump(rx, ARRAY_SIZE(rx), 32, "RX");
return 0;
}
exit(-1);
return 0;
}
int main() {
int fd = open("/dev/spiio0", O_RDONLY);
if (fd < 0) {
perror("Failed to open GPIO value file\n");
return 1;
}
for (int i = 0; i <= 255; i++)
{
tx[i] = i;
}
spi_settings.mode = 0;
spi_settings.bits = 8;
spi_settings.speed = 10*1000*1000;
spi_settings.delay = 0;
SpiDevFd = OpenSpiDev("/dev/spidev2.0", &spi_settings);
if (SpiDevFd < 0) {
perror("Failed to spi dev file\n");
return 1;
}
unsigned long max = 0;
unsigned long min = 8500;
unsigned long avg = 0;
int testCnt = 10000;
for (int i = 0; i < testCnt; i++) {
struct timeval start;
struct timeval end;
unsigned long timer = 0;
gettimeofday(&start, NULL);
int ret = ReadData(fd);
gettimeofday(&end, NULL);
timer = 1000000 * (end.tv_sec - start.tv_sec) + end.tv_usec - start.tv_usec;
printf("timer = %ld us\n", timer);
avg += timer;
if (timer > max) {
max = timer;
if (max > 25000) {
printf("max ===%ld\n", max);
exit(-1);
}
}
if (timer < min) {
min = timer;
}
}
printf("max=%ld us,min=%ld us, avg= %ld us\n", max, min, avg/testCnt);
close(fd);
return 0;
}
spidev.c:
#include "spidev.h"
#include <linux/spi/spidev.h>
#include <linux/types.h>
#include <getopt.h>
#include <sys/ioctl.h>
#define SPI_API_VERSION "v1.0.0-a1"
enum
{
SPI_MODE = 0,
SPI_DELAY = 0,
SPI_SPEED = 15 * 1000 * 1000,
SPI_BITS = 8
};
int TransferSpi(int fd, SPI_Settings *pspiSettings, const uint8_t *tx, int txSize, uint8_t *rx)
{
int ret;
struct spi_ioc_transfer tr = {
.tx_buf = (unsigned long)tx,
.rx_buf = (unsigned long)rx,
.len = txSize,
.delay_usecs = pspiSettings->delay,
.speed_hz = pspiSettings->speed,
.bits_per_word = pspiSettings->bits,
};
ret = ioctl(fd, SPI_IOC_MESSAGE(1), &tr);
if (ret < 1)
{
perror("can't send spi message");
if (errno == EAGAIN) {
printf("spi operation would block, try a gain later.\n");
}
return -1;
}
return ret;
}
int OpenSpiDev(const char *devName, SPI_Settings *pspiSettings)
{
printf("the version of spi api is %s.\n", SPI_API_VERSION);
int fd = -1;
int ret = -1;
fd = open(devName, O_RDWR);
if (fd < 0)
{
perror("can't open device");
return -1;
}
/*
* spi mode
*/
ret = ioctl(fd, SPI_IOC_WR_MODE, &pspiSettings->mode);
if (ret == -1)
{
perror("can't set spi mode");
return -1;
}
ret = ioctl(fd, SPI_IOC_RD_MODE, &pspiSettings->mode);
if (ret == -1)
{
perror("can't get spi mode");
return -1;
}
/*
* bits per word
*/
ret = ioctl(fd, SPI_IOC_WR_BITS_PER_WORD, &pspiSettings->bits);
if (ret == -1)
{
perror("can't set bits per word");
return -1;
}
ret = ioctl(fd, SPI_IOC_RD_BITS_PER_WORD, &pspiSettings->bits);
if (ret == -1)
{
perror("can't get bits per word");
return -1;
}
/*
* max speed hz
*/
ret = ioctl(fd, SPI_IOC_WR_MAX_SPEED_HZ, &pspiSettings->speed);
if (ret == -1)
{
perror("can't set max speed hz");
return -1;
}
ret = ioctl(fd, SPI_IOC_RD_MAX_SPEED_HZ, &pspiSettings->speed);
if (ret == -1)
{
perror("can't get max speed hz");
return -1;
}
int flags = fcntl(fd, F_GETFL);
if (fcntl(fd, F_SETFL, flags|O_NONBLOCK) == -1) {
perror("can't set non-blocking mode");
return -1;
}
printf("spi delay: %d\n", pspiSettings->delay);
printf("spi mode: %d\n", pspiSettings->mode);
printf("bits per word: %d\n", pspiSettings->bits);
printf("max speed: %d Hz (%d KHz)\n", pspiSettings->speed, pspiSettings->speed / 1000);
return fd;
}
void CloseSpiDev(const int fd)
{
close(fd);
}
void hex_dump(const void *src, size_t length, size_t line_size,
char *prefix)
{
int i = 0;
const unsigned char *address = src;
const unsigned char *line = address;
unsigned char c;
printf("%s | ", prefix);
while (length-- > 0)
{
printf("%02X ", *address++);
if (!(++i % line_size) || (length == 0 && i % line_size))
{
if (length == 0)
{
while (i++ % line_size)
printf("__ ");
}
printf(" |");
while (line < address)
{
c = *line++;
printf("%c", (c < 32 || c > 126) ? '.' : c);
}
printf("|\n");
if (length > 0)
printf("%s | ", prefix);
}
}
}
int test_main(int argc, char *argv[])
{
SPI_Settings spiSettings = {SPI_MODE, SPI_BITS, SPI_SPEED, SPI_DELAY};
int fd = OpenSpiDev("/dev/spidev2.0", &spiSettings);
uint8_t tx[256] = {0};
for (int i = 0; i <= 255; i++)
{
tx[i] = i;
}
uint8_t rx[ARRAY_SIZE(tx)] = {
0,
};
struct timeval start;
struct timeval end;
unsigned long timer;
gettimeofday(&start, NULL);
TransferSpi(fd, &spiSettings, tx, ARRAY_SIZE(tx), rx);
gettimeofday(&end, NULL);
timer = 1000000 * (end.tv_sec - start.tv_sec) + end.tv_usec - start.tv_usec;
printf("timer = %ld us\n", timer);
hex_dump(tx, ARRAY_SIZE(tx), 32, "TX");
hex_dump(rx, ARRAY_SIZE(rx), 32, "RX");
CloseSpiDev(fd);
return 0;
}
spidev.h:
#ifndef __SPIDEV_H
#define __SPIDEV_H
#include <stdint.h>
#include <string.h>
#include <stdlib.h>
#include <unistd.h>
#include <stdio.h>
#include <fcntl.h>
#include <time.h>
#include <errno.h>
#include <sys/time.h>
#define ARRAY_SIZE(a) (sizeof(a) / sizeof((a)[0]))
typedef struct _SPI_Settings
{
uint8_t mode; /*recommendation value: 0*/
uint8_t bits; /*recommendation value: 8*/
uint32_t speed; /*recommendation value: 15*1000*1000*/
uint16_t delay; /*recommendation value: = 0*/
} SPI_Settings;
int TransferSpi(int fd, SPI_Settings *pspiSettings, const uint8_t *tx, int txSize, uint8_t *rx);
int OpenSpiDev(const char *devName, SPI_Settings *pspiSettings);
void CloseSpiDev(const int fd);
void hex_dump(const void *src, size_t length, size_t line_size, char *prefix);
#endif //__SPIDEV_H
Be aware that differences in
gettimeofday()do not measure program execution time, but time passed in general. Hence, OS or other programs may have been running during a given interval and adding to the measured time. Since you mention, that the time difference is occasional, this could be the explanation.With this reservation, let us look at what is measured:
timer1measures read of 1 byte from SPI.timer2measures a SPI transfer in the unknown (does not matter) function TransferSpi.timermeasures both of the above and additionally:printf()statementshex_dump()These additional items are by no means insignificant. I would not be surprised if the
printf()-statements alone could explain the difference.I would recommend measuring the above mentioned bullets separately which may show where the additional time is spent.