Delay between characteristics changing and connected device getting notification of that change

[DiBosco]

Hi folks,

I have a system basically working with the following setup:

#define MIN_CONN_INTERVAL               MSEC_TO_UNITS(7.5, UNIT_1_25_MS)      
#define MAX_CONN_INTERVAL               MSEC_TO_UNITS(7.5, UNIT_1_25_MS)       
#define SLAVE_LATENCY                   0      

I have a custom service with four characteristics that allow data to get from Nordic to PC (running Linux, not Windows or OSX) with handshaking in the following way:

PC Puts data in char1

Nordic gets new data and then:

Nordic writes value to char2 which tells the PC the Nordic has got the data and has enough space in its buffer for the PC to send more data. PC then pus updated version in char1 and so on...

The other two characteristics work for data being sent the other way.

Now, this works fine apart from the fact that there's a big old delay between data being put in a characteristic and the other end getting notification of that change. One problem is I don't know whether this is a delay between the Nordic picking up what the PC has changed or the PC picking up what the Nordic has changed.

I have put measurements at the PC end so I can tell that from a characteristic changed by the Nordic to tell the PC it is ready for more data it takes 140ms between updates. ie it is a round trip of 140ms, which is far too long!

Nordic writes to char2, PC updates char 1. Between the PC picking up that change in char2 and updating char1 there is less than a millisecond.

From the Nordic picking up the change in  char1 and putting a new value in char2 to twell the PC it can update char1 there is less than a millisecond.

So, there is either:

A delay in the soft device updating the characteristic after its API is called or:

A delay in the PC picking up the change in the characteristic or:

A delay in the PC from the application writing to the characteristic and it appearing "on air" or:

A delay in the soft device from picking up the change in char1 to sending it to my software running on the Nordic.

Or some combination of these. 

Are there any settings I have not tweaked that might be causing this? If so, what migt they be?

Can anyone think of anything I can do to track down exactly where the problem might be please? If I could toggle a pin on the PC when it picks up a change in char2 that might help I guess, but the days of parallel ports are long gone! ;)

Many thanks.

[tesc]

Hi,

A sniffer trace should reveal quite clearly what is going on over-the-air, and by that reveal where you get the delays. That should narrow it down enough that you can investigate the device and piece of code responsible for the delay.

Regards,
Terje

[DiBosco]

Hi,

Many thanks for the reply. How does this know, though, when a characterstic change reaches various stages

So: PC changes charactersitc. Goes out on to the air. How can this know the delay between Qt program on computer writing to the chatacteristic and that change appearing on the air?

Then how does it know how long it has taken the on air change to hit my custom hardware with the nRF on it? In terms of the hardware detecting the change, the soft machine detecting the change and it finally bubbling through to my custom app on the nRF?

Similarly going the other way, my app writes to the soft device; how on earth does the sniffer know when this has happened and what the delay is between that charcractersitc having been changed and it appearing on air, let alone how we time between writing to the soft device API and the change being detected on the PC?

I must be missing something fundamental here! Thanks. :)

[tesc]

Hi,

I may have misunderstood your use case, but it sounded like it was a back-and-forth sending of values between the devices. (Writing one way, then notification the other way, then writing the first way again, etc.)

With a sniffer trace you can see when each message is sent over-the-air, and thereby you get the delays e.g. from pc writes to char1 until nRF sends notification for write on char2.

And vice versa, you can see what is the delay between notification sent on char2 until write happens on char1.

E.g. you should be able to figure out in what "end" of the connection the delay is happening. (Either on pc side, on nRF side, or both.)

Then you know if you should debug more on the PC side, or on the nRF side, in order to figure out why the delay is there...

Regards,
Terje

[DiBosco]

It's equally as likely I'm missing something, but...

...I still don't know how this sniffer knows, after the PC posts an updated value, at what point the nRF has detected that signal. Surely the sniffer can on;y tell when:

a. the computer has put a new calue in the characterstic and it's on the air.

b. When the nRF has done the same thing.

I don't get how the sniffer has any clue about what goes on internally in both the nRF and the computer. eg The delay bewteeen the new value appearing on air and the soft device presenting that change to the app.

My Linux laptop can give me a time stamp of when it puts a characteristic change on air with BT mon, but there's no way of measuring the time between the laptop positing the value on air and that value popping out of the soft device.

Maybe I'm not explaining this very well. :/ Maybe I need to draw a diagram of what I'm on about?

[tesc]

Hi,

The sniffer can only tell when messages are sent, yes.

But if the behavior of the devices is to respond as quickly as possible to GATT writes and/or notifications, then you can measure the time between a and b, and between b and a, in your description.

Then you know the delay from a write is sent over the air, until the notification (with a new value) is sent back, and so you can tell how quickly the nRF does its job. E.g. you know the total time for the nRF to register the value, find the new value, and respond with a notification.

Similarly, you will see the total time for the PC to process an incoming notification until the write has been sent over-the-air.

A diagram of what is happening would be great for clearing up misunderstandings, yes!

Regards,
Terje

[DiBosco]

Sorry for the delay, been on other stuff.

OK, this first one hopefully shows what I mean. The Qt app (top left) posts an update to a characteristic. The sniffer can then see when that comes on air. However, the sniffer has no chance (as far as I can tell) of knowing when the soft device posts that value to my app or, indeed, when the soft device even first becomes aware of that characteristic change.

Similarly the other way. My app on the nRF posts a change in the return characteristic, the sniffer can see that on air, but how does it know when the laptop running the Qt app has notification?

btmon on the laptop might well have the same kind of info as the sniffer.

I've tried a crude timeline above too to try and make the point.

I know that the nRF app turns around quickly from getting a notification from the soft device, to posting a change in the "handshake" characteristic annd I know at the Qt end there is a similar fast turn around once the handshake characteristic change is detected and the Qt app posts the next packet of data.

So, am I missing something? If not, are there any common gotchas for this kind of thing?

Thanks!

[tesc]

Hi,

To reiterate your notes from your first image:

1. Laptop posts data (sniffer can timestamp)
2. nRF receives change notification (sniffer cannot timestamp)
3. nRF posts data (sniffer can timestamp)
4. laptop receives change notification (sniffer cannot timestamp)

I was under the impression that:

• on the nRF side, 2. triggers 3., and this should happen as quickly as possible
• on the laptop side, 4. triggers 1., and this should happen as quickly as possible
• the round-trip, e.g. 1-2-3-4, or 3-4-1-2, is very long, but we do not know where it takes so long (e.g. is it the laptop or the nRF?)

With sniffer timestamps we can measure the time spent on either side from rx to tx on that side.

In the below drawing, I have drawn the transmissions (visible to the sniffer) in green, and marked various time intervals. It is a bit simplified on the laptop side, since you probably have multiple layers in the stack there, but in any case there will be a delay between over-the-air traffic and logging (no matter how "far down in the stack" the logging happens.)

The main point is: If we rely on software running on one of the sides, we do not know what portion of time is spent "between rx and tx on the other side", and what portion of time is spent "by radio software on the local side". With the sniffer log we know for sure what the "reaction time" is for each device.

In addition to that, useful things in the sniffer log that I have not mentioned yet:

• if link layer packets are resent
• in the case of writes, if there is long writes (a value written to a characteristic is so long it gets sent with several packets)
• what connection parameters are negotiated
• +++ (basically we get an authoritative source for everything going on over-the-air.)

Regards,
Terje

[DiBosco]

Hi Terje,

Sorry for the delay, holidays and getting dragged off to other things has delayed this.

I suspect I am still missing something fundamental here. Sorry if I'm repeating myself and not explaining myself well here, but I just don't understand how this helps in seeing what goes on in the software on our custom hardware that has the Nordic device on it.

How does the sniffer get into our custom hardware/software to see where these delays are happening? Do we have to have some sort of UART connection from our custom hardware to the sniffer? If not. the sniffer, surely, can simply see what's happening on the airwaves and not if our Nordic code is resending or putting in delays?

What am I not understanding here?

Thanks again and sorry if I'm being slow.

[tesc]

Hi,

It is in order to see which side is responsible for the delays. Further debugging is next step.

Regards,
Terje