Repeated calls to issue_stream_cmd are silently dropped

[mmatthebi]

Issue Description

When calling radio_block_control::issue_stream_cmd() with a timed command in the future more often than the command queue can store, overflowing stream_cmds are silently ignored. However the docs state that the command should block.

When the command queue is full, UHD will block until the USRP has signaled that there is space for more commands.

Setup Details

I use an X410 with UHD4.5 (same issue happens with v4.7) with X4_400 image, but any image with 400MHz bandwidth should work. I compile this source code directly on the device:

#include <iostream>
#include <thread>
#include <chrono>

#include <uhd/utils/graph_utils.hpp>
#include <uhd/rfnoc/block_id.hpp>
#include <uhd/rfnoc/radio_control.hpp>
#include <uhd/rfnoc/replay_block_control.hpp>
#include <uhd/rfnoc_graph.hpp>
#include <uhd/rfnoc/mb_controller.hpp>

#include <uhd/version.hpp>

using uhd::rfnoc::block_id_t;
using uhd::rfnoc::replay_block_control;
using uhd::rfnoc::radio_control;
using uhd::rfnoc::rfnoc_graph;

using namespace std::chrono_literals;



uint64_t get_timestamp() {
        auto now = std::chrono::steady_clock::now();
        return std::chrono::duration_cast<std::chrono::microseconds>(now.time_since_epoch()).count();
}

int main(int argc, char *argv[]) {
    try {
        std::cout << "hi" << uhd::get_version_string() << std::endl;

        if (argc < 3) {
            std::cout << "Usage: <program> <ip> <num_commands>" << std::endl;
            return 1;
        }

        std::string ip = argv[1];
        uint64_t NUM_SAMPLES = 1024;
        size_t NUM_REPS = std::stoi(argv[2]);

        auto graph = rfnoc_graph::make("addr="+ip);

        auto replayCtrl = graph->get_block<replay_block_control>(block_id_t("0/Replay#0"));
        auto radio0 = graph->get_block<radio_control>(block_id_t("0/Radio#0"));

        std::this_thread::sleep_for(500ms);

        // streaming connection
        std::cout << "Connect for record" << std::endl;
        // connect forward edge
        graph->connect(replayCtrl->get_block_id(), 0, radio0->get_block_id(), 0, false);
        graph->connect(radio0->get_block_id(), 0, replayCtrl->get_block_id(), 0, true);
        graph->commit();

        const uint64_t MEM_SIZE = replayCtrl->get_mem_size();
        replayCtrl->record(MEM_SIZE / 2, NUM_SAMPLES * 4 * NUM_REPS, 0);

        double fpgaTime = graph->get_mb_controller()->get_timekeeper(0)->get_time_now().get_real_secs();

        double txRxTime = fpgaTime + 0.5;
        std::cout << "recording " << NUM_SAMPLES << std::endl;

        // record
        uhd::stream_cmd_t rxStreamCmd(uhd::stream_cmd_t::STREAM_MODE_NUM_SAMPS_AND_DONE);
        rxStreamCmd.num_samps = NUM_SAMPLES;
        rxStreamCmd.stream_now = false;
        auto start = get_timestamp();
        auto start2 = start;
        for (int c = 0; c < NUM_REPS; c++) {
                rxStreamCmd.time_spec = uhd::time_spec_t(txRxTime+c*0.001);
                radio0->issue_stream_cmd(rxStreamCmd, 0);
                auto now = get_timestamp();
                std::cout << "stream " << c << " " << now - start2 << " " << now - start << std::endl;
                start = now;
        }

        uhd::rx_metadata_t asyncMd;
        double timeout = 1;
        while (replayCtrl->get_record_async_metadata(asyncMd, timeout)) {
            if (asyncMd.error_code != uhd::rx_metadata_t::ERROR_CODE_NONE)
                throw std::runtime_error("Error at recording: " + asyncMd.strerror());
            timeout = 0.02;
        }

        std::cout << "Recorded bytes: " << replayCtrl->get_record_fullness(0) << std::endl;


    } catch(std::exception& e) {
        std::cerr << "ERROR: " << e.what() << std::endl;
        return 1;
    }


    return 0;
}

using g++ issue.cpp -luhd -o issue. I run the program with ./issue localhost <N> where N is an integer number describing the number of stream commands to send to the FPGA.

The programs creates an RFNoc graph using a replay block which records samples coming from the radio. The radio is instructed to record 1024 samples every ms for a given number N of repetitions. The program outputs the timestamps between subsequent calls to issue_stream_cmd (3rd column), the amount of time gone since the first stream command (2nd column) and also the amount of data stored in the replay block (last line).

Expected Behavior

I expect the amount of data stored in the replay block to be 4*1024*N where

• 4 is the bytes per sample
• 1024 is the number samples per burst
• N is the number of bursts

Moreover, I expect that the calls to issue_stream_cmd block until the command queue is free again.

Actual Behaviour

For N<=32 everything is as expected, meaning that the correct number of samples is recorded (maximum is 4*1024*32=131072 bytes) and the subsequent calls to issue_stream_cmd do not block:

./issue localhost 32
hi4.5.0.0-0-g471af98f
[INFO] [UHD] linux; GNU C++ version 9.2.0; Boost_107100; UHD_4.5.0.0-0-g471af98f
[INFO] [MPMD] Initializing 1 device(s) in parallel with args: mgmt_addr=127.0.0.1,type=x4xx,product=x410,serial=323F769,name=NE-LAB-X410-05,fpga=X4_400,claimed=False,addr=localhost
[INFO] [MPM.PeriphManager] init() called with device args `fpga=X4_400,mgmt_addr=127.0.0.1,name=NE-LAB-X410-05,product=x410,clock_source=internal,time_source=internal,initializing=True'.
Connect for record
[WARNING] [0/Radio#0] Attempting to set tick rate to 0. Skipping.
recording 1024
stream 0 166 166
stream 1 320 154
stream 2 472 152
stream 3 611 139
stream 4 777 166
stream 5 908 131
stream 6 1046 138
stream 7 1198 152
stream 8 1375 177
stream 9 1548 173
stream 10 1788 240
stream 11 1961 173
stream 12 2131 170
stream 13 2287 156
stream 14 2454 167
stream 15 2626 172
stream 16 2809 183
stream 17 2963 154
stream 18 3154 191
stream 19 3306 152
stream 20 3475 169
stream 21 3659 184
stream 22 3832 173
stream 23 3997 165
stream 24 4164 167
stream 25 4337 173
stream 26 4509 172
stream 27 4681 172
stream 28 4855 174
stream 29 5024 169
stream 30 5193 169
stream 31 5348 155
Recorded bytes: 131072

However, for N>32 the amount of samples remains constant (131072) and there is no blocking visible of the issue_stream_cmd calls. Instead, it seems that the calls to issue_stream_cmd which are beyond the queue's capacity are silently dropped and never executed.

# ./issue localhost 36
hi4.5.0.0-0-g471af98f
[INFO] [UHD] linux; GNU C++ version 9.2.0; Boost_107100; UHD_4.5.0.0-0-g471af98f
[INFO] [MPMD] Initializing 1 device(s) in parallel with args: mgmt_addr=127.0.0.1,type=x4xx,product=x410,serial=323F769,name=NE-LAB-X410-05,fpga=X4_400,claimed=False,addr=localhost
[INFO] [MPM.PeriphManager] init() called with device args `fpga=X4_400,mgmt_addr=127.0.0.1,name=NE-LAB-X410-05,product=x410,clock_source=internal,time_source=internal,initializing=True'.
Connect for record
[WARNING] [0/Radio#0] Attempting to set tick rate to 0. Skipping.
recording 1024
stream 0 176 176
stream 1 320 144
stream 2 465 145
stream 3 604 139
stream 4 733 129
stream 5 862 129
stream 6 1012 150
stream 7 1186 174
stream 8 1335 149
stream 9 1495 160
stream 10 1662 167
stream 11 1834 172
stream 12 1978 144
stream 13 2146 168
stream 14 2301 155
stream 15 2486 185
stream 16 2631 145
stream 17 2818 187
stream 18 2965 147
stream 19 3114 149
stream 20 3265 151
stream 21 3429 164
stream 22 3619 190
stream 23 3785 166
stream 24 3940 155
stream 25 4093 153
stream 26 4261 168
stream 27 4412 151
stream 28 4590 178
stream 29 4759 169
stream 30 4926 167
stream 31 5095 169
stream 32 5261 166
stream 33 5409 148  <<<--- here I would expect to block (assuming that the queue length is 32)
stream 34 5587 178
stream 35 5739 152
Recorded bytes: 131072   <<<--- still only 32 bursts have been recorded.

Steps to reproduce the problem

compile and run the program above as described.

[mmatthebi]

as a workaround, is there a way to query the command queue fullness? This could be used to manually block in the loop.

[mmatthebi]

@mbr0wn @joergho any insights here? Can you reproduce on your side?