Odd I2C receive timing issue.

Created Mon, 11 Jul 2016 15:13:16 +0000 by photomankc

photomankc

Mon, 11 Jul 2016 15:13:16 +0000

In trying to work around the fact that i2c writes interrupt for every byte rather than when the transmission stops I've created a class to track the bytes of a packet as they come in and buffer them. In case we don't get all the bytes and to avoid perpetually waiting on that missing byte it implements an expiration on a incomplete message.

What I keep running into is a strange issue where every few events, the last byte does not seem to generate an interrupt and remains in the Wiring buffer. My command message then expires because a byte is missing. Then when the next message is sent the missing byte from the previous message is the first byte read on the interrupt. This blows things up until yet another message is received and properly processed.

In trying to diagnose it I added print statements to print the bytes on each interrupt. The code then executes perfectly. I can't create a failure. Then when I remove the print statements the symptoms return. Suspecting it was the delay caused by the print statement I inserted some microseconds of delay before reading the Wiring buffer. This was successful when I added 90 microseconds of delay. Once that is added the symptoms stop and I get no more expired messages. However adding over a millisecond of delay to read 12 bytes seems stupid and I don't understand why it would become needed? I'm open to there being an issue in my packet object but I'm lost as to how adding 90 microseconds of the delay before Wire.read() would make what I do happen differently.

Wire.begin(I2C_ID);
  Wire.onReceive(receiveEvent);
  Serial.begin(115200);

....

void receiveEvent(int howMany)
{
    delayMicroseconds(90);
    
    int d = Wire.read();

    if (g_command.getCommand() == 0)
    {
      g_command.setCommand(d);
    }
    else
    {
      g_command.addByte(d);
    }
}

As you see there is not much to the handler. We always read the 1 byte that generates the interrupt, then one of two things is done. If this is the first byte in a new command then we set the command, otherwise it goes into the command data array and that's pretty much it from the event handler perspective.

What I see without the delay added is: This repeats with random numbers of properly handled messages in between, numbers are HEX.

ec [40][1|2|3|4|5|6|7|8|9|A|B] (Indicates echo command. Properly handled command to echo the bytes received) x [40][1|2|3|4|5|6|7|8|9|A] (Expired command. A cmd has 12 bytes, command included and the last byte takes > 3ms to get) bc [B] (indicates bad command. A command without a handler in the loop switch statement)
bc [2] (incoming bytes get interpreted as 'quick' commands, cmds lower than 0x14 with no other data, but not yet handled) bc [5] (and the numbers depend on how many bytes get jammed into the data array before the next loop executes) bc [9] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] x [40][1|2|3|4|5|6|7|8|9|A] bc [B] bc [1] bc [6] bc [A]

That seems to suggest that the bad command is really the final byte of the expired command before it but for some reason I was never interrupted to read that byte until the next command takes place.

With the delay added I get this forever: ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B] ec [40][1|2|3|4|5|6|7|8|9|A|B]

Frustrating. Honestly at this point I wonder if I can't simply just poll for I2C data. Interrupt receiving on the ChipKit is a mess.

photomankc

Mon, 11 Jul 2016 15:35:43 +0000

Here is what CommandPacket (g_command) looks like:

#ifndef i2cpacket_h
#define i2cpacket_h

const uint8_t PACKET_SIZE      = 12;    // Data transmission size
const uint8_t TIMEOUT          = 3;     // Millis incomplete packet expires
const uint8_t ECMD_HALT        = 0x0A;  // Express command to stop
const uint8_t CMD_TURN45R      = 0x0B;
const uint8_t CMD_TURN45L      = 0x0C;
const uint8_t CMD_TURN90R      = 0x0D;
const uint8_t CMD_SHOW_VERSION = 0x0F;
const uint8_t CMD_FORWARD_STP  = 0x14;
const uint8_t CMD_REVERSE_STP  = 0x15;
const uint8_t CMD_TURN         = 0x16;
const uint8_t CMD_FORWARD_IN   = 0x17;
const uint8_t CMD_REVERSE_IN   = 0x18;
const uint8_t CMD_ECHO_BYTES   = 0x40;  // Echos all data back onto the bus


class CommandPacket
{
  protected:
    uint8_t  m_command;
    uint32_t m_startTime;
    uint8_t  m_bytesNeeded;
    uint8_t  m_dataIndex;
    int8_t   m_eod;
    uint8_t  m_data[16];
    
  public:
    CommandPacket();
    void setCommand(uint8_t cmd);
    void addByte(uint8_t d);
    void addWord(uint16_t d);
    void addDWord(uint32_t d);
    
    uint8_t  getCommand();
    uint8_t  getLength();
    uint8_t  getByte();
    uint16_t getWord();
    uint32_t getDWord();

    void resetIndex(uint8_t index=0);
    void clear();
    int  isComplete();
    int  isExpired();
};


/** @brief Create a new CommandPacket object
 *
 */
inline CommandPacket::CommandPacket()
{
  this->clear();
}


/** @brief Set the command byte and mark the time.
 *
 * @param uint8_t cmd: The command byte (first byte transmitted)
 */
inline void CommandPacket::setCommand(uint8_t cmd)
{
  if (cmd > 0 and cmd < 0x14)
  {
    m_command = cmd;
    m_startTime = millis();
    m_bytesNeeded = 0;
  }
  else if (cmd > 0x13 and cmd < 0x41)
  {
    m_command = cmd;
    m_startTime = millis();
    m_bytesNeeded = 11;
  }
  else
  {
    m_command = 0;
  }
}


/** @brief Add a byte of data to the packet
 *
 * @param uint8_t d: A byte of data.
 */
inline void CommandPacket::addByte(uint8_t d)
{
  if (m_eod < PACKET_SIZE and m_bytesNeeded)  // If it's within bounds
  {
    m_eod++;            // Advance the end-of-data pointer
    m_data[m_eod] = d;  // Add the data to the buffer
    m_bytesNeeded--;    // Decrement the number of bytes needed
  }
  else
    return;             // If out of bounds return without action
}


/** @brief Add a word of data to the packet.
 *
 * @param uint16_t d: A word of data.
 */
inline void CommandPacket::addWord(uint16_t d)
{
  uint8_t l_byte, h_byte;

  l_byte = d;
  h_byte = (d >> 8);

  this->addByte(l_byte);
  this->addByte(h_byte);
}


/** @brief Add a dword of data to the packet.
 *
 * @param uint32_t d: A dword of data.
 */
inline void CommandPacket::addDWord(uint32_t d)
{
  uint16_t l_word, h_word;

  l_word = d;
  h_word = (d >> 16);

  this->addWord(l_word);
  this->addWord(h_word);
}


/** @brief Get the command byte.
 *
 * @return uint8_t: The command byte.
 */
inline uint8_t CommandPacket::getCommand()
{
  return m_command;
}


/** @brief Get the length of the data for this command
 *
 *  @return uint8_t The data length.
 */
inline uint8_t CommandPacket::getLength()
{
  return m_eod + 1;
}


/** @brief Reset the internal next-byte index to zero (or as desired)
 *
 * @param uint8_t index: The value to set the index to (default is 0)
 */
inline void CommandPacket::resetIndex(uint8_t index)
{
  m_dataIndex = index;
}


/** @brief Return the next data byte in sequence
 *
 *  @return uint8_t: The byte at the next buffer position
 */
inline uint8_t CommandPacket::getByte()
{
  uint8_t result = m_data[m_dataIndex];
  m_dataIndex++;

  if (m_dataIndex > m_eod)
    resetIndex();

  return result;
}


/** @brief Return a word of data from the packet.
 *
 * @return uint16_t: A word of data.
 */
inline uint16_t CommandPacket::getWord()
{
  uint8_t  l_byte, h_byte;
  uint16_t result;

  h_byte = getByte();
  l_byte = getByte();
  result = h_byte;
  result << 8;
  result |= l_byte;

  return result;
}


/**@brief Get a word of data from the packet.
 *
 * @return uint32_t: A dword of data.
 */
inline uint32_t CommandPacket::getDWord()
{
  uint8_t a_byte, b_byte, c_byte, d_byte;
  uint32_t result;

  a_byte = getByte();
  b_byte = getByte();
  c_byte = getByte();
  d_byte = getByte();
  result = a_byte;
  result << 8;
  result += b_byte;
  result << 8;
  result += c_byte;
  result << 8;
  result += d_byte;

  return result;
}


/** @brief Reset all internal data.
 *
 */
inline void CommandPacket::clear()
{
  m_eod = -1;
  m_dataIndex = 0;
  m_command = 0;
  m_startTime = 0;
  m_bytesNeeded = 0;

  for(int i=0; i<16; i++)
  {
    m_data[i] = 0;
  }
}


/** @brief Determine if all bytes have been acquired.
 *
 * @return int: Return 1 if all data has been collected, 0 otherwise.
 */
inline int CommandPacket::isComplete()
{
  // If there is no command then it is incomplete.
  if (!m_command)
  {
    return 0;
  }

  // if there are more bytes needed, it is incomplete.
  if (m_bytesNeeded)
    return 0;
  else
    return 1;
}


/** @brief Determine if the packet receive time has expired.
 *
 *  @return int: Return 1 if the command has expired, 0 otherwise.
 */
inline int CommandPacket::isExpired()
{
  int result = 0;
  int millisNow = millis();
  int millisExpired = m_startTime + TIMEOUT;

  if (m_command and m_bytesNeeded)
  {
    if (millisNow > millisExpired)
    {
      result = 1;
    }
  }

  return result;
}

#endif

photomankc

Tue, 12 Jul 2016 17:53:55 +0000

Here's what I had to do to work around it:

if(g_command.isExpired())
  {
    // If the command expired make one retry to read
    // the final byte
    receiveEvent(1);

    // if still expired then give up on the command
    if(g_command.isExpired())
    {
      Serial.println("x");
      g_result = RES_EXP;
      g_command.clear();
      g_commandByte = 0;
    }
  }
  else if(g_command.isComplete())
  {
    g_commandByte = g_command.getCommand();
  }

If the command expires I call my ISR manually one last time. If there is really one last byte waiting for me then it gets added to the command and a completed command does not expire. Otherwise it is expired and it gets dumped. I changed the ISR to look for available bytes first now so that I don't cram garbage into the command with a return result from read for a byte that's not there.

void receiveEvent(int howMany)
{
  while (Wire.available())
  {
    int d = Wire.read();
    if (g_command.getCommand() == 0)
    {
      g_command.setCommand(d);
    }
    else
    {
      g_command.addByte(d);
    }
  }
}

This solves the 50% expired command rate I was seeing and while a command may take a little longer to come together, the ISR is not burning up my clock cycles in a delay loop. An awful lot of futzing to get structured data off the I2C bus. :|