tx_timed_samples.cpp with float timespec creates LATE errors

[mmatthebi]

Issue Description

I found a weird behaviour in setting the time_spec for a burst transmission in the future. I modified the tx_timed_samples.cpp example, where i changed the type of seconds_in_future from double to float. Moreover, I added some more debug output. I attach the source code below.

Setup

If I compile this the program on the USRP X410 with UHD v4.2.0.0 freshly installed with

$ g++ tx_timed_samples.cpp -o tx_timed_samples -lboost_system -lboost_program_options -luhd -lpthread

Expected Behaviour

and run as such:

root@NE-LAB-X410-01:~/tx_timed_samples_bug# ./tx_timed_samples --nsamps 20000 --secs 0.25 --args="addr=localhost" --dilv

Creating the usrp device with: addr=localhost...
[INFO] [UHD] linux; GNU C++ version 9.2.0; Boost_107100; UHD_4.2.0.0-0-g46a70d85
[INFO] [MPMD] Initializing 1 device(s) in parallel with args: mgmt_addr=127.0.0.1,type=x4xx,product=x410,serial=323F754,name=NE-LAB-X410-01,fpga=X4_200,claimed=False,addr=localhost
[INFO] [MPM.PeriphManager] init() called with device args `fpga=X4_200,mgmt_addr=127.0.0.1,name=NE-LAB-X410-01,product=x410,clock_source=internal,time_source=internal'.
Using Device: Single USRP:
  Device: X400-Series Device
  Mboard 0: x410
  RX Channel: 0
    RX DSP: 0
    RX Dboard: A
    RX Subdev: 0
  RX Channel: 1
    RX DSP: 1
    RX Dboard: A
    RX Subdev: 1
  RX Channel: 2
    RX DSP: 2
    RX Dboard: B
    RX Subdev: 0
  RX Channel: 3
    RX DSP: 3
    RX Dboard: B
    RX Subdev: 1
  TX Channel: 0
    TX DSP: 0
    TX Dboard: A
    TX Subdev: 0
  TX Channel: 1
    TX DSP: 1
    TX Dboard: A
    TX Subdev: 1
  TX Channel: 2
    TX DSP: 2
    TX Dboard: B
    TX Subdev: 0
  TX Channel: 3
    TX DSP: 3
    TX Dboard: B
    TX Subdev: 1

Setting TX Rate: 6.250000 Msps...
[WARNING] [0/DUC#0] The requested interpolation is odd; the user should expect passband CIC rolloff.
Select an even interpolation to ensure that a halfband filter is enabled.

[WARNING] [MULTI_USRP] Could not set TX rate to 6.250 MHz. Actual rate is 6.302 MHz
[WARNING] [0/DUC#0] The requested interpolation is odd; the user should expect passband CIC rolloff.
Select an even interpolation to ensure that a halfband filter is enabled.

[WARNING] [MULTI_USRP] Could not set TX rate to 6.250 MHz. Actual rate is 6.302 MHz
[WARNING] [0/DUC#1] The requested interpolation is odd; the user should expect passband CIC rolloff.
Select an even interpolation to ensure that a halfband filter is enabled.

[WARNING] [MULTI_USRP] Could not set TX rate to 6.250 MHz. Actual rate is 6.302 MHz
[WARNING] [0/DUC#1] The requested interpolation is odd; the user should expect passband CIC rolloff.
Select an even interpolation to ensure that a halfband filter is enabled.

[WARNING] [MULTI_USRP] Could not set TX rate to 6.250 MHz. Actual rate is 6.302 MHz
Actual TX Rate: 6.301538 Msps...

[WARNING] [0/Radio#0] Attempting to set tick rate to 0. Skipping.
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 1
success

Done!

Everything is as expected.

Erroneous behaviour

However, If I run with a nsecs value which is not exactly representable in floating point (like 0.3), The output becomes erronous (there are many L in the console, and I get many async error code 8 (which is LATE):

root@NE-LAB-X410-01:~/tx_timed_samples_bug# ./tx_timed_samples --nsamps 20000 --secs 0.3 --args="addr=localhost" --dilv

Creating the usrp device with: addr=localhost...
[INFO] [UHD] linux; GNU C++ version 9.2.0; Boost_107100; UHD_4.2.0.0-0-g46a70d85
[INFO] [MPMD] Initializing 1 device(s) in parallel with args: mgmt_addr=127.0.0.1,type=x4xx,product=x410,serial=323F754,name=NE-LAB-X410-01,fpga=X4_200,claimed=False,addr=localhost
[INFO] [MPM.PeriphManager] init() called with device args `fpga=X4_200,mgmt_addr=127.0.0.1,name=NE-LAB-X410-01,product=x410,clock_source=internal,time_source=internal'.
Using Device: Single USRP:
  Device: X400-Series Device
  Mboard 0: x410
  RX Channel: 0
    RX DSP: 0
    RX Dboard: A
    RX Subdev: 0
  RX Channel: 1
    RX DSP: 1
    RX Dboard: A
    RX Subdev: 1
  RX Channel: 2
    RX DSP: 2
    RX Dboard: B
    RX Subdev: 0
  RX Channel: 3
    RX DSP: 3
    RX Dboard: B
    RX Subdev: 1
  TX Channel: 0
    TX DSP: 0
    TX Dboard: A
    TX Subdev: 0
  TX Channel: 1
    TX DSP: 1
    TX Dboard: A
    TX Subdev: 1
  TX Channel: 2
    TX DSP: 2
    TX Dboard: B
    TX Subdev: 0
  TX Channel: 3
    TX DSP: 3
    TX Dboard: B
    TX Subdev: 1

Setting TX Rate: 6.250000 Msps...
[WARNING] [0/DUC#0] The requested interpolation is odd; the user should expect passband CIC rolloff.
Select an even interpolation to ensure that a halfband filter is enabled.

[WARNING] [MULTI_USRP] Could not set TX rate to 6.250 MHz. Actual rate is 6.302 MHz
[WARNING] [0/DUC#0] The requested interpolation is odd; the user should expect passband CIC rolloff.
Select an even interpolation to ensure that a halfband filter is enabled.

[WARNING] [MULTI_USRP] Could not set TX rate to 6.250 MHz. Actual rate is 6.302 MHz
[WARNING] [0/DUC#1] The requested interpolation is odd; the user should expect passband CIC rolloff.
Select an even interpolation to ensure that a halfband filter is enabled.

[WARNING] [MULTI_USRP] Could not set TX rate to 6.250 MHz. Actual rate is 6.302 MHz
[WARNING] [0/DUC#1] The requested interpolation is odd; the user should expect passband CIC rolloff.
Select an even interpolation to ensure that a halfband filter is enabled.

[WARNING] [MULTI_USRP] Could not set TX rate to 6.250 MHz. Actual rate is 6.302 MHz
Actual TX Rate: 6.301538 Msps...

[WARNING] [0/Radio#0] Attempting to set tick rate to 0. Skipping.
Setting device timestamp to 0.000000...

Waiting for async burst ACK... Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
async code: 8
LLasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 1
success
Setting device timestamp to 0.000000...

Waiting for async burst ACK... async code: 8
Lasync code: 8
LLasync code: 8
async code: 8
LLasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
Lasync code: 8
async code: 1
success

Done!

root@NE-LAB-X410-01:~/tx_timed_samples_bug# 

if I change back the type of seconds_in_future to double and also in the options parser line, the error is gone and evreything works as expected.

I know that 0.3seconds cannot be fully represented in both double adn float. However, I expect that the casting into double would not create any problems as long as the time is clearly in the future. I do not expect to see these "LATE" messages in the console, even though I supply a float (also, the compiler does not throw a warning regardign a lossy conversion).

Source code

//tx_timed_samples.cpp modified
//
// Copyright 2010-2011,2014 Ettus Research LLC
// Copyright 2018 Ettus Research, a National Instruments Company
//
// SPDX-License-Identifier: GPL-3.0-or-later
//

#include <uhd/usrp/multi_usrp.hpp>
#include <uhd/utils/safe_main.hpp>
#include <uhd/utils/thread.hpp>
#include <boost/format.hpp>
#include <boost/program_options.hpp>
#include <boost/thread/thread.hpp>
#include <complex>
#include <iostream>

namespace po = boost::program_options;

int UHD_SAFE_MAIN(int argc, char* argv[])
{
    // variables to be set by po
    std::string args;
    std::string wire;
    float seconds_in_future;
    size_t total_num_samps;
    double rate;
    float ampl;
    float curtime;

    // setup the program options
    po::options_description desc("Allowed options");
    // clang-format off
    desc.add_options()
        ("help", "help message")
        ("args", po::value<std::string>(&args)->default_value(""), "single uhd device address args")
        ("wire", po::value<std::string>(&wire)->default_value(""), "the over the wire type, sc16, sc8, etc")
        ("secs", po::value<float>(&seconds_in_future)->default_value(1.5f), "number of seconds in the future to transmit")
        ("nsamps", po::value<size_t>(&total_num_samps)->default_value(10000), "total number of samples to transmit")
        ("rate", po::value<double>(&rate)->default_value(100e6/16), "rate of outgoing samples")
        ("ampl", po::value<float>(&ampl)->default_value(float(0.3)), "amplitude of each sample")
        ("dilv", "specify to disable inner-loop verbose")
	("curtime", po::value<float>(&curtime)->default_value(0.0f))
    ;
    // clang-format on
    po::variables_map vm;
    po::store(po::parse_command_line(argc, argv, desc), vm);
    po::notify(vm);

    // print the help message
    if (vm.count("help")) {
        std::cout << boost::format("UHD TX Timed Samples %s") % desc << std::endl;
        return ~0;
    }

    bool verbose = vm.count("dilv") == 0;

    // create a usrp device
    std::cout << std::endl;
    std::cout << boost::format("Creating the usrp device with: %s...") % args
              << std::endl;
    uhd::usrp::multi_usrp::sptr usrp = uhd::usrp::multi_usrp::make(args);
    std::cout << boost::format("Using Device: %s") % usrp->get_pp_string() << std::endl;

    // set the tx sample rate
    std::cout << boost::format("Setting TX Rate: %f Msps...") % (rate / 1e6) << std::endl;
    usrp->set_tx_rate(rate);
    std::cout << boost::format("Actual TX Rate: %f Msps...") % (usrp->get_tx_rate() / 1e6)
              << std::endl
              << std::endl;


    // create a transmit streamer
    uhd::stream_args_t stream_args("fc32", wire); // complex floats
    uhd::tx_streamer::sptr tx_stream = usrp->get_tx_stream(stream_args);

    // allocate buffer with data to send
    std::vector<std::complex<float>> buff(
        tx_stream->get_max_num_samps(), std::complex<float>(ampl, ampl));

    for (int i = 0; i < 10; i++) {

    std::cout << boost::format("Setting device timestamp to %f...") %  curtime << std::endl;
    usrp->set_time_now(uhd::time_spec_t(curtime));
    // setup metadata for the first packet
    uhd::tx_metadata_t md;
    md.start_of_burst = false;
    md.end_of_burst   = false;
    md.has_time_spec  = true;
    md.time_spec      = uhd::time_spec_t(seconds_in_future);

    // the first call to send() will block this many seconds before sending:
    const double timeout =
        seconds_in_future + 0.1; // timeout (delay before transmit + padding)

    size_t num_acc_samps = 0; // number of accumulated samples
    while (num_acc_samps < total_num_samps) {
        size_t samps_to_send = std::min(total_num_samps - num_acc_samps, buff.size());

        // send a single packet
        size_t num_tx_samps = tx_stream->send(&buff.front(), samps_to_send, md, timeout);

        // do not use time spec for subsequent packets
        md.has_time_spec = false;

        if (num_tx_samps < samps_to_send)
            std::cerr << "Send timeout..." << std::endl;
        if (verbose)
            std::cout << boost::format("Sent packet: %u samples") % num_tx_samps
                      << std::endl;

        num_acc_samps += num_tx_samps;
    }

    // send a mini EOB packet
    md.end_of_burst = true;
    tx_stream->send("", 0, md);

    std::cout << std::endl << "Waiting for async burst ACK... " << std::flush;
    uhd::async_metadata_t async_md;
    bool got_async_burst_ack = false;
    // loop through all messages for the ACK packet (may have underflow messages in queue)
    while (not got_async_burst_ack and tx_stream->recv_async_msg(async_md, timeout)) {
	    auto code = async_md.event_code;
        got_async_burst_ack =
            (code == uhd::async_metadata_t::EVENT_CODE_BURST_ACK);
	std::cout << "async code: " << code << std::endl;
    }
    std::cout << (got_async_burst_ack ? "success" : "fail") << std::endl;
    }

    // finished
    std::cout << std::endl << "Done!" << std::endl << std::endl;

    return EXIT_SUCCESS;
}

[mmatthebi]

As a quick follow-up, this might help to debug:

$ cat t.cpp           
$ cat t.cpp 
#include <iostream>

int main() {
    float f = 0.3;

    double d = 0.3;
    double d2 = f;
    std::cout << (d == d2) << std::endl;
}
$ g++ t.cpp && ./a.out
0

which shows that in the conversion something happens. And this little difference makes UHD misinterpret time_spec in some way which I cannot debug.

[mbr0wn]

tl;dr: Use a recent UHD and this won't happen, and don't use float for timestamps.

There are a couple of things going on here. First, remember that float does not have great accuracy at all, but we're trying to encode nanoseconds within a single variable! UHD will internally calculate tick values from this timestamp, and if you're using floats, they will already be way off! Consider this code:

#include <iostream>

int main(void)
{

        double t0_d = 0.3;
        uint64_t t0_du = t0_d * 245.76e6;

        float t0_f = 0.3;
        uint64_t t0_fu = double(t0_f) * 245.76e6;

        std::cout << t0_du << std::endl; // Will output: 73728000
        std::cout << t0_fu << std::endl; // 73728002

        return 0;
}

Using a float or a double will yield two different tick values, offset by over 8ns, or two samples! This is already too bad to be useful, so the first takeaway is, just don't ever use float timestamps.

The next thing is that X410 uses 4 samples-per-clock in the configuration that you're running. Maybe you can see where this is going: 73728000 % 4 == 0, but 73728002 % 4 != 0. In the version you're running, we relied on the timestamp (in ticks) being a value that the USRP will actually produce in its internal counters. If you initialize the time of the USRP to 0 at some point, then all requested TX timestamps must be multiples of 4. That means the USRP starts with time 0, then 4, ... and so on, until it is 73728000, then 73728004. As you can see, we never reach timestamp 73728002, and therefore, the radio never starts transmitting, but when we reach time 73728004, then it's already too late.

The good news is, you don't need to fix your code to make this do something. In 9afa6be, we allowed fractional multiples of SPC. That means that your code with a recent version of UHD won't produce the lates anymore. However, it will still not transmit at the right time, you will be off by 8ns. You might not care, but others might and therefore I must repeat this again: Don't specify timestamps as float variables.

[mmatthe]

Thanks @mbr0wn for the detailed explanation why this happened in the past. Good that it's fixed!