PacketTimeStamp CC2420 bug

PacketTimeStamp Bug in CC2420 radio chip

Parent Project: FTSP

Related TEP: PacketTimeStamp TEP

Description of PacketTimeStamp

PacketTimeStamp interface provides accurate timestamping of radio messages low in the radio stack (MAC layer). this is required to allow for accurate time-synchronization algorithms built on top of PacketTimeStamp interface.

CC2420 radio chip implementation of PacketTimeStamp uses SFD interrupt for both reception and transmission timestamps. Time difference between the SFD interrupt firing at sender and receiver is less then 1 microsecond, theoretically allowing for sub-microsecond accuracy. To eliminate interrupt handling delays, mote platforms connect capture timer to the SFD interrupt line, recording the timestamp irrespective of when the interrupt is handled in software. MicaZ uses Timer1 (driven by external 32khz oscillator). Telos uses TimerX (driven by xxx).

Timestamps recorded at SFD interrupt are saved in cc2420_metadata_t.timestamp and are not transmitted in the air. Specifically, saving timestamps is done using PacketTimeStamp.set() in tos/chips/cc2420/CC2420TransmitP.nc (TX side) and tos/chips/cc2420/CC2420ReceiveP.nc (RX side). Client application can read this timestamp from Receive.receive() or AMSend.SendDone() events.

One problem is that multiple messages may be received before the client application has a chance reading the timestamp in receive() event. Therefore, CC2420ReceiverP.nc maintains a FIFO buffer for all received timestamps and serves them to the client app as needed.

Bug Description

The bug is related to the FIFO buffer with received timestamps: it seems that sometimes timestamps are not dropped from FIFO, even though the message corresponding message was dropped.

Evidence

Test application: TestPacketTimeStamp DataLogger

Setup: 4 micaz nodes (ids=1,2,3,9) running TestPacketTimeStamp application, 1 micaz running BaseStation

TestPacketTimeStamp: simple app that periodically timestamps and transmits radio messages using PacketTimeStamp<T32khz> (1 jiffy=30.5us); embedding tx timestamps in the transmitted message. when the node receives this message, it timestamps its reception and reports both TX and RX timestamps to the base station. i wrote a simple java app which looks at the timestamps and tries to find inconsistencies. time errors can be found by looking at time offsets of clocks of 2 nodes. these offsets change very little over time - if there is a big jump (ie. more than a few clock ticks), we have a problem. i checked in data as well (1218525201390.tgz), you can call 'java DataLogger 1218525201390.report' to get similar logs as bellow.

Logged Data: i only look at messages transmitted by node 1 and report all errors over 5 jiffies in the logs bellow. i calculate 2 errors: a) RXTX is between receiver and transmitter (ie. using tx and rx timestamps), and b) RXRX error is between 2 receivers who timestamped the same message (ie. using 2 rx timestamps).

the problem is clearly on the rx side: eg. mote 1 transmitted msg 27 and the node 2 timestamped it with a value 337 jiffies (about 10ms) higher than expected according to the transmitter (RXTX err: ids [1->2 ]) and other receivers (RXRX err: ids [1->2,3], RXRX err: ids [1->2,9]). this means that tx timestamp must have been ok (we got RXTX ok: ids [1->9 ] for the same message). node 2's time stays screwed up until msg 110 and than it never reports any error until the end of experiment. in fact, node 2 was reporting wrong timestamps for any transmitter until message 110 (log1_full_rx2_only).

PacketTimeStamp_CC2420_bug_log1_full (all data, tx: node1, rx: all)

PacketTimeStamp_CC2420_bug_log1_errors_only (errors, tx: node1, rx:all)

PacketTimeStamp_CC2420_bug_log1_full_rx2_only (all data, tx: all, rx:node2)