Possible bug in RFA1DriverLayerP under high mcu load

[ucolesanti]

It seems that when theAtmega128RFA1 is busy in other tasks (e.g., in my case it has to continously read 800Hz data from an accelerometer and store it in a flash), the radio driver might invert RX_START and RX_END interrupts. The reason seems to be the following: let assume that the mcu is busy in some atomic stuff, then the TRX_RX_START and TRX_RX_END interrupts may occur both before the driver starts to manage the first service routine. However, since both are handled by an AVR_NONATOMIC_HANDLER (i.e., they are interruptible), what I think it happens is the following:

Precondition: both interrupts have already occured

1- the AVR_NONATOMIC_HANDLER(TRX_RX_START_vect) is called first since RX_START has priority over RX_END
2- since sei() is called immediately, the AVR_NONATOMIC_HANDLER(TRX_RX_END_vect) is called immediately after and runs its code: it sets the radioIrq variable with its value and calls a tasklet.schedule()
3- the tasklet is free and calls tasklet.run()
4- tasklet.run() manages the interrupt (serviceRadio()) as RX_END but it ignores the event since it is not in cmd=CMD_RECEIVE state
5- when the tasklet.run() finishes, the AVR_NONATOMIC_HANDLER(TRX_RX_START_vect) resumes its execution and sets the radioIrq as RX_START
6- again the tasklet.run() is called and runs serviceRadio() managing the RX_START, the driver set its command as cmd=CMD_RECEIVE
7- it locks in this state since there will be no RX_END events. It will eventually unlock if a new RX_START is detected.

It is just an intuition since I observed several times RX_START events without RX_END and in all these cases I noticed an RX_END triggered just before without a corresponding RX_START.
The problem is present in tinyos 2.1.2 release but I think it still persists in tinyos-main. I think I solved the problem by changing RX_START and RX_END handlers from AVR_NONATOMIC_HANDLER to AVR_ATOMIC_HANDLER and by calling __nesc_enable_interrupt() just before calling Tasklet.schedule(). I noticed that with this small change, serviceRadio() started to manage several radioIrq with a value of 48 which corresponds to RX_START and RX_END that both occured (never happened with the old code). I also added a new if statement for the timestamp with the following:
if(irq == (IRQ_RX_START | IRQ_RX_END)){
call PacketTimeStamp.set(rxMsg, time);
}

Btw, if you think that my analysis is correct and the workaround too, I can make a pull request.
Let me know,

Ugo

[ucolesanti]

I wrote an additional test to demonstrate this buggy behavior:
I used a transmitter that sends a single packet after 5 seconds (LPL disabled) and a receiver that toggles a led on upon the reception of that packet. If I add to the receiver an atomic section, after radio starts, that keeps the mcu busy for more than 5 seconds then, after I switch on both nodes simultaneously, the packet will be missed by the receiver. Using some diag messages in service radio, it is possible to note that serviceRadio will be called twice, but with TRX24_RX_STOP managed before TRX24_RX_START, leading to the packet loss.
If I switch the AVR_NONATOMIC_HANDLER to AVR_ATOMIC_HANDLER and I add __nesc_enable_interrupt() just before the call to Tasklet.schedule() and if I repeat the experiment, the packet is correctly received and diagmsg will show a single serviceRadio with radioIrq having both flags, TRX24_RX_START and TRX24_RX_STOP, set. This is the expected behavior I think.
Hope it helps,

Ugo