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);
    ...
}

[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?

[jonappleseed]

4 servers latency (this takes the min for each one)

14/05/2019 17:18:24	1	0x0105	0x0104	0x0106	0x0103	
14/05/2019 17:18:24	1	534	541	546	583	
14/05/2019 17:18:30	2	46	61	50	54	
14/05/2019 17:18:35	3	57	47	46	55	
14/05/2019 17:18:40	4	54	45	56	49	
14/05/2019 17:18:45	5	52	61	59	57	
14/05/2019 17:18:50	6	52	44	56	51	
14/05/2019 17:18:55	7	42	43	58	44	
14/05/2019 17:19:00	8	27	41	32	131	
14/05/2019 17:19:05	9	42	47	38	98	
14/05/2019 17:19:10	10	533	538	534	532	
14/05/2019 17:19:15	11	41	38	50	31	
14/05/2019 17:19:21	12	47	60	62	45	
14/05/2019 17:19:26	13	89	74	100	61	
14/05/2019 17:19:31	14	41	28	45	40	
14/05/2019 17:19:36	15	70	61	30	105	
14/05/2019 17:19:41	16	37	30	41	85	
14/05/2019 17:19:46	17	43	27	38	33	
14/05/2019 17:19:51	18	44	56	40	37	
14/05/2019 17:19:56	19	58	39	49	45	
14/05/2019 17:20:01	20	36	47	41	32	
14/05/2019 17:20:06	21	543	540	556	543	
14/05/2019 17:20:12	22	50	49	43	56	
14/05/2019 17:20:17	23	50	63	102	58	
14/05/2019 17:20:22	24	62	61	57	53	
14/05/2019 17:20:27	25	68	55	51	57	
14/05/2019 17:20:32	26	56	110	57	66	
14/05/2019 17:20:37	27	51	78	107	51	
14/05/2019 17:20:42	28	46	92	42	41	
14/05/2019 17:20:47	29	40	42	52	51	
14/05/2019 17:20:52	30	49	44	50	60	
14/05/2019 17:20:57	31	92	55	59	45	
14/05/2019 17:21:03	32	45	45	55	55	
14/05/2019 17:21:08	33	97	56	102	51	
14/05/2019 17:21:13	34	46	70	59	45	
14/05/2019 17:21:18	35	520	528	525	510	
14/05/2019 17:21:23	36	105	42	61	52	
14/05/2019 17:21:28	37	70	53	99	60	
14/05/2019 17:21:33	38	43	45	37	43	
14/05/2019 17:21:38	39	84	50	112	33	
14/05/2019 17:21:43	40	47	35	42	46	
14/05/2019 17:21:48	41	58	68	60	54	
14/05/2019 17:21:53	42	54	50	43	51	
14/05/2019 17:21:59	43	43	54	102	56	
14/05/2019 17:22:04	44	41	51	52	56	
14/05/2019 17:22:09	45	51	57	98	52	
14/05/2019 17:22:14	46	32	37	42	36	
14/05/2019 17:22:19	47	69	66	49	48	
14/05/2019 17:22:24	48	45	36	34	47	
14/05/2019 17:22:29	49	51	41	38	40	
14/05/2019 17:22:34	50	103	51	46	39	
14/05/2019 17:22:39	51	100	98	54	54	
14/05/2019 17:22:44	52	52	99	53	51	
14/05/2019 17:22:50	53	39	98	40	55	
14/05/2019 17:22:55	54	48	40	54	49	
14/05/2019 17:23:00	55	45	43	34	40	
14/05/2019 17:23:05	56	104	47	52	57	
14/05/2019 17:23:10	57	91	52	128	51	
14/05/2019 17:23:15	58	53	59	55	95	
14/05/2019 17:23:20	59	96	93	50	82	
14/05/2019 17:23:25	60	43	48	36	42	
14/05/2019 17:23:30	61	205	46	48	46	
14/05/2019 17:23:35	62	60	61	60	59	
14/05/2019 17:23:41	63	40	93	92	41	
14/05/2019 17:23:46	64	66	50	50	62	
14/05/2019 17:23:51	65	42	43	39	50	
14/05/2019 17:23:56	66	37	54	39	42	
14/05/2019 17:24:01	67	45	57	54	51	
14/05/2019 17:24:06	68	537	582	591	529	
14/05/2019 17:24:11	69	64	60	72	114	
14/05/2019 17:24:16	70	105	54	111	63	
14/05/2019 17:24:21	71	46	92	44	93	
14/05/2019 17:24:26	72	57	59	60	56	
14/05/2019 17:24:32	73	48	60	42	43	
14/05/2019 17:24:37	74	40	49	42	40	
14/05/2019 17:24:42	75	59	45	102	46	
14/05/2019 17:24:47	76	49	155	41	54	
14/05/2019 17:24:52	77	45	97	57	93	
14/05/2019 17:24:57	78	56	53	58	53	
14/05/2019 17:25:02	79	103	57	110	57	
14/05/2019 17:25:07	80	97	88	30	32	
14/05/2019 17:25:12	81	107	53	53	42	
14/05/2019 17:25:17	82	36	43	38	52	
14/05/2019 17:25:23	83	79	32	41	24	
14/05/2019 17:25:28	84	30	43	40	35	
14/05/2019 17:25:33	85	52	43	47	58	
14/05/2019 17:25:38	86	47	38	31	32	
14/05/2019 17:25:43	87	530	573	526	522	
14/05/2019 17:25:48	88	63	34	35	50	
14/05/2019 17:25:53	89	77	53	66	62	
14/05/2019 17:25:58	90	55	41	39	44	
14/05/2019 17:26:03	91	44	53	52	42	
14/05/2019 17:26:08	92	51	55	57	110	
14/05/2019 17:26:14	93	49	42	45	58	
14/05/2019 17:26:19	94	104	65	62	100	
14/05/2019 17:26:24	95	97	53	106	102	
14/05/2019 17:26:29	96	45	42	47	92	
14/05/2019 17:26:34	97	56	51	48	59	
14/05/2019 17:26:39	98	57	42	43	55	
14/05/2019 17:26:44	99	51	48	41	55	
14/05/2019 17:26:49	100	1014	1065	1017	1066	

[Hung Bui]

Hi Jon, 

Could you provide more info of the statistic? How many hops ? what was the payload size ? 

[jonappleseed]

14 bytes incl. opcode. This is all single hop. I am almost certain this is a result of the segmentation process.

[Hung Bui]

We are suspecting the responses from the servers has been collided. Are the response in one packet or they are also segmented message ? 

We would need to check which direction introduce the large latency. If possible could you toggle an GPIO pin on the client and on the servers when you send and receive respectively. So that we can measure the latency of the single direction from client to servers. 

You can use an oscilloscope or a digital analyzer to record the latency between the GPIOs toggle. 

Also please make sure the testing environment is not congested with other RF communication (wifi, other mesh , etc).