SPI byte transfer latency

93 views
Skip to first unread message

Sam

unread,
Oct 1, 2020, 1:35:16 PM10/1/20
to bcm2835

I am using a raspberry pi 4 to communicate with a TDC through SPI. I'm using the bcm2835 c libraries for SPI communication and I'm noticing delays between sending/receiving bytes in a single or multiple bcm2835_spi_transfern() calls.
For example, at completely random times in a run, if I am reading 10 bytes, 2 will be read, then there will be a 50 us delay, and then the remaining 8 will be read. Does anyone have ideas what could be causing this?

John L. Males

unread,
Oct 1, 2020, 2:23:21 PM10/1/20
to Samantha Rudinsky
Sam,

Points you may want to consider in random delays you have
observed:

1) Kernel latency.

2) If Pi is set up as CLI only or GUI.

3) Other daemons that may be competing for Kernel attention.

4) SPI device specific behaviour documented or not.

I had been working on code for ADC that is on hold due to some
external factors. I found that there was variability in ADC
data rates. Some may be a result you have observed and/or
unique to nature of ADCs in general and/or a common type of ADC
design I am coding for.


John L. Males
Toronto, Ontario
Canada
01 October 2020 14:23 -0400 EDT


================================================================

2020-10-01 18:14:07+0000-UTC Time: 1601576047 PC/System time

1 Oct 18:14:07 ntpdate[86729]: ntpdate 4.2.8p12-a (1)

1 Oct 18:14:21 ntpdate[89996]: step time server 70.26.92.75
offset -0.001308 sec

FreeBSD 11.3-RELEASE-p13 FreeBSD 11.3-RELEASE-p13 #0: Tue Sep
1 06:56:51 UTC 2020
ro...@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC

(Work in progress alternative to Linux Kernel of its own right,
Debian, and
other Linux based Kernel distributions determined.)

Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz
Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz (1396.86-MHz K8-class
CPU) Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz (1396.86-MHz
K8-class CPU) Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz
(1396.86-MHz K8-class CPU) Intel(R) Core(TM) i3-2367M CPU @
1.40GHz (1396.86-MHz K8-class CPU) Intel(R) Core(TM) i3-2367M
CPU @ 1.40GHz (1396.86-MHz K8-class CPU)

dev.cpu.0.temperature: 72.0C
dev.cpu.1.temperature: 72.0C
dev.cpu.2.temperature: 70.0C
dev.cpu.3.temperature: 70.0C
hw.acpi.thermal.tz0.temperature: 72.1C

vmstat -s:

2111393598 cpu context switches
35672388 device interrupts
7664945 software interrupts
629175588 traps
2254675305 system calls
27 kernel threads created
1680790 fork() calls
39612 vfork() calls
8 rfork() calls
9733 swap pager pageins
80196 swap pager pages paged in
15851 swap pager pageouts
140420 swap pager pages paged out
20554 vnode pager pageins
209821 vnode pager pages paged in
194 vnode pager pageouts
213 vnode pager pages paged out
346 page daemon wakeups
274334034 pages examined by the page daemon
0 clean page reclamation shortfalls
4262707 pages reactivated by the page daemon
67452396 copy-on-write faults
299178 copy-on-write optimized faults
451645596 zero fill pages zeroed
58590 zero fill pages prezeroed
10049 intransit blocking page faults
656863351 total VM faults taken
29721 page faults requiring I/O
0 pages affected by kernel thread creation
59390281 pages affected by fork()
1385481 pages affected by vfork()
348 pages affected by rfork()
639053264 pages freed
19887773 pages freed by daemon
211004982 pages freed by exiting processes
40809 pages active
1754325 pages inactive
5441 pages in the laundry queue
645082 pages wired down
1607109 pages free
4096 bytes per page
107389538 total name lookups
cache hits (88% pos + 3% neg) system 0% per-directory
deletions 0%, falsehits 0%, toolong 0%

Boot time : 1601326255

procs memory page disks
faults cpu0 cpu1 cpu2 cpu3 r b w avm
fre flt re pi po fr sr ad0 pa0 in sy cs us sy
id us sy id us sy id us sy id 0 0 0 2456096 6428376 2629 17
0 0 2558 1098 0 0 143 9026 8452 21 6 73 22 5 73 22
6 72 22 5 72

memory info:

real memory = 17179869184 (16384 MB)
avail memory = 16495013888 (15730 MB)

last pid: 1116; load averages: 0.36, 0.30, 0.27 up
2+21:23:27 18:14:22 52 processes: 1 running, 51 sleeping

Mem: 160M Active, 6853M Inact, 21M Laundry, 2520M Wired, 1554M
Buf, 6277M Free Swap: 48G Total, 147M Used, 48G Free

hw.physmem: 17053859840
hw.usermem: 14411427840
hw.realmem: 17179869184

total used free shared
buffers cached Mem: 16210872 2765240
13445632 0 0 0 Swap:
50331644 150180 50181464

swapinfo:

Device 1K-blocks Used Avail Capacity
/dev/ada0s1b 50331644 150180 50181464 0%

vmstat:

procs memory page disks
faults cpu r b w avm fre flt re pi po
fr sr ad0 pa0 in sy cs us sy id 0 0 0 2456096 6428380
2629 17 0 0 2558 1098 0 0 143 9026 8452 22 6 73


Message replied to:

Date: Thu, 1 Oct 2020 10:35:15 -0700 (PDT)
From: Sam <samantha...@gmail.com>
To: bcm2835 <bcm...@googlegroups.com>
Subject: [bcm2835] SPI byte transfer latency
> --
> You received this message because you are subscribed to the
> Google Groups "bcm2835" group. To unsubscribe from this group
> and stop receiving emails from it, send an email to
> bcm2835+u...@googlegroups.com. To view this discussion
> on the web visit
> https://groups.google.com/d/msgid/bcm2835/7e66406d-bece-4ca7-ae9a-9a3ffc794ecen%40googlegroups.com.

Samantha Rudinsky

unread,
Oct 1, 2020, 2:34:35 PM10/1/20
to bcm...@googlegroups.com
Thanks for the response. I am set up as CLI. How would I be able to determine kernel latency? Can in be remedied?

You received this message because you are subscribed to a topic in the Google Groups "bcm2835" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/bcm2835/8coWhEkH-mA/unsubscribe.
To unsubscribe from this group and all its topics, send an email to bcm2835+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/bcm2835/20201001182307.d1ebe69b34ab816bdc171e42%40gmail.com.

Arjan van Vught

unread,
Oct 1, 2020, 2:37:05 PM10/1/20
to bcm...@googlegroups.com
Alternatively you can use a non-Linux, a baremetal environment -> https://github.com/rsta2/circle

- Arjan

John L. Males

unread,
Oct 1, 2020, 3:11:19 PM10/1/20
to Samantha Rudinsky
Sam,

Arjan van Vught's reply may be worth a go. I have not used a
bare metal solution on a Pi nor what Arjan is suggesting. I
assume you know the big difference of running code on a Pi with
OS like Linux vs running code on a micro controller such as
commonly done with Arduino, ESP8266, STM32, ESP32, and
similar with respect to latency and interrupt latency. Perhaps
and only if will make sense for what you are trying to
accomplish might a Pi bare metal approach be worth trying or to
try to see if different and in what manner different from SPI
delay point of view.

I would think for starters that your Pi OS is CLI based
eliminates the GIU overheads. Maybe see what and how many
processes running. I for one tend to run code from RAM Disk for
many reasons, one is to improve response of applications. If
you have not already move as much of the system file system as
can to tmpfs or similar. Remove the SD file for swapping as
that is bad idea to have swap file on SD card. See if any of
those ideas or other approaches they may suggest improve the SPI
latency observations you have made.

I do not have skills or experience yet, but maybe you need to
scope or use logic analyzer to see if the device is posing
challenges to OS and/or hardware SPI on Pi. I say maybe as I
do not know if you have or have access to scope or logic
analyzer, let alone if you have skills or nack to learn to use
and understand these instruments and their use/data.


John L. Males
Toronto, Ontario
Canada
01 October 2020 15:11 -0400 EDT


================================================================

2020-10-01 18:55:01+0000-UTC Time: 1601578501 PC/System time

1 Oct 18:55:01 ntpdate[46894]: ntpdate 4.2.8p12-a (1)

1 Oct 18:55:15 ntpdate[48965]: step time server 206.108.0.131
offset -0.000930 sec

FreeBSD 11.3-RELEASE-p13 FreeBSD 11.3-RELEASE-p13 #0: Tue Sep
1 06:56:51 UTC 2020
ro...@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC

(Work in progress alternative to Linux Kernel of its own right,
Debian, and
other Linux based Kernel distributions determined.)

Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz
Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz (1396.86-MHz K8-class
CPU) Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz (1396.86-MHz
K8-class CPU) Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz
(1396.86-MHz K8-class CPU) Intel(R) Core(TM) i3-2367M CPU @
1.40GHz (1396.86-MHz K8-class CPU) Intel(R) Core(TM) i3-2367M
CPU @ 1.40GHz (1396.86-MHz K8-class CPU)

dev.cpu.0.temperature: 72.0C
dev.cpu.1.temperature: 72.0C
dev.cpu.2.temperature: 69.0C
dev.cpu.3.temperature: 70.0C
hw.acpi.thermal.tz0.temperature: 72.1C

vmstat -s:

2113374261 cpu context switches
35928789 device interrupts
7722761 software interrupts
632857744 traps
2262919163 system calls
27 kernel threads created
1697379 fork() calls
39997 vfork() calls
8 rfork() calls
9734 swap pager pageins
80198 swap pager pages paged in
15851 swap pager pageouts
140420 swap pager pages paged out
20554 vnode pager pageins
209821 vnode pager pages paged in
195 vnode pager pageouts
214 vnode pager pages paged out
346 page daemon wakeups
274498381 pages examined by the page daemon
0 clean page reclamation shortfalls
4262707 pages reactivated by the page daemon
68116241 copy-on-write faults
301897 copy-on-write optimized faults
454058601 zero fill pages zeroed
58590 zero fill pages prezeroed
10050 intransit blocking page faults
660806424 total VM faults taken
29722 page faults requiring I/O
0 pages affected by kernel thread creation
59976963 pages affected by fork()
1398943 pages affected by vfork()
348 pages affected by rfork()
642924514 pages freed
19887773 pages freed by daemon
212037264 pages freed by exiting processes
40705 pages active
1774418 pages inactive
5430 pages in the laundry queue
648888 pages wired down
1583325 pages free
4096 bytes per page
107847112 total name lookups
cache hits (88% pos + 3% neg) system 0% per-directory
deletions 0%, falsehits 0%, toolong 0%

Boot time : 1601326255

procs memory page disks
faults cpu0 cpu1 cpu2 cpu3 r b w avm
fre flt re pi po fr sr ad0 pa0 in sy cs us sy
id us sy id us sy id us sy id 0 0 0 2477184 6333240 2620 17
0 0 2549 1088 0 0 142 8971 8378 21 6 73 22 5 73 22
6 73 22 5 73

memory info:

real memory = 17179869184 (16384 MB)
avail memory = 16495013888 (15730 MB)

last pid: 60255; load averages: 0.36, 0.32, 0.29 up
2+22:04:21 18:55:16 52 processes: 1 running, 51 sleeping

Mem: 160M Active, 6931M Inact, 21M Laundry, 2535M Wired, 1554M
Buf, 6184M Free Swap: 48G Total, 147M Used, 48G Free

hw.physmem: 17053859840
hw.usermem: 14395838464
hw.realmem: 17179869184

total used free shared
buffers cached Mem: 16210872 2780000
13430872 0 0 0 Swap:
50331644 150176 50181468

swapinfo:

Device 1K-blocks Used Avail Capacity
/dev/ada0s1b 50331644 150176 50181468 0%

vmstat:

procs memory page disks
faults cpu r b w avm fre flt re pi po
fr sr ad0 pa0 in sy cs us sy id 1 0 0 2477184 6333244
2620 17 0 0 2549 1088 0 0 142 8971 8378 22 6 73


Message replied to:

Date: Thu, 1 Oct 2020 13:34:22 -0500
From: Samantha Rudinsky <samantha...@gmail.com>
To: bcm...@googlegroups.com
Subject: Re: [bcm2835] SPI byte transfer latency
> https://groups.google.com/d/msgid/bcm2835/CAK_H8tVQxrBTA68Ti_RUHE1Wat%2BdJTeqZJriN_zXN619JOr9iA%40mail.gmail.com.

Samantha Rudinsky

unread,
Oct 4, 2020, 11:48:23 AM10/4/20
to bcm...@googlegroups.com
I observed the latencies through a logic analyzer. This was the only way to diagnose the problem as otherwise I was just missing interrupts and did not know why. I don't want to move to a bare metal solution because that would negate the benefits of using a Pi over other microcontrollers. 
How do you ensure your code is running on RAM? Also, are you familiar with masking all other interrupts during the program run? 

Arjan van Vught

unread,
Oct 4, 2020, 11:54:18 AM10/4/20
to bcm...@googlegroups.com

Op 4 okt. 2020, om 17:48 heeft Samantha Rudinsky <samantha...@gmail.com> het volgende geschreven:

I observed the latencies through a logic analyzer. This was the only way to diagnose the problem as otherwise I was just missing interrupts and did not know why. I don't want to move to a bare metal solution because that would negate the benefits of using a Pi over other microcontrollers. 
Basically, the Raspberry Pi board is a far better than any microcontroller board. For sure there are no RAM constraints with the RPi board.  And you can do SPI DMA with a pretty high clock frequency.  

How do you ensure your code is running on RAM? Also, are you familiar with masking all other interrupts during the program run? 
You  can prevent swapping on Linux as described here -> https://www.airspayce.com/mikem/bcm2835/ “Real Time performance constraints”. This might help (a little bit).

- Arjan 

John L. Males

unread,
Oct 4, 2020, 1:04:22 PM10/4/20
to Samantha Rudinsky
Sam,

To disable swapping I am sure you know how to with the swapoff
command. I would remove the swap file image that the default
Raspberry PI OS images have (on SD card). I would hope with the
swap file image removed any subsequent boot of the PI OS will
not create a swap file image to restore the one removed from
the SD image.

I highly suspect your CLI based PI OS is not using the
swap file, but you know how to check this with swapon command.

It has been some years since my extensive assembler coding at
the OS and compiler levels. I would think masking other
interrupts would not be a good idea. If other interrupts can
be confirmed as the source of your latency issues then the
question is are those other interrupts excessive and/or have
means to be reduced via what is running on your Pi OS? Masking
other interrupts I suspect could cause other issues in greater
scope compared to the code your current assessment to be missing
interrupts.

I assume with the logic analyzer you see the SPI device raise
the line for the PI pin you have assigned to sense the SPI
device interrupt? If so and your assessment of sometimes the
interrupt is missed I would suggest either the bcm2835 library
and/or the Linux Kernel are at issue. I currently do not have
a PI OS up and running due to a UPS Hat causing file system
corruption while I was working towards creating my custom for
my needs Pi OS image. This is why I am asking what Kernel
version is the PI OS using or did you build your own kernel?
If my question about what Kernel version you are using happens
to cause you to decide to build a Kernel I would suggest doing
so if you can via cross compile on something other than the Pi
simply to avoid the extensive SD card wear it would cause.

Do you have a Pi other than Pi 4 to try to see if you have the
same, different, or no issues? Point is to find out if for
some reason the issue you are experiencing is Pi 4 specific.

I do not know if there is a real time version of the Linux
Kernel available for Pi OS. If so that may worth a try to see
what, if any, differences occur for the application and/or
logic analyzer findings you have thus far.

I know you have your reasons for using a Pi for what you are
working towards. If it is not too difficult in terms of code
adjustments for the purpose of testing maybe it might be an
idea from testing point of view to try the application on a
micro controller. Latency for interrupts in micro controller
is far far less than would be under an OS. The idea of this
test is to determine if there might be a Pi OS factor and/or
device SPI issue.


John L. Males
Toronto, Ontario
Canada
04 October 2020 17:04 -0400 EDT


================================================================

2020-10-04 16:31:19+0000-UTC Time: 1601829079 PC/System time

4 Oct 16:31:19 ntpdate[37564]: ntpdate 4.2.8p12-a (1)

4 Oct 16:31:34 ntpdate[39347]: step time server 132.246.11.227
offset -0.000107 sec

FreeBSD 11.3-RELEASE-p13 FreeBSD 11.3-RELEASE-p13 #0: Tue Sep
1 06:56:51 UTC 2020
ro...@amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC

(Work in progress alternative to Linux Kernel of its own right,
Debian, and
other Linux based Kernel distributions determined.)

Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz
Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz (1396.86-MHz K8-class
CPU) Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz (1396.86-MHz
K8-class CPU) Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz
(1396.86-MHz K8-class CPU) Intel(R) Core(TM) i3-2367M CPU @
1.40GHz (1396.86-MHz K8-class CPU) Intel(R) Core(TM) i3-2367M
CPU @ 1.40GHz (1396.86-MHz K8-class CPU)

dev.cpu.0.temperature: 74.0C
dev.cpu.1.temperature: 74.0C
dev.cpu.2.temperature: 74.0C
dev.cpu.3.temperature: 74.0C
hw.acpi.thermal.tz0.temperature: 73.1C

vmstat -s:

3714777493 cpu context switches
81748017 device interrupts
13214685 software interrupts
1118894072 traps
1215719883 system calls
27 kernel threads created
2954554 fork() calls
69460 vfork() calls
8 rfork() calls
28927 swap pager pageins
138347 swap pager pages paged in
36155 swap pager pageouts
347633 swap pager pages paged out
33656 vnode pager pageins
324684 vnode pager pages paged in
16520 vnode pager pageouts
310049 vnode pager pages paged out
1125 page daemon wakeups
569612219 pages examined by the page daemon
0 clean page reclamation shortfalls
27610974 pages reactivated by the page daemon
119168717 copy-on-write faults
518233 copy-on-write optimized faults
788499346 zero fill pages zeroed
66656 zero fill pages prezeroed
487395 intransit blocking page faults
1168466348 total VM faults taken
60535 page faults requiring I/O
0 pages affected by kernel thread creation
104990967 pages affected by fork()
2429249 pages affected by vfork()
348 pages affected by rfork()
1107693096 pages freed
65053662 pages freed by daemon
367730754 pages freed by exiting processes
951976 pages active
1689666 pages inactive
699143 pages in the laundry queue
674952 pages wired down
37029 pages free
4096 bytes per page
196029434 total name lookups
cache hits (87% pos + 3% neg) system 0% per-directory
deletions 0%, falsehits 0%, toolong 0%

Boot time : 1601389878

procs memory page disks
faults cpu0 cpu1 cpu2 cpu3 r b w avm
fre flt re pi po fr sr ad0 pa0 in sy cs us sy
id us sy id us sy id us sy id 1 0 0 63595180 148056 2660 63
0 0 2522 1297 0 0 186 2768 8458 20 6 74 21 5 74 21
5 74 21 5 74

memory info:

real memory = 17179869184 (16384 MB)
avail memory = 16495013888 (15730 MB)

last pid: 47758; load averages: 0.83, 0.90, 1.10 up
5+02:00:17 16:31:35 67 processes: 1 running, 66 sleeping

Mem: 3719M Active, 6600M Inact, 2731M Laundry, 2637M Wired,
1554M Buf, 144M Free Swap: 48G Total, 868M Used, 47G Free, 1%
Inuse

hw.physmem: 17053859840
hw.usermem: 14289092608
hw.realmem: 17179869184

total used free shared
buffers cached Mem: 16210872 9304184
6906688 0 0 0 Swap: 50331644
888328 49443316

swapinfo:

Device 1K-blocks Used Avail Capacity
/dev/ada0s1b 50331644 888328 49443316 2%

vmstat:

procs memory page disks
faults cpu r b w avm fre flt re pi po
fr sr ad0 pa0 in sy cs us sy id 0 0 0 63595116
148072 2660 63 0 0 2522 1297 0 0 186 2768 8458 21
5 74


Message replied to:

Date: Sun, 4 Oct 2020 10:48:10 -0500
From: Samantha Rudinsky <samantha...@gmail.com>
To: bcm...@googlegroups.com
Subject: Re: [bcm2835] SPI byte transfer latency


[snip]
[snip]
> > https://groups.google.com/d/msgid/bcm2835/20201001191104.467e07ee87f8d193770e81be%40gmail.com
> > .
> >
>
> --
> You received this message because you are subscribed to the
> Google Groups "bcm2835" group. To unsubscribe from this group
> and stop receiving emails from it, send an email to
> bcm2835+u...@googlegroups.com. To view this discussion
> on the web visit
> https://groups.google.com/d/msgid/bcm2835/CAK_H8tU4icck2YWAsOzFoTyeibqs2BvHLnkmaye8hnt-2Q5rtA%40mail.gmail.com.
Reply all
Reply to author
Forward
0 new messages