nRF52 - Irregular delay between data packets

[Pjay]

Hi there,

In my application I use a hardware timer to capture and transmit sensor data with a sample time of 10ms (after corresponding notification is enabled). The connection interval is set up to 7.5ms. 

As the TX queue is filled with slower rate than the data is (or should) be transmitted, I would expect that there are "empty" (or no) packets between the sensor data packets, but not that multiple data packets are transmitted during one connection interval. However, that seems to be the case: I use a nRF DK52 board in combination with nRF Connect using a PC to enable notification of the bluetooth characteristic which should send packets with sensor data every 7.5ms. However, examining the timestamps of the incoming packets,

1) the delay times between the packets seem to vary and are never 7.5ms (s. Screenshot)
2) it seems as if during some connection intervals multiple packets are received

The data packets contain an index which is incremented by the sensor application with every new data set. Apparently, no packets seem to miss. Only the time in between the incoming packets is what troubles me (as for the real application the sensor data is transmitted to a second device which performs real time processing of the data, where the time difference of the packets is of importance). 

I am using an nRF52832 with SD s132 5.0.0 and have activated DLE.

The log file gained by nRF Connect is attached.

Thanks in advance for any help!

[Sigurd]

Hi,

There could be some log buffering and deferred logging happening in the nRF Connect BLE app, so the timestamps might not be perfectly accurate. In order to get accurate timestamps, and see what’s really happening on-air, you would need to do a sniffer trace. If you have a extra DK, you could use nRF Sniffer for that. (I recommend to use the nRFSniffer v2 variant)

[Pjay]

Hi,

thanks for the reply.

I went through the various steps to get the sniffer running under wireshark.. Although I followed all the steps in the troubleshooting area (checking the jlink version on the firmware, running the "sethwfc force" option and so on) the tool chain does not work properly. I need several starting retries to finally receive packets after activating the COM port.
However, even then there seems to be a problem remaining, because all advertising packets show "length is incorrect" under header->length of payload (s. screenshot below).
I'm using Wireshark Version 2.4.2 and Sniffer v2_001. The sniffer firmware runs on a NRF52 DK (PCA10040).
Do you have any ideas what causes this behaviour?

(The marked packet in the screenshot does not relate to my device, it is just examplatory... All received advertising messages are shown in that way).

 

[Pjay]

I already had found the information regarding the bug of the prior version when using DLE, so I already have used 2.0.0.-beta 3 (the profile folder seems to be the same as v2_001, that's why this version appears in the lower-right corner).

However, an update of Wireshark (to v3.01) apparently did the job and I now see normal behavior when sniffing data (maybe a reinstalling of the old version would have done the trick as well, but I cannot say for the certain).

Nevertheless: the problem of varying delay times between the packets can also be observed when looking at the time stamps of packet (s. screenshot).

For your information: our application is based on three devices which communicate via bluetooth. Two of the devices are self-developed battery driven devices each using an NRF52, and the third device is usually a smartphone. However for simplicity I use an NRF52-DK board connected to the PC via USB instead of the smartphone most of the times. One of the self-developed boards (“slave”) collects sensor data and sends it to the other board (“master”) every 7.5ms. The master uses its’ own data and the data of the slave for processing and sends the preprocessed data to the central (in this case the NRF52 DK). The DK transmits the data via RTT to the PC. The bluetooth code of the master is originally based on the relay example found in the SDK, and the bluetooth code of the slave is originally based on the heart rate example. However, many changes containing own services and characteristics (with own UUIDs) have been implemented since beginning of the project.  

For sniffing of the attached log file I first turned on the slave device, and filtered the displayed data based on the advertising data. Then I turned on the master. The master automatically connects to the slave. The master does not activate notification of the slave characteristic before connecting to the central. That’s why there seem to be a lot of empty packet exchanges in between the connection events (s. log file). After connecting to the central, the central activates notification of the master (to central), and the master activates notification of the slave (to master). After the master establishes connection to the central, the packets start to appear with the info “bad MIC”. Is the tool confused by the messages the master exchanges with the central to establish connection? The data format of the slave generally does not change, it only starts containing real data (no empty packets anymore).

Anyway, as I’m currently interested in the packet timing, the time stamps are relevant and should still be valid.

Do you have any idea for the variation of delay times regarding the data sent from the slave to the master? As mentioned, usually no packets get lost (this is verified by the incremented packet indexes).

Do you have any suggestion to deal with the “bad MIC” problem?

Thanks in advance!

 

 

 WiresharkLog.pcapng

[Sigurd]

Hi,

Pjay said:

Do you have any suggestion to deal with the “bad MIC” problem?

The link gets encrypted, and the sniffer is therefore unable to see the packet content. See chapter 5.4 and 5.5 in the Sniffer User guide.

Pjay said:

he problem of varying delay times between the packets can also be observed when looking at the time stamps of packet

I don't see any issues in the log. The connection interval is 15 ms (Delta time (µs start to start) for master + slave). For each connection event, the master sends a packet, and the slave responds. Then after 15 ms the next connection event starts. The slave is always just sending 1 packet per connection event.

Note that the "Time" field in the sniffer is not accurate(that is just the time stamp on UART on PC), the accurate timestamp is the "delta time" fields.

[Pjay]

Hi,

Sigurd said:

The link gets encrypted, and the sniffer is therefore unable to see the packet content.

I thought that sniffing is possible, as long as the encryption is initiated after starting of the sniffing, as it was during my procedure (s. here https://devzone.nordicsemi.com/f/nordic-q-a/14035/is-nrf-sniffer-doing-decryption). Is bonding mandatory for that? Or are the devices using encryption information which was exchanged during first connection?

Sigurd said:

I don't see any issues in the log. The connection interval is 15 ms (Delta time (µs start to start) for master + slave). For each connection event, the master sends a packet, and the slave responds. Then after 15 ms the next connection event starts. The slave is always just sending 1 packet per connection event.

Isn't the delta time just the time spend during a connection interval, defined by NRF_SDH_BLE_GAP_EVENT_LENGTH? That would be "the time set aside for this connection on every connection interval". But what I am interested in is the time difference between two adjacent connection intervals.
By the way: the min- and max-values for the connection intervals are set to 7.5ms in the software for all devices. The value for NRF_SDH_BLE_GAP_EVENT_LENGTH is set to 5, which should result in 6.25 ms.

And: what does the flag "More Data" (TRUE/FALSE) represent? I wasn't able to find this information in the user guide. The flag is TRUE for some of the packets send from the slave to the master...

[Sigurd]

Hi,

Pjay said:

what does the flag "More Data" (TRUE/FALSE) represent?

It means that the peripheral has more data to send. From the Bluetooth spec(BLUETOOTH SPECIFICATION Version 5.0 | Vol 6, Part B page 2642):

The MD bit of the Header of the Data Channel PDU is used to indicate that the device has more data to send. If neither device has set the MD bit in their packets, the packet from the slave closes the connection event. If either or both of the devices have set the MD bit, the master may continue the connection event by sending another packet, and the slave should listen after sending its packet. If a packet is not received from the slave by the master, the master will close the connection event. If a packet is not received from the master by the slave, the slave will close the connection event.

Pjay said:

Isn't the delta time just the time spend during a connection interval, defined by NRF_SDH_BLE_GAP_EVENT_LENGTH?

No. Delta is the time since previously recieved packet.

Looking at the event counter field, it seems like every other connection event is missed by the sniffer(maybe due to the encryption), OR since this is a multlink central, the connection events are being skipped so that it can scan for other devices.

1) Is the central doing scanning when it's connected to 1 peripheral?

2) if the central is not scanning, could you provide a sniffer-log where you are not encrypting the link ?

[Pjay]

Hi Sigurd,

Sigurd said:

1) Is the central doing scanning when it's connected to 1 peripheral?

No, the central device stops scanning after connecting to the Master (Relay).

Sigurd said:

2) if the central is not scanning, could you provide a sniffer-log where you are not encrypting the link ?

Please find the log file attached to this post. I disabled encryption by declining pairing using
sd_ble_gap_sec_params_reply(conn_handle,BLE_GAP_SEC_STATUS_PAIRING_NOT_SUPP, NULL, NULL);
I hope this is correct.

Wireshark_NoEncryption.pcapng

[Pjay]

Hi Sigurd,

the log files I have uploaded so far were related to the communication between the slave and the master/relay. As the master has to communicate with both the slave and the central, I think the log file of the master to central communication could be interesting as well (see attachment). I think that one cause of timing problems could be, that I have activated the connection length extension for the master. As the master has to handle two connections, this might be a problem. I also tested the communication with deactivated connection extension, and the result is very bad (many missing packets, see log file).

What is your opinion? Could this be the reason for sporadic timing problems?

WithConnExtension.pcapngWithoutConnExtension.pcapng

[Pjay]

Hi,

another question: as already stated I have activated data length extension and set MTU Size to 247. In my recent software, I have increased the transmitted data bytes from 64 to 82 bytes (sent from master/relay to central). Now, regularly some packets get lost (before all packets were received). If the available packet data size is 247 (or 244 without header), why does it matter if I transmit 64 or 82 bytes? Shouldn't the time needed for the 247 byte packet be the same?

[Sigurd]

Hi,

The latest sniffer log also has event counter increments of more than 1, and that happens when the device starts to send notifications. But you are not losing any packets (as the SN, NESN are in sync). So, it seems like the master is deliberately skipping connection events.

How did the setup look like when you captured the sniffer log ?Could you explain this some more ? How many devices, 2 or 3? 1 DK used for nRF Connect BLE app(acting as central master) that you connect to this relay device(acting as peripheral in this case) ? Is the relay device connected to anything else, I assume it can connect to another peripheral? Is the relay scanning for other peripherals?

Pjay said:

some packets get lost

How are you detecting this ?

[Pjay]

Hi,

altogether 3 devices are used: two self-developed boards with an NRF52, and one NRF52DK board.  One of the self-developed boards acts as relay, and at the beginning scans for the advertising message of the other board (“slave”). The relay connects to the slave but does not yet activate notification of the slave characteristic. The connection interval is 7.5ms. As long as the relay is only connected to the slave, it simultaneously sends out its own advertising message. The DK board is used as central master and scans for the advertising message of the relay. It automatically connects to the relay based on the UUID and then it activates notification of the relay service/characteristic. In that case, the relay activates notification of the corresponding characteristic of the slave. After that, none of the devices advertises or scans anymore.
The slave sends its data to the relay, the relay send preprocessed data to the central master. The master transmits the data via NRF_LOG-commands either by UART or RTT to the PC (NRF connect app is not involved!).
Each notification message contains a Message ID, which is incremented in every call to BLE-update. BLE-Update is called based on a timer interrupt event every 10ms. The relay sends its own message ID and the Message ID received by the slave to the central. In this way, it can be controlled if any packet was not received between slave and relay, and/or relay and central (by looking at the difference between the message IDs of two adjacent packets). When I speak of lost packets, I mean the case when the difference between two adjacent packets is larger than 1 because that indicates that the corresponding message was not received.

However, I think I found out why in wireshark the difference of the packet index between adjacent  packets is always 1 (i.e. no packet is lost), but the difference of “my” message ID is not always 1 between two adjacent packets: the reason is, that the call to BLE update function was not always successful. It occasionally returned NRF_ERROR_RESOURCES, that means that the message was not sent. In these cases, the (application) message ID was still incremented, so that ID differences > 1 occurred. Now, I have changed the code to repeat the call to BLE Update function in case of return value NRF_ERROR_RESOURCES and it seems that the problem is solved.

What exactly is meant with “resources”? Does it mean that there is not enough time left in the current connection interval? Or does it have anything to do with the transmit buffer size?

If the BLE update is called periodically in a fixed timing interval, does the timing between the call to BLE update function and the next connection event matter? What happens for example, if the function is called when the connection event has already started?

[Sigurd]

Pjay said:

What exactly is meant with “resources”? Does it mean that there is not enough time left in the current connection interval? Or does it have anything to do with the transmit buffer size?

NRF_ERROR_RESOURCES means that too many notifications are queued, and the internal buffers in the SoftDevice are full. If that happens, you can not queue any more notifications until the BLE_GATTS_EVT_HVN_TX_COMPLETE event occurs. You have 2 options, either call your update function in a loop until the function returns NRF_SUCCESS, or wait for the BLE_GATTS_EVT_HVN_TX_COMPLETE and then send the packet. (e.g. in ble_app_uart example we are just waiting in a loop).

Pjay said:

If the BLE update is called periodically in a fixed timing interval, does the timing between the call to BLE update function and the next connection event matter? What happens for example, if the function is called when the connection event has already started?

At the start of the connection event the peripheral will start to send all the data(notifications) in the internal buffer as fast as possible to the central. When the peripheral don't have any more data to send, the connection event ends, and the peripheral need to wait until the next connection event occurs before it can send data again. If the application is queuing up data to the softdevice fast enough, i.e. faster than the data is being sent over BLE(this is typically not the case), the whole connection event could possibly be used to send data. The internal buffer size is configured indirectly by setting the NRF_SDH_BLE_GAP_EVENT_LENGTH in sdk_config.h, so if you are having issues with NRF_ERROR_RESOURCES, I suggest increasing that value in the peripheral project.