USB is having problem working together with Radio on nrf52833.

[Nadi]

SDK version: SDK17.0

 

We have low received radio message count with open USB CDC compared to when it is closed.

The low rx varies from 20% to 50%.

USB open = screen session opened

USB close = screen session closed

 

The issue is seen more in a crowded area where a lot of ble radio are transmitting. However, when USB CDC is closed the issue went away even in a crowded area.

 

Be noted that the USB received print outs have no issue and they are proper messages.

The problem is only the count of received radio messages if we compare a back to back tests are for example 2 minutes where in one USB is open and on the other USB is closed.

 

Anyone else has similar issue? Any help would be appreciated.

[Edvin]

Hello,

What do you mean by "rx varies from 20% to 50%"? Are you claiming that you are seeing packet loss? If so, can you please share:

1: how you calculate this number?

2: How do you transmit the messages?

3: How do you receive the messages (I guess this is part of 1), how you measure the RX packets).

Hint: I believe you need to check the return value from the softdevice call that sends the messages. Does it always return 0 (NRF_SUCCESS)? My suspicion is that the packet that you are missing doesn't return NRF_SUCCESS. Is it the peripheral or the central that sends the messages?

Best regards,

Edvin

Best regards,

Edvin

[bdieseldorff]

Hi Edvin, I'm a co-worker of Nadi.

We have a number of devices broadcasting on a regular basis with a predetermined ibeacon UUID.
We have one device (we'll call it DUT) that we're actively working with.

The DUT has a counter that increments whenever it receives an advertisement with the predetermined ibeacon UUID.
What we observe is that we the counter increments faster when we do not have a usb_cdc connection open.

The measurement is simple:
- Open the usb_cdc connection, and get the counter value via a CLI command (A)
- Wait 5 minutes
- Get the counter value (B)
- Close the connection, and wait 5 minutes
- Open the connection, and get the counter value (C)

We then calculate the ratio as: (C-B)/(B-A)
We would expect this to be extremely close to 1, as a usb_cdc connection should have no impact on the radio.
Instead we commonly get ratios around 1.2-1.5. We have seen particular cases where this is even greater than 5.

Details:
- For the "open the connection" step, we've used various tools including pyserial and screen.
- The message transmission should not be relevant, as the transmitting devices are not interacted with in any way during this test.
- We also get this mismatch from both our dev boards, and commercially available ibeacon tags
- We have done many variants of this and get similar results
- Many prints per second, to no prints whatsoever during the "wait" times
- An additional UART connection, where we print info every time the DUT receive an advertisement with the predetermined UUID. This gives us fine time resolution, and the log we make from this shows the same behavior (this is how we made the attached plot).

[Edvin]

Can you show me a snippet of where you increase your counter? I assume it would be in the advertising report event. Is there anything there that would take longer while you have the USB port open than when it is closed? Do you use your USB peripheral at all in that event?

You don't change the scan window/interval when opening the USB port? What priority is your USB port running? What does the USB port do? Can you show me some snippets of what you use it for?

My suspicion is that something is preventing the adv_report events from occuring in your application. Perhaps they are blocked by the USB, or that they are using longer time while the USB is open? (blocking itself).

Either way, scanning for advertisements is not a "trusted" tranfer. You can't expect to receive all packets, but I agree that it should be possible to use the USB without significant change in the behavior.

Best regards,

Edvin

[bdieseldorff]

We've tried incrementing the counter in various places (see code) including:
- [1] during any ble event, with all other code in ble_evt_handler commented
- [2] after establishing that the event is a BEL_GAP_EVT_ADV_REPORT; with code as shown
- [3] inside our custom_ble_evt_handler for cases where ibeacon uuid matches a specified uuid

static void ble_evt_handler(ble_evt_t const * p_ble_evt, void * p_context)
{
    uint16_t conn_handle = p_ble_evt->evt.gap_evt.conn_handle;
    uint16_t role = ble_conn_state_role(conn_handle);
    ble_gap_evt_t const * p_gap_evt = &p_ble_evt->evt.gap_evt;
    const ble_gap_evt_adv_report_t * p_adv_report = &p_gap_evt->params.adv_report;
    // counter increment location 1
    if ((role == BLE_GAP_ROLE_CENTRAL) || (p_ble_evt->header.evt_id == BLE_GAP_EVT_ADV_REPORT))
    {
        switch (p_ble_evt->header.evt_id)
        {
            case BLE_GAP_EVT_ADV_REPORT: {
                uint8_t * raw_data = (uint8_t *) &p_adv_report->data.p_data[0];
                uint16_t raw_data_len = p_adv_report->data.len;
                custom_ble_evt_handler(&p_adv_report->peer_addr.addr[0],
                                       (uint8_t) p_adv_report->rssi, &raw_data[0], raw_data_len); // counter increment location 3 inside after matching ibeacon UUID
                // counter increment location 2
            }
            break;
            default:
                break;
        }
    }
}

We don't change any settings when we open up a connection. We see the issue even when USB doesn't send or receive any bytes during the 5-minute wait period (we've confirmed using wireshark and USBPcap that nothing is being sent or received in that time).

We agree that something is likely taking more time or being serviced less, but we don't understand why that would be the case based on an open connection that isn't receiving or sending anything. NRFX_USBD_CONFIG_IRQ_PRIORITY is set to 6, and we've tried a few priorities for APP_BLE_OBSERVER_PRIO (3, 1, 0) without seeing a change in behavior. We've also put counters to track any APP_USBD_EVT and APP_USBD_CDC_ACM_USER_EVT - no events are happening unexpectedly.

We understand that scanning won't catch all packets. Our application is designed to tolerate some packet loss. However, losing an extra 30% of packets because we're using usbd_cdc instead of UART isn't acceptable.

A couple of other observations:
- There seems to be some interaction with the device that opens the serial port. We've seen no issues (ie, ratio ~= 1) with default Raspberry Pi 3s opening the port. However, we see issues on most devices including: multiple Windows computers, a computer running Mac OS, a Linux VM within Windows, a Raspberry Pi 4, and Raspberry Pi 3s with an option to force the internal hub to be slower (dwc_otg.speed=1).

- This issue seems more likely in cases when many devices are broadcasting. We've seen it inconsistently with as few as 3 broadcasting devices, and see it very consistently in a setup that has 15+ broadcasting devices.

[Edvin]

I am not sure why you are seeing this. Is your device acting only as a scanner, or do you do other BLE roles as well? Are you in a connection? If so, central or peripheral? And are you at any point advertising using this device?

BR,

Edvin

[bdieseldorff]

Hi Edvin,

The device is in scan mode most of the time (~190ms per 200ms). In the other time period, it sends out a single advertisement. We are not in a connection.

That being said, this behavior should not be affected by opening a usbd_cdc serial connection.

[Edvin]

Hello,

I still agree that the USB shouldn't affect this. What I am fishing for is whether you:

1. Start advertising or enter a connection when you enable the USB

2. Enable the USB whenever you enter a connection

Something that would link the USB to BLE activity.

I see that you are using quite a long scan window (190ms). What you should be aware of is that the softdevice scheduler can only schedule entire scan windows. The scheduler is dynamic, so whenever it fails to schedule one type of event (scan window, advertising event, connection event) due to a collision, this event type will have a higher priority the next time it is scheduled. Since scan windows are only possible to schedule as a whole, whenever the softdevice tries to schedule a scan window (which it will do every scan interval) it either succeeds, or it fails. If it fails, it will not try to schedule another scan window until the next scan interval starts. In your case, this means that you will lose 200ms of scanning. 

Even though you line up your occasional advertising to fit in between the scan windows, let's say by setting the advertising interval to 200, advertisements in BLE has a random delay of 0-10ms added to each advertising interval, so the advertisement will collide with a scan window almost every time in the scheduler, so the softdevice has to pick one.

Try decreasing your scan window and scan interval. If you keep the SCAN_WINDOW/SCAN_INTERVAL ratio, you will still scan an equal amount of time, but you will not lose as much scan time when a scan window is not successfully scheduled.

Let us say you keep the advertising interval at whatever you are currently using, but decrease the scan interval to 40ms and scan window to 38 (same ratio), you will only miss 30ms of scanning every time an advertisement is prioritized over a scan window.

Best regards,

Edvin

[bdieseldorff]

Hi Edvin,

Thanks for your thoughts - we're also confused about how this has an effect with no apparent link between USB and radio Rx. As I mentioned, we've run this code base using UART for all of our CLI and output. In that case, the only usbd functionality we were using was the initialization. Even in that case, we saw this issue, which should eliminate both #1 and #2 that you proposed. Also note - we don't use BLE connections at all, just advertise and scan.

While we use timers, they only set a next state, they do not force it, so we won't step on our own toes.
- Advertise state: check if there's a new advertise state, stop the ongoing scan, do an advertisement, show error if any, clear 'new state' flag
- Scan state: check if there's a new scan state, start a scan, show error if any, clear 'new state' flag

This structure should prevent any collisions between scanning and advertising. Even if our structure isn't set up correctly, we check the return code from nrf_ble_scan_start, and report any errors. We don't see these errors, so we should be confident we're not failing to schedule scans.

[Edvin]

Is there some way for me to reproduce what you are seing using a DK?

BR,

Edvin