[Discuss-gnuradio] inband timestamp issues

[Ketan Mandke]

My colleague Steve and I have been working with the inband receive
code in an effort to understand how the timestamps work. Specifically,
we have been printing the timestamps from the usrp_rx block while
running test_usrp_inband_2rx.cc in usrp/host/apps-inband. There is
some puzzling behavior that we have observed and unable to explain. We
are operating with a decimation rate of 64 (i.e. a 1 MHz sample rate).

Note, this is using the gnuradio trunk rev 8586, with the
gnuradio/trunk/usrp/ code unchanged except to print timestamp data in
usrp_rx.cc. There don't seem to be any major changes since this revision.

1) Every so often we notice that the timestamp difference between
packets from channel 0 and channel 1 sometimes changes. This change in
timestamp difference is also accompanied by a sudden spike in the
timestamp value followed by about 7 usb_packets with very similar
timestamps. For example, the trace might look like this for a while:

[usrp_rx]: chan 0 received packet len = 504 bytes, ts = 100000, diff = 7802
[usrp_rx]: chan 1 received packet len = 504 bytes, ts = 100262, diff =   262
[usrp_rx]: chan 0 received packet len = 504 bytes, ts = 108064, diff = 7802
[usrp_rx]: chan 1 received packet len = 504 bytes, ts = 108326, diff =   262
....,
where diff = the difference between the current and previous
timestamp; and then we get a sudden jump in the timestamp value:

[usrp_rx]: chan 0 received packet len = 504 bytes, ts = 180640, diff = 7802
[usrp_rx]: chan 1 received packet len = 504 bytes, ts = 511000, diff = 330360
[usrp_rx]: chan 0 received packet len = 504 bytes, ts = 511990, diff =   990
[usrp_rx]: chan 1 received packet len = 504 bytes, ts = 512988, diff =   998
[usrp_rx]: chan 0 received packet len = 504 bytes, ts = 513982, diff =   994
[usrp_rx]: chan 1 received packet len = 504 bytes, ts = 514972, diff =   990
[usrp_rx]: chan 0 received packet len = 504 bytes, ts = 517138, diff = 2166
[usrp_rx]: chan 1 received packet len = 504 bytes, ts = 518128, diff =   990

and then normal operation will resume, but with a new delay between
the two channels:

[usrp_rx]: chan 0 received packet len = 504 bytes, ts = 525170, diff = 7042
[usrp_rx]: chan 1 received packet len = 504 bytes, ts = 526194, diff = 1024
[usrp_rx]: chan 0 received packet len = 504 bytes, ts = 533235, diff = 7041
[usrp_rx]: chan 1 received packet len = 504 bytes, ts = 534258, diff = 1023

This behavior can occur multiple times during the operation of
test_usrp_inband_2rx.cc and results in a new delay offset between the
channels. We noticed that the number of transcient timestamps is
approximately equal to the number of usb_packets that would occupy the
size of the fifo buffers (16Kbits) that feed rx_buffer_inband in the
FPGA code. We think that somehow, the operation of rx_buffer_inband is
stalling which would cause these buffers to fill up and then get
dumped out at once (which might explain the transient behavior above).
Any ideas what might be causing these random jumps in the timestamp?

Although this is a made up trace, it is indicative of the behavior we
have observed. I can send a real trace if anyone feels it is
necessary.


2) Occasionally we see an out of order packet arrive at usrp_rx in the
inband code. This timestamp is usually for a packet that should arrive
sometime in the future. We are clueless as to why this might be
happening.

This seems to happen 1 in every 5k-10k usb_packets.

--
Ketan Mandke