search

Nuand / bladeRF

bladeRF USB 3.0 Superspeed Software Defined Radio Source Code
http://nuand.com
Other
1.15k stars 459 forks source link

trigger: rx timeout not respected #655

Closed rtucker closed 6 years ago

rtucker commented 6 years ago

Reported by lbelella in forums: https://nuand.com/forums/viewtopic.php?p=9002#p9002

Attempting to do a triggered RX results in a spew of timeouts, before the RX occurs:

bladeRF> set samplerate rx 7.68M
bladeRF> rx config file=/tmp/foo.bin n=15360000 timeout=60
bladeRF> trigger j71-4 rx slave
bladeRF> rx start
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:282] Reading MS1
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:291] Read enable register: 0x01
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[0]: 0x80
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[1]: 0x50
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[2]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[3]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[4]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[5]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[6]: 0x01
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[7]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[8]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[9]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:310] Read r register: 0xc0
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:150] Unpacked P1: 0x00005080 (20608) P2: 0x00000000 (0) P3: 0x00000001 (1)
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:168] Unpacked a + b/c: 165 + 0/1
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:169] Unpacked r: 1
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:341] Calculated multisynth frequency: 7680000 + 0/1

    Warning: The current sample rate may be too low. For 16 transfers,
    32768 samples per buffer, and a 60 ms timeout, a sample rate
    over 9611947 Hz may be required. Alternatively, the 'timeout'
    parameter could be increased, but may yield underruns.

[VERBOSE @ host/libraries/libbladeRF/src/backend/usb/nios_access.c:392] nios_config_read: Read 0x0018002f
[VERBOSE @ host/libraries/libbladeRF/src/backend/usb/nios_access.c:403] nios_config_write: Wrote 0x0018002f
[DEBUG @ host/libraries/libbladeRF/src/board/bladerf1/bladerf1.c:1297] Enable channel: RX - True
bladeRF> [DEBUG @ host/libraries/libbladeRF/src/streaming/sync.c:401] sync_rx: Worker is idle. Going to reset buf mgmt.
                                                                                                                       [DEBUG @ host/libraries/libbladeRF/src/streaming/sync.c:421] sync_rx: Reset buf_mgmt consumer index
                                              [DEBUG @ host/libraries/libbladeRF/src/streaming/sync.c:436] sync_rx: Worker is now running.
                                                                                                                                          [ERROR @ host/libraries/libbladeRF/src/streaming/sync.c:306] wait_for_buffer: Timed out waiting for buf_ready after 60 ms
                                                                                       [DEBUG @ host/libraries/libbladeRF/src/board/bladerf1/bladerf1.c:1297] Enable channel: RX - False
            rx
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd960ec010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd960bc010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd9609b010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd9607a010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd96059010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd96038010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd96017010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd95ff6010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd95fd5010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd95fb4010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd95f93010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd95f72010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd95f51010
[ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fbd95f30010

  State: Idle
  Channels: RX1
  Last error: Operation timed out
  File: /tmp/foo.bin
  File format: SC16 Q11, Binary
  # Samples: 15360000
  # Buffers: 32
  # Samples per buffer: 32768
  # Transfers: 16
  Timeout (ms): 60

bladeRF>

(note: the sample rate warning is very likely a red herring)

rtucker commented 6 years ago

verbose log output provided by lbelella: timeout.txt

rtucker commented 6 years ago

I subsequently realized timeout= is in milliseconds, so here it is with timeout of 30000 ms:

bladeRF> rx config file=/tmp/foo.bin timeout=30000
bladeRF> trigger
[VERBOSE @ host/libraries/libbladeRF/src/backend/usb/nios_access.c:1076] RX1 trigger read value 0x09
[VERBOSE @ host/libraries/libbladeRF/src/backend/usb/nios_access.c:1076] RX1 trigger read value 0x09

  J71-4 RX trigger
    State:          Armed
    Role:           Slave
    Fired:          No

[VERBOSE @ host/libraries/libbladeRF/src/backend/usb/nios_access.c:1076] TX1 trigger read value 0x08
[VERBOSE @ host/libraries/libbladeRF/src/backend/usb/nios_access.c:1076] TX1 trigger read value 0x08

  J71-4 TX trigger
    State:          Disarmed
    Role:           Slave
    Fired:          No

bladeRF> rx start
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:282] Reading MS1
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:291] Read enable register: 0x01
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[0]: 0x40
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[1]: 0x27
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[2]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[3]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[4]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[5]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[6]: 0x02
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[7]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[8]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:300] Read regs[9]: 0x00
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:310] Read r register: 0xc0
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:150] Unpacked P1: 0x00002740 (10048) P2: 0x00000000 (0) P3: 0x00000002 (2)
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:168] Unpacked a + b/c: 82 + 1/2
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:169] Unpacked r: 1
[VERBOSE @ host/libraries/libbladeRF/src/driver/si5338.c:341] Calculated multisynth frequency: 15360000 + 0/1
[VERBOSE @ host/libraries/libbladeRF/src/backend/usb/nios_access.c:392] nios_config_read: Read 0x0018002f
[VERBOSE @ host/libraries/libbladeRF/src/backend/usb/nios_access.c:403] nios_config_write: Wrote 0x0018002f
[DEBUG @ host/libraries/libbladeRF/src/board/bladerf1/bladerf1.c:1297] Enable channel: RX - True
bladeRF> [DEBUG @ host/libraries/libbladeRF/src/streaming/sync.c:401] sync_rx: Worker is idle. Going to reset buf mgmt.
                                                                                                                       [DEBUG @ host/libraries/libbladeRF/src/streaming/sync.c:421] sync_rx: Reset buf_mgmt consumer index
                                              [DEBUG @ host/libraries/libbladeRF/src/streaming/sync.c:436] sync_rx: Worker is now running.
                                                                                                                                          [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e00027b0
                                                                            [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e00227c0
              [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e00427d0
                                                                                                                            [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e00627e0
                                                              [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e00827f0
                                                                                                                                                                           [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e00a2800
                                                                                                             [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e00c2810
                                               [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e00e2820
                                                                                                                                                             [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e0102830
                                                                                               [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e0122840
                                 [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e0142850
                                                                                                                                               [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e0162860
                                                                                 [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e0182870
                   [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e01a2880
                                                                                                                                 [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e01c2890
                                                                   [ERROR @ host/libraries/libbladeRF/src/backend/usb/libusb.c:1088] Transfer timed out for buffer 0x7fd9e01e28a0
     [DEBUG @ host/libraries/libbladeRF/src/board/bladerf1/bladerf1.c:1297] Enable channel: RX - False

bladeRF> rx

  State: Idle
  Channels: RX1
  Last error: Operation timed out
  File: /tmp/foo.bin
  File format: SC16 Q11, Binary
  # Samples: 100000
  # Buffers: 32
  # Samples per buffer: 32768
  # Transfers: 16
  Timeout (ms): 30000

bladeRF>

tl;dr: still brokeny

rtucker commented 6 years ago

Okay, so there's a stream timeout, which is configured by the rx config timeout=<n> and enforced by a pthread_cond_timedwait() in sync.c's wait_for_buffer(). Then there's a transfer timeout, which is passed to libusb_fill_bulk_transfer() in libusb.c's submit_transfer().

The transfer timeout is currently hardcoded to 1000 in async_init_stream() (based on BULK_TIMEOUT_MS in usb.h). So, stream timeouts longer than 1000 ms are being thwarted by all of the transfers timing out after 1000 ms.

I have a fix and will have a PR shortly...