[Tinyos-devel] Testing FTSP

[Omprakash Gnawali]

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