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.