# Odd results when measuring timing

Some introduction to my case: I have an ADC (MCP3008) connected to my RasPi with SPI. To that ADC I have connected 2 multiplexers (4051 dip-chips, I plan on connecting 8 multiplexers eventually). So in total I can now connect 64 analog inputs to my raspberry pi, which is because I'm building an electric/digital xylophone.

To measure the delay between two readings of the same input I have the following code:

``````import Adafruit_GPIO.SPI as SPI
import RPi.GPIO as GPIO
from time import time

MUX_0 = 26
MUX_1 = 21
MUX_2 = 20

GPIO.setmode(GPIO.BCM)
GPIO.setup(26, GPIO.OUT)
GPIO.setup(21, GPIO.OUT)
GPIO.setup(20, GPIO.OUT)

SPI_PORT = 0
SPI_DEVICE = 0

GPIO.output(MUX_0, i%8-1%2)
GPIO.output(MUX_1, (i%8-1>>1)%2)
GPIO.output(MUX_2, (i%8-1>>2)%2)

while True:
start_time = time()
for i in range(64):
if i == 63:
print(str((time() - start_time) * 1000.0) + " milliseconds")
start_time = time()
``````

So this (for what I know) measures the time between two readings of input 9. This gives me an average delay of about 1.2ms, which is good. However, if I change the if-statement to `if i == 63:` for example, the average is about 7ms. I tried some other numbers and the delay seems to go up with the input numbers. However, that doesn't make sense to me and I don't know what causes it.

Below is a piece of output with `if i == 0`.

``````0.138998031616 milliseconds
0.15115737915 milliseconds
0.138998031616 milliseconds
0.136852264404 milliseconds
0.149965286255 milliseconds
0.142097473145 milliseconds
0.140905380249 milliseconds
0.139951705933 milliseconds
0.1380443573 milliseconds
0.139951705933 milliseconds
0.136852264404 milliseconds
0.137090682983 milliseconds
0.137090682983 milliseconds
0.137805938721 milliseconds
0.135898590088 milliseconds
``````

Below is a piece of output with `if i == 63`.

``````7.63201713562 milliseconds
7.57384300232 milliseconds
7.52806663513 milliseconds
7.58504867554 milliseconds
7.65609741211 milliseconds
7.57813453674 milliseconds
7.69996643066 milliseconds
7.60006904602 milliseconds
7.68804550171 milliseconds
7.59100914001 milliseconds
7.66706466675 milliseconds
7.6060295105 milliseconds
7.5900554657 milliseconds
``````

Edit:

I just continued testing to find out if it's the adc or python that makes the difference. So I replaced the range in the for-loop with `range(63, -1, -1)`, effectively reading the inputs in reverse order. For some reason, the numbers are now reversed as well. I.e. the very low delay is now with input 63 and the high delay with input 0. Still no clue why this is though.

Edit 2: Added output excerpts for clarification.

• Without seeing the code and the corresponding output it's difficult to say what you are doing wrong.
– joan
Dec 14 '17 at 20:35
• What other code would you like? This is all the code I'm using. The output is in the form: 6.49785995483 milliseconds. The actual number differentiates as explained in the question Dec 14 '17 at 20:52
• At the risk of repeating myself. Without seeing the code and the corresponding output it's difficult to say what you are doing wrong.
– joan
Dec 14 '17 at 21:00
• I added two examples of output to show what the script exactly outputs. Dec 14 '17 at 21:15
• You are timing the cumulative delay between Sample 1 and Sample 64. You reset `start_time` every cycle of your loop, so this is never Sample 64 to Sample 64 delay Dec 14 '17 at 22:03

You reset the variable `start_time` every outer loop. So you are always timing from the start of reading to your selected sample. It makes sense that the value you get increases

``````while True:
start_time = time() <----- THIS HERE
for i in range(64):
if i == 63:
print(str((time() - start_time) * 1000.0) + " milliseconds")
start_time = time() <---- IMMEDIATELY RESET ON NEXT OUTER LOOP CYCLE
``````

Keep in mind, when thinking about timing. SPI is actually pretty slowly clocked serial data.

Best case scenario for a `32 bit` exchange on `1MHz` , that is `32us` on the wire, meaning the best possible case for that transaction. With Operating System Calls and other delays its likely much more than that. You are seeing `132us` which is reasonable

If you have 64 samples, this means you will have approximately `~2ms` total time of bits on the wire. Using your data it is probably more like `~10ms` which is what you are seeing.

Then add on top of that, inconsistent scheduling. Everytime you have a call to the kernel (`ioctl` with spi read) your thread will reschedule, which, if the system is particularly loaded, will cause even more jitter.

• Thanks for the elaboration and the comment on timing. Is there any way I can get faster results? Such prioritizing this process somehow or something else. 10ms is probably too much for my application (audio) Dec 15 '17 at 0:33
• @RienHeuver you can probably get some improvement, but its a fundamental limitation of a serial bus like SPI and using multiplexing instead of parallel ADCs. In the best case, at `10MHz` is `100ns` per bit on the wire, or `200us` absolute best case to read 64 channels of 32 bits ignoring all overhead, so estimate `1ms` real delay . Commercial designs will use multiple ADC's with dedicated sampling controllers/ASICs which is why pro audio equipment can be very expensive You may find some useful information in my lengthy rant/answer here Dec 15 '17 at 0:53
• Keep in mind, that using this approach you are heavily loading your system with a polling loop, even with 4 cores you will likely experience hiccups when the system is loaded with other software. To get further improvement, besides hardware, you will probably need to look at real time operating systems or a dedicated kernel driver to squeeze more performance. This is not a trivial problem. To get audio quality, i.e. 44KHz (aka `22us` total) sampling, is simply not possible with a multiplexed design. Dec 15 '17 at 0:56