[Tinyos-devel] Testing FTSP

[Branislav Kusy]

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.

brano