Odd results when measuring timing

Question

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 Adafruit_MCP3008
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

adc = Adafruit_MCP3008.MCP3008(spi=SPI.SpiDev(SPI_PORT, SPI_DEVICE))

def readInput(i):
    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)
    return adc.read_adc(i//8)

while True:
    start_time = time()
    for i in range(64):
        adc_in = readInput(i)
        if i == 63:
            print(str((time() - start_time) * 1000.0) + " milliseconds")
            print("Read value: " + str(adc_in))
            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
Read value: 389
0.15115737915 milliseconds
Read value: 394
0.138998031616 milliseconds
Read value: 392
0.136852264404 milliseconds
Read value: 391
0.149965286255 milliseconds
Read value: 395
0.142097473145 milliseconds
Read value: 389
0.140905380249 milliseconds
Read value: 393
0.139951705933 milliseconds
Read value: 392
0.1380443573 milliseconds
Read value: 390
0.139951705933 milliseconds
Read value: 394
0.136852264404 milliseconds
Read value: 389
0.137090682983 milliseconds
Read value: 392
0.137090682983 milliseconds
Read value: 392
0.137805938721 milliseconds
Read value: 389
0.135898590088 milliseconds
Read value: 394

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

7.63201713562 milliseconds
Read value: 4
7.57384300232 milliseconds
Read value: 4
7.52806663513 milliseconds
Read value: 4
7.58504867554 milliseconds
Read value: 4
7.65609741211 milliseconds
Read value: 4
7.57813453674 milliseconds
Read value: 4
7.69996643066 milliseconds
Read value: 4
7.60006904602 milliseconds
Read value: 4
7.68804550171 milliseconds
Read value: 4
7.59100914001 milliseconds
Read value: 4
7.66706466675 milliseconds
Read value: 4
7.6060295105 milliseconds
Read value: 4
7.5900554657 milliseconds
Read value: 4

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.

Answer 1

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):
        adc_in = readInput(i)
        if i == 63:
            print(str((time() - start_time) * 1000.0) + " milliseconds")
            print("Read value: " + str(adc_in))
            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.