[Tinyos-devel] ctp vs other radio clients

[Omprakash Gnawali]

On Tue, Oct 28, 2008 at 9:58 AM, Philip Levis <pal at cs.stanford.edu> wrote:
>
> On Oct 27, 2008, at 11:16 PM, Omprakash Gnawali wrote:
>
>> BTW, SUBSEND_BUSY turns out is not rare and it is not obvious why this
>> happens just looking at the log. Here is an example:
>>
>> 1196564165.570171: NET_C_FE_SENDDONE_WAITACK 52 163 6 9448 0
>> 1196564165.570287: NET_C_FE_RCV_MSG 37 154 43 9449 0
>> 1196564165.570384: NET_C_FE_SEND_BUSY = 0x19 9450 0
>> 1196564165.570492: NET_C_FE_SENDDONE_WAITACK 52 163 6 9451 0
>> 1196564165.592724: NET_C_FE_RCV_MSG 14 164 17 9452 0
>> 1196564165.657187: NET_C_FE_FWD_MSG 52 163 6 9453 0
>> 1196564165.657448: NET_C_FE_RCV_MSG 40 154 21 9454 0
>> 1196564165.780492: NET_C_FE_SENDDONE_WAITACK 37 154 6 9455 0
>> 1196564165.780754: NET_C_TREE_NEW_PARENT 30 9456 0
>> 1196564165.780889: NET_C_FE_SEND_BUSY = 0x19 9457 0
>> 1196564165.811205: NET_C_FE_SENDDONE_WAITACK 37 154 30 9458 0
>> 1196564165.811484: NET_C_FE_SENDDONE_WAITACK 37 154 30 9459 0
>> 1196564165.922115: NET_C_FE_SENDDONE_WAITACK 37 154 30 9460 0
>> 1196564165.946090: NET_C_FE_RCV_MSG 46 160 9 9461 0
>> 1196564165.946232: NET_C_FE_LOOP_DETECTED 46 160 12 9462 0
>> 1196564165.946330: NET_C_TREE_SENT_BEACON 30 0 124 9463 0
>> 1196564165.946486: NET_C_FE_RCV_MSG 46 160 9 9464 0
>> 1196564165.946599: NET_C_FE_DUPLICATE_QUEUE 9465 0
>> 1196564165.989108: NET_C_FE_RCV_MSG 46 160 9 9466 0
>> 1196564165.989254: NET_C_FE_DUPLICATE_QUEUE 9467 0
>> ************ 1196564165.989353: NET_C_FE_SUBSEND_BUSY 9468 0 <===
>> 1196564165.989466: NET_C_FE_SENDDONE_WAITACK 37 154 30 9469 0
>> 1196564166.99127: NET_C_FE_RCV_MSG 16 162 3 9470 0
>> 1196564166.227916: NET_C_FE_SEND_BUSY = 0x19 9471 0
>> 1196564166.228043: NET_C_FE_SENDDONE_WAITACK 37 154 30 9472 0
>> 1196564166.228142: NET_C_TREE_NEW_PARENT 46 9473 0
>> 1196564166.228240: NET_C_FE_SENDDONE_WAITACK 37 154 46 9474 0
>> 1196564166.228339: NET_C_FE_RCV_MSG 16 159 24 9475 0
>> 1196564166.228482: NET_C_FE_LOOP_DETECTED 16 159 12 9476 0
>> 1196564166.228482: NET_C_FE_LOOP_DETECTED 16 159 12 9476 0
>> 1196564166.228583: NET_C_TREE_SENT_BEACON 46 0 128 9477 0
>> 1196564166.228682: NET_C_FE_RCV_MSG 49 169 4 9478 0
>> 1196564166.228793: NET_C_FE_SENDDONE_WAITACK 37 154 46 9479 0
>> 1196564166.328579: NET_C_FE_SENDDONE_WAITACK 37 154 46 9480 0
>> 1196564166.328778: NET_C_FE_RCV_MSG 16 161 13 9481 0
>> 1196564166.328924: NET_C_FE_SENDDONE_WAITACK 37 154 46 9482 0
>> 1196564166.380408: NET_C_FE_SENDDONE_WAITACK 37 154 46 9483 0
>> 1196564166.453833: NET_C_FE_SENDDONE_WAITACK 37 154 46 9484 0
>> 1196564166.540293: NET_C_FE_SENDDONE_WAITACK 37 154 46 9485 0
>> 1196564166.540548: NET_C_FE_RCV_MSG 34 155 55 9486 0
>> 1196564166.540674: NET_C_FE_LOOP_DETECTED 34 155 12 9487 0
>> 1196564166.607995: NET_C_FE_SENDDONE_WAITACK 37 154 46 9488 0
>> 1196564166.624631: NET_C_FE_SENDDONE_WAITACK 37 154 46 9489 0
>> 1196564166.624992: NET_C_TREE_NEW_PARENT 7 9490 0
>> 1196564166.650840: NET_C_FE_RCV_MSG 15 162 2 9491 0
>> 1196564166.651039: NET_C_FE_LOOP_DETECTED 15 162 12 9492 0
>> 1196564166.674908: NET_C_TREE_SENT_BEACON 7 0 133 9493 0
>> ************* 1196564166.708980: NET_C_FE_SUBSEND_BUSY 9494 0 <===
>> 1196564166.783057: NET_C_FE_FWD_MSG 37 154 7 9495 0
>> 1196564166.783295: NET_C_FE_FWD_MSG 14 164 7 9496 0
>> 1196564166.807740: NET_C_FE_SENDDONE_WAITACK 40 154 7 9497 0
>> 1196564167.123786: NET_C_FE_FWD_MSG 40 154 7 9498 0
>
> IIRC, this happens when a new packet is submitted from above. I'll try to
> take a look this week. It would be nice to track down this bug.
>

Maybe that is what triggers this bug but in the above trace this
happened less than one second apart while new packets are being
generated in avg. 8 seconds apart. So it is happening at other times
as well.

- om_p