Serial port latency

Today I noticed some unexpected delays between state transitions. Although these delays were relatively small (tens of milliseconds), they were troubling for two reasons:

• We aren't doing anything particularly intensive on the arduino yet, so why would it be delayed? Since the arduino runs at 16MHz, we have 16000 clock cycles per ms. This should be plenty for everything we're doing now.
• Down the road, we'll want to ensure we have maximal temporal precision. <1ms would be nice. I suspect this will be a recurring issue, so I wanted to get some practice dealing with it.

Here's the specific case in which the delays occurred. To deliver rewards to the subject, we use two states:

• START_REWARD : a digital output is activated to open a solenoid valve. Also, we note the current time and add 40 ms to it. Call this the "timer". Go to REWARD_TIMER.
• REWARD_TIMER : Check the time. If it's greater than or equal to the timer, close the valve and go on to the next state. Otherwise, keep looping through this state.

Each loop through REWARD_TIMER should be pretty quick, since all we have to do is check the time and compare it to the timer. <1ms precision seems very doable here.

But here's the results I was getting. These are the lines taking from "ardulines". The states are numbered instead of named in this output. START_REWARD is state 5 and REWARD_TIMER is state 7.

...

TRIAL OUTCOME HIT

3521 STATE CHANGE 1 3

3523 EVENT REWARD_L

DEBUG reward timer 3563

DEBUG reward timer 3563

DEBUG reward timer 3563

3523 STATE CHANGE 3 5

3644 STATE CHANGE 5 7

3668 STATE CHANGE 7 8

...

Let me walk you through it.

1. A correct trial ("hit") occurs
2. Time 3521ms: the state changes into START_REWARD
3. Time 3523ms: we reach START_REWARD, and this event is announced
4. I added the debug announcement while investigating this issue. It prints out the value of the timer: 40ms plus the beginning of START_REWARD, or 3563ms, as expected. I repeated the debug announcement 3 times for test purposes (see below).
5. Time 3644ms: We transition from START_REWARD (state 5) to REWARD_TIMER (state 7).

Why did that happen at 3644ms instead of 3563ms? That's like 80ms late! That's an eternity even for an 16MHz CPU. It's also screwing up the time that our valve is open and therefore the reward amounts.

Moreover, I noticed that repeating the DEBUG announcement 3 times increased the latency to the state change. This hinted that the problem was in the Serial.println function.

But the documentation for Serial.print clearly states that Serial.print is non-blocking! That means that the Arduino should have continued processing state changes, even if the serial writes were slow.

Well, as it turns out, the serial writes are stored in a buffer which is only 64 bytes long (an amount I consider to be ridiculously small). Once this buffer is full, the Serial.print function becomes blocking: it does nothing until the buffer has been emptied. I strongly feel this should have been documented!

So what to do? As a short-term solution, I increased the baud rate to the maximum allowable: 115200 baud (characters per second). At the default setting of 9600 baud, transmitting 100 characters takes 10.4 ms, plus probably some start/stop overhead. At the higher setting, it should take only 0.9ms. Hopefully it can empty the buffer before the next announcement is made.  

In fact this works quite well:

TRIAL OUTCOME HIT

3584 STATE CHANGE 1 3

3586 EVENT REWARD_L

DEBUG reward timer 3626

DEBUG reward timer 3626

DEBUG reward timer 3626

3586 STATE CHANGE 3 5

3627 STATE CHANGE 5 7

The state change is now supposed to occur at 3626 ms and it occurs at 3627 ms. Not bad.

Another workaround is to increase the size of the serial buffer, but this looks relatively complex.

One conclusion here is that my serial messages should be as short and infrequent as possible, to avoid overflowing the buffer. Okay, I can make them shorter by abbreviating the messages (SC instead of "STATE CHANGE", for instance). But at some point we may have quite a lot of messages to transmit (every single one of the subject's touches, for instance). We may run into a fundamental limitation of the arduino, or really its serial port.

More generally, this is one of the reasons why real-time operating systems exist. If the solenoid is supposed to be open for 40ms, I want a guarantee that it will be open for exactly that long! RTOSs are designed for this purpose, but the arduino is not. Even worse, the addition of debugging information can change the latencies! 

Nonetheless, with careful programming I think we should be able to satisfy a reasonable tolerance (<2ms) most of the time (>99%), and hopefully detect any failures when they occur.