[Tinyos-devel] Testing FTSP
Branislav Kusy
kusy at stanford.edu
Tue Aug 12 15:20:07 PDT 2008
hi all,
i did some testing - summarized it briefly at
http://docs.tinyos.net/index.php/PacketTimeStamp_CC2420_bug
please take a look. in short, the problem is in CC2420's implementation
of PacketTimeStamp interface which provides FTSP with incorrect
timestamps for possibly long periods of time (minutes). there seems to
be a bug in how cc2420 radiostack maintains timestamps on the receiver
side. i'm not sure where exactly the bug is - but it seems that the FIFO
that keeps rx timestamps in CC2420ReceiverP can get shifted under high
message load and then takes a while to reset.
i'll try to figure out how to fix this. i'm sure there are people who
understand the radio stack better than i - would be great if you could
take a look.
brano
Omprakash Gnawali wrote:
> On Tue, Jul 29, 2008 at 8:38 PM, Branislav Kusy <kusy at stanford.edu> wrote:
>> Omprakash Gnawali wrote:
>>> On Tue, Jul 29, 2008 at 11:11 AM, Branislav Kusy <kusy at stanford.edu>
>>> wrote:
>>>> Omprakash Gnawali wrote:
>>>>> On Tue, Jul 29, 2008 at 9:58 AM, Branislav Kusy <kusy at stanford.edu>
>>>>> wrote:
>>>>>>>> these results are really bad, there should be no red crosses after
>>>>>>>> the
>>>>>>>> initial synchronization period (first 40-50 seconds). is there a way
>>>>>>>> to
>>>>>>> Agree.
>>>>>>>
>>>>>>>> re-run the experiment (first 500s would be enough) while logging the
>>>>>>>> whole
>>>>>>>> debug struct(test_ftsp_msg_t)? could i also see the deployment map?
>>>>>>> Just so I understand this, I am dividing these attributes into useful
>>>>>>> and not useful (log trigger is a periodic timer in my experiment).
>>>>>>> Please let me know if you agree:
>>>>>>>
>>>>>>> Not useful:
>>>>>>> report->counter = rcm->counter;
>>>>>>> report->local_rx_timestamp = rxTimestamp;
>>>>>>> report->global_rx_timestamp = rxTimestamp;
>>>>>> looking at the counter vs the local time is very useful in finding out
>>>>>> problems in timestamping (code that records time deep in the MAC layer,
>>>>>> after receiving SFD interrupt). so i'd include this data as useful.
>>>>> Isn't this counter the count value in RadioCountToLeds pkt? If so, I
>>>>> don't have this information because I don't run RadioCountToLeds. I
>>>>> trigger logging using a periodic timer.
>>>>>
>>>>> ...
>>>>>
>>>>>> would be a problem. increasing timesync period could be a solution? but
>>>>>> first, it would be very useful to see the local time vs counter graph -
>>>>>> there used to be a bug in radio stack which would cause wrong
>>>>>> association
>>>>>> between incoming radio packets and SFD interrupts (timestamps are
>>>>>> buffered
>>>>>> in a FIFO in CC2420ReceiveP.nc). i haven't seen it in rc3 testing
>>>>>> (about
>>>>>> 20
>>>>>> micaz motes running for an hour, single hop), but i'd just like to make
>>>>>> sure
>>>>>> before we start tweaking ftsp.
>>>>> Maybe we are talking about two different counters?
>>>> i see - you are right. localtime and counter are not useful in this case.
>>>> let's just see the useful data you proposed. actually, maybe add the
>>>> global
>>>> time (it can happen that is_synced is 0 and global time is crap). global
>>>> time won't tell us much about accuracy (you trigger it from a timer), but
>>>> we'll at least see if the error is large (e.g. couple of 10s of seconds).
>>>>
>>> Here is the structure that I log every 4 s:
>>> typedef nx_struct compact_test_ftsp_msg
>>> {
>>> nx_uint32_t local_time;
>>> nx_uint32_t global_time;
>>> nx_uint8_t is_synced;
>>> nx_uint16_t ftsp_root_addr;
>>> nx_uint8_t ftsp_seq;
>>> nx_uint8_t ftsp_table_entries;
>>> } compact_test_ftsp_msg_t;
>>>
>>> Here is the code:
>>>
>>> event void Timer.fired() {
>>>
>>> compact_test_ftsp_msg_t* report =
>>> (compact_test_ftsp_msg_t*)call Packet.getPayload(&uartmsg,
>>> sizeof(compact_test_ftsp_msg_t));
>>>
>>> uint32_t rxTimestamp = call GlobalTime.getLocalTime();
>>>
>>> report->local_time = rxTimestamp;
>>> report->is_synced = call GlobalTime.local2Global(&rxTimestamp);
>>> report->global_time = rxTimestamp;
>>> report->ftsp_root_addr = call TimeSyncInfo.getRootID();
>>> report->ftsp_seq = call TimeSyncInfo.getSeqNum();
>>> report->ftsp_table_entries = call TimeSyncInfo.getNumEntries();
>>>
>>> call UARTSend.send(0xffff, &uartmsg,
>>> sizeof(compact_test_ftsp_msg_t));
>>> }
>>>
>>> Here is the URL to the log from all the nodes:
>>> http://enl.usc.edu/~om_p/net2/test-ftsp/run3.tar.gz
>>>
>>> And here is a graph that shows sync/desync status of the network
>>> during this experiment:
>>> http://enl.usc.edu/~om_p/net2/test-ftsp/ftsp_result3.gif
>> the data looks terrible - the worst i've ever seen, actually :).
>>
>> i think the timestamping is screwed up - i looked at global time differences
>> for consecutive lines in your log - global time should increase by 4096 +-
>> timestamping error for consecutive firings, since timer goes off every 4
>> seconds. i looked at direct neighbors of node 1 (nodes 2 and 8). e.g. log8:
>> first 45 values are ok, but after receiving timesync message from node 1
>> (seqnum 86), the global time actually decreases by -30473. after that the
>> timing is messed up until seqnum 235. i don't see any other reason then the
>> rx timestamp of message 86 being wrong - node 8 had a full table of valid
>> entries and it received the new timesync message in time directly from the
>> root. the pattern repeats: it works well for a while and then is totally
>> messed up for a while...
>>
>> it should be quite easy to come up with a smaller scale experiment where
>> this shows up. it'd be enough to look at receiver timestamps (local clock),
>> bypassing ftsp completely. maybe just two nodes, one is sending messages
>> from a fast timer, the other one logs received timestamps. perhaps a few
>> other nodes would be needed to generate interfering traffic. i can look at
>> it sometime next week.
>>
>
> Just to give you one more dataset with less external traffic (channel
> 16 instead of 26 which was being used heavily earlier).
>
> Graph: http://enl.usc.edu/~om_p/net2/test-ftsp/ftsp_result4.gif
> Log: http://enl.usc.edu/~om_p/net2/test-ftsp/run4.tar.gz
>
> This is better than the earlier data but similar to the one we saw last night.
>
> Thanks.
>
> - om_p
> _______________________________________________
> Tinyos-devel mailing list
> Tinyos-devel at millennium.berkeley.edu
> https://www.millennium.berkeley.edu/cgi-bin/mailman/listinfo/tinyos-devel
More information about the Tinyos-devel
mailing list