Requested timestamp is in the past error

[wpats]

Hi,

I have the following code snippet to get the current timestamp (after I do a retune) and schedule a receive at this timestamp. My understanding is that the timestamp in the sample buffers will be before the current one and I want to discard those and only want those from the current timestamp (after the retune). However this code always results in the "timestamp is in the past" error. Even if I increment the current timestamp value by sample rate I get the same error:

Code: Select all

  struct bladerf_metadata metadata2;
  memset(&metadata2, 0, sizeof(metadata2));
  status = bladerf_get_timestamp(this->m_dev, 
                                 BLADERF_MODULE_RX, 
                                 &metadata2.timestamp);
  HANDLE_ERROR("Failed to get current RX timestamp: %s\n");
  fprintf(stderr, "Current RX timestamp: 0x%016lx ", metadata2.timestamp);

  // Schedule for  1 second in the future.
  metadata2.timestamp += this->m_sampleRate;
  fprintf(stderr, " 0x%016lx ", metadata2.timestamp);
  metadata2.flags = 0;

  /* ... Handle signals at current frequency ... */
  status = bladerf_sync_rx(this->m_dev,
                           sample_buffer,
                           this->m_sampleCount,
                           &metadata2,
                           0);
                             
  fprintf(stderr, " 0x%016lx\n", metadata2.timestamp);
  HANDLE_ERROR("Failed to receive samples at %u Hz: %%s\n", 
               this->m_frequencies[this->m_frequencyIndex]);

So I've had to resort to call sync_rx in a loop with the BLADERF_META_FLAG_RX_NOW flag and loop until I get the desired timestamp:

Code: Select all

  struct bladerf_metadata metadata2;
  memset(&metadata2, 0, sizeof(metadata2));
  status = bladerf_get_timestamp(this->m_dev, 
                                 BLADERF_MODULE_RX, 
                                 &metadata2.timestamp);
  HANDLE_ERROR("Failed to get current RX timestamp: %s\n");
  fprintf(stderr, "Current RX timestamp: 0x%016lx ", metadata2.timestamp);

  metadata = metadata2;
  metadata2.flags = BLADERF_META_FLAG_RX_NOW;

  /* ... Handle signals at current frequency ... */
  while (true) {
    status = bladerf_sync_rx(this->m_dev,
                             sample_buffer,
                             this->m_sampleCount,
                             &metadata2,
                             0);
                             
    fprintf(stderr, " 0x%016lx\n", metadata2.timestamp);
    HANDLE_ERROR("Failed to receive samples at %u Hz: %%s\n", 
                 this->m_frequencies[this->m_frequencyIndex]);
    if (metadata2.timestamp >= metadata.timestamp) {
      break;
    }

This works fine. But I don't understand why the initial version doesn't.

Thanks for any help,

--Patrick

[jynik]

Hi Patrick,

Nothing in your general approach is jumping out at me as incorrect; this should work. In fact, I have done some frequency hopping applications using this same approach.

Could you share the following?

• A log with libbladeRF set to its DEBUG log level. There's a debug message that should get printed to tell us what the last timestamp libbladeRF saw is, such that it thinks your requested timestamp is in the past.
• A complete program to reproduce this. Since nothing jumped out at me, I'm thinking something elsewhere in the code might be responsible...

Just curious, does the libbladeRF_example_sync_rx_meta program (built when CMake is provided -DBUILD_LIBBLADERF_DOC_EXAMPLES=ON), work for you? I suspect you've already taken a look at that, but it might be a good sanity check.

Best regards,
Jon

[jynik]

Just another note... when debugging timestamp code, it was quite helpful for me to enable the verbose log messages within the sync.c code. This can be done via the CMake option ENABLE_LIBBLADERF_SYNC_LOG_VERBOSE=Yes. This is defaulted to OFF, as it will generate quite a bit of output.

[wpats]

Hi Jon,

I tried building the examples and found that the libbladeRF_example_sync_tx_meta works just fine. As far as I can tell I am doing the same sequence of API calls as that but I get the error. I'm not sure how the set the DEBUG log level. I ran cmake with -DENABLE_LIBBLADERF_SYNC_LOG_VERBOSE=Yes and built but that did not produce any output.

I have attached a tar file with reduced repro program. It includes a Makefile and a run_scan script which should repro the problem.

Thanks for helping me debug this,

--Patrick

[jynik]

Hi Patrick,

You can set the log level via bladerf_log_set_verbosity(), providing one of these enum values. Alternatively, you can set the BLADERF_LOG_LEVEL environment variables, as described on this page.

While looking at your code and our example code, I noticed a timestamp increment in our code did not match the comment. I've addressed this and tried to clean things up here in this commit. I sincerely apologize for that and any inconvenience and confusion it caused you.

I also think I see what the problem is. If I'm correct, it would be good to figure out how we can better articulate this in the documentation; you feedback here would be very helpful.

It looks like you're trying to read the hardware timestamp counter every time you want to receive samples, and then schedule an RX 1ms into the future. (Note that samplerate/100 is actually 10ms, however).

However, bladerf_get_timestamp() only gives you a very coarse timestamp counter estimate. Upon this request reaching the FPGA...

• The timestamp value is read by the NIOS II in the FPGA
• This value is communicated from the NIOS II back to the Cypress FX3 over a 4Mbps UART
• Once received by the FX3, this value is packed into the response of a USB control transfer (a vendor request)
• This value is read from the host and returned from the API call

As you could guess, there's quite a bit of latency here, with a lot of it being introduced by that slow UART interface. All the while, the FPGA timestamp counter has kept on ticking.

Therefore, we really don't want to be using this API call once we're streaming samples; the RX metadata gives us an accurate timestamp count that we can trust. We can, however, use bladerf_get_timestamp() as a means to get an initial frame of reference to begin streaming our data. We can simple increment the metadata.timestamp field accordingly after that.

I've reworked this example a bit to hopefully show this a bit better:

• On lines 185 and 188, we compute 150 ms and 1 ms increments, in units of timestamp ticks.
• On line 197 we read the timestamp to get our initial frame of reference
• On line 206 we advance this timestamp by 150 ms. In reality, this timestamp counter value is now less than 150 ms due to the aforementioned latency. However, once we've got our first read, we're locked in and should be able to sample accurately at the desired timestamps. 150ms may certainly be overkill, but it's short enough to not induce an unacceptible startup delay to a user in many cases.
• On line 211 our first reception occurs
• On line 231 we update the timestamp for the next read. We schedule it to be 1ms after the last sample we read.
• Looping around to 211 again, we can confirm that we got our read at exactly the time we specified.

Hopefully, this makes a bit more sense. If not, let me know.

The beauty of this is that once you're sampling at specific timestamps, you can synchronize this to your retunes (via bladerf_schedule_retune()).

The basic idea is exemplified by the following pseudo-code:

Code: Select all

let ts_inc_1ms = samplerate * 5 / 1000;
let ts_inc_150ms = 150 * ts_inc_1ms;

# Set up our frame of reference - set up our first RX ~150 ms in the future
t = bladeRF_get_timestamp(...);
t += ts_inc_150ms;

while not done:
    RX N samples at timestamp t;

    # Schedule a retune in 1ms
    t += N + ts_inc_1ms
    bladerf_schedule_retune(..., t, ...)

   # Schedule the next read 1ms after that
   t += ts_inc_1ms
end
 

To take things even a step further... there FPGA's retune queue is 16 elements deep, IIRC. Therefore, if you know you the relative intervals at which you want to retune and schedule your RX's using this knowledge, you could queue up a few of your retunes up in advance. (For example, if you were writing a frequency hopping application, you could schedule the first few hops within a message.) The advantage of doing this is that you could sneak the enqueue of a future retune into the "dead time" between one RX and another, instead of waiting for the retune to happen and finish.

I've thrown quite a bit at you, I know. I hope this will get you back on track, and if not, I'll do my best to help.

Have a happy and safe holiday season!
- Jon

[jynik]

Hey Patrick,

I just wanted to check back in with you, as it's been a while since our last discussion on this thread.

Did the scheduled retuning approach I provided here make sense? This approach will yield vastly faster "sweep" times than the following:

Code: Select all

while (not done) {
   bladerf_set_frequency(f);
   bladerf_get_timestamp(..., &meta.timestamp)
   bladerf_sync_rx(..., meta.timestamp)

Cheers,
Jon