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.

A simple behavioral protocol

Let's put together the tools we have so far and build a complete behavioral protocol. This is for an early phase of behavioral shaping, in which all a subject has to do is activate a touch sensor, after which he will immediately receive a reward. We also want the ability to give rewards at arbitrary times, even when the subject has done nothing.

Here's what will be running on the computer:

1) The chat interface. This receives input from the Arduino over the serial port and immediately writes it to a file on disk. Let's call this file 'ardulines'. Also, it checks a pipe, called 'TO_DEV' for any input from the user/experimenter, and sends it to the Arduino.

2) Another terminal which allows the user/experimenter to write to the pipe TO_DEV. This is the same pipe that is checked by the chat interface; anything written to it is sent to the Arduino. This is how the user/experimenter can signal the delivery of a reward at an arbitrary time.

3) A graphical display script which reads all of the text in ardulines, parses it, and displays the progress of the subject graphically.

I've intentionally separated the chat interface from everything else. That's because we want this to keep running even if something else, like the graphical display, crashes. We also want it to keep ardulines constantly updated with the latest info from the Arduino. Thus, in the worst case when everything crashes, we'll have all of the data from the session.

Later it might be nice to combine scripts 2 and 3, so that the user can both view the progress of the subject and send new signals to the Arduino within the same environment. Let's keep it simple for now though.

Here's what will be running on the Arduino:

The sketch will implement the chat receiver from last time, to catch text coming from the computer (such as user commands). It will also contain a simple state machine that goes through the following states.

• State 0: Trial start. Send the time to the computer. Go to state 1.
• State 1: Wait for input. If subject touches the sensor, or if the text 'REWARD' is received from the computer, go to State 1. Otherwise stay in State 0.
• State 2: Deliver reward. Open the reward valve. Start a reward timer. Go to state 3.
• State 3: Wait until reward timer reaches desired value. Close the valve. Go to State 0.

The nice thing about state machines is that it's very clear what the inputs and outputs are supposed to be in each state, as well as when to transition. That makes debugging easier.

The waiting state 3 is an example of how to avoid delay commands in the Arduino. Instead, we should aim to call loop() as often as possible, even if we do nothing on most of the calls. That way, our other code (such as receiving chats) will still run; if we had used delay, then nothing would happen until the delay was over.

The code

All of the code is available in the LickTrain directory on the ArduFSM project on github. I'll also include snippets here to explain them.

The chat.py module incorporates the chatting functions that I discussed in previous postings, as well as the logic relating to ardulines and TO_DEV pipe.

On the Arduino side, there are a couple of modules -- chat.cpp and mpr121.cpp -- that handle the chat receiving and the touch sensor, respectively. Thanks to Jim Lindblom and SparkFun for providing the MPR121 code!

Here is the loop() function in the main sketch that implements the state machine:

Here is a script, main1.py, which I use to start and run the chatter:

In operation!

I used this to run an experiment. Here's a screen shot:

Here's what's going on:

• Upper right terminal: this is an IPython instance running main1.py, shown above. In addition to writing out ardulines and polling TO_DEV, it is also echoing everything to the terminal as a simple text-based readout of what's going on.
• Lower right terminal: here's where I can write the string "REWARD" to TO_DEV whenever I want to send a reward manually, as opposed to the automatic rewards that the state machine delivers after touches.
• Lower left terminal: another ipython instance where I'm running a simple graphical display script, shown on the upper left. This script parses ardulines and can display graphs based on the events it reads. In this case there is not much to display, so I'm simply creating a histogram over time of rewards. I'd like to have t

Next steps

There's a few user-interface niceties to take care of. It would be nice to have the graphical display script run continuously, so I don't have to update the graph manually. 

I'd like to standardize the text output from the arduino a bit more. Essentially we are creating a communication protocol. Ideally we'd be able to send asynchronous commands (like REWARD) to the Arduino, as well as set parameters (like the inter-trial interval) on the fly so that we don't need to hard code them in the sketch. Conversely, the Arduino should report on everything it is doing (like state changes, touches detected) so that they can be written to ardulines in a standardized format.

Probably most important is creating a more complex state machine, one that implements a standard two-alternative choice psychological paradigm, so that we can study more interesting behaviors.