Occasionally large latency

[jonappleseed]

I have run many tests using the light_switch demo. I have noticed that occasionally the latency is much larger. The latency jump is between sends, i.e. it will send 20 times with avg latency of 100ms then the 21st time it will be 1000ms, then resume to normal. Is this because the board is busy in these instances? I am doing group sending.

N.B. This happens with all configs e.g. different packet sizes, instaburst on/off

My timing code works as follows:

At sending:

static void button_event_handler(...){
    ...
    status = generic_onoff_client_set(&m_clients[1], &set_params, &transition_params);            
    hal_led_pin_set(BSP_LED_1, set_params.on_off);
    tx_timestamp = NRF_RTC0->COUNTER; // tx_timestamp is a global
    ...
}

And receiving:

uint32_t time_calc(uint32_t initial, uint32_t final) {
    uint32_t delta = ((final - initial) * 1000) / 32768;
    return delta;
}

static void app_generic_onoff_client_status_cb(...) {
    ...
    uint32_t ts = tx_timestamp;
    uint32_t rtt = time_calc(ts, NRF_RTC0->COUNTER);
    ...
}

[Hung Bui]

Hi,

Could you let me know how do you trigger sending on your client board ? Is it by pressing the button ? And it's always on the 21st time it will have 1000ms delay ?

How long is between each press ? (between each 21st time where you see 1000ms delay )

Could you try disable proxy feature and check if you still see the issue ? 

How many nodes in your network ? Could you try to send to a unicast address , not to a group address ? 

1000ms delay is quite long and I don't see any reason why it would take that long to get the ACK. 

[jonappleseed]

I have a script which uses RTT to do this. It will send 0 to the board every 5 seconds. 21st and 1000 ms were just examples. I run my tests 100 times and large latencies occur maybe 3-5 times. 15 node network. Disabling the proxy feature seemed to have no effect. It even occasionally goes up to 10,000 ms!

[Hung Bui]

Could you give some more information about the number of hops ? How is your 15 nodes distributed, the distance between them, Txpower ? Are all of them configured as relay node?

When you sending the message to a group address, how do you handle multiple responses ? 

[jonappleseed]

It happens regardless of tx power, I've tried 0, 4 and 8 dBm. app_generic_onoff_client_status_cb() is called whenever a status message is received. For each response:

__LOG(LOG_SRC_APP, LOG_LEVEL_INFO, "reply for 0x%04x from 0x%04x in %lu ms | ttl: %u | rssi: %d | %u -> %u \r\n",
                  p_in->src,
                  p_meta->src.value,
                  rtt,
                  p_meta->ttl,
                  p_meta->p_core_metadata->params.scanner.rssi,
                  p_in->present_on_off,
                  p_in->target_on_off);

Yes, they are configured as relays. It also happens when I run a many-to-many case in which nodes are sending to subsets of the testbed. The testbed has a few nodes on a lower floor and the two floors are about 50mx20m. Multi-hop is roughly 2-3 hops, some are single hop.

[Hung Bui]

Could you try to reduce the number of node to the minimum that you can reproduce the issue ? Or you can start with 2 nodes and check if you can see the issue ? 

This would help us to reduce the issue here. 

The latency of 10s doesn't make much sense, how many retries you have with your set command  ?

Please test with as little modification to the example code as possible. 

How big is your packet ? Please try to minimize the payload to one single packet. 

Our latency test here showing with 4 hops the average latency was about 230ms with peak to 332ms. (20ms advertising interval)

[jonappleseed]

This happens as soon as the messages are segmented (>11 bytes at the app layer). Still the average is low, just the occasional high latency. Do know if this a Bluetooth mesh problem?