I2S and Zigbee Router strange behavior

[Renan Auguto Starke]

SoC: nrf52840

SDK: OpenConnect 2.4.4

I have been developing an ambient noise system using I2C microphone, nrf52840 and Zigbee networks for some time. The firmare reads 1 minute of ambient noise, filters for eight different frequencies and publishes RMS values using a customized Zigbee cluster.

Battery power devices, end-devices, are working fine. They stay online for weeks/months until the battery runs out. They never stop.

I also have another firmware with the same functionality, but it is a Zigbee router. This version also reads 1 minute of ambient noise, filters for eight different frequencies and publishes RMS values using the same customized Zigbee cluster.

Unfortunately, with the router version I’m struggling to solve a problem with the I2S driver. After a while, It seems like it runs out o memory as shown in the following log:

Boot:

I: I2S MCK frequency: 1391304, actual PCM rate: 28985

I: Production configuration is not present or invalid (status: -1)

I: Zigbee stack initialized

I: Unimplemented signal (signal: 54, status: 0)

I: Joined network successfully on reboot signal (Extended PAN ID: 00124b002a2e8593, PAN ID: 0x1a62)

(...)

I: Unimplemented signal (signal: 54, status: 0)    <- Zigbee router signals

I: Unimplemented signal (signal: 54, status: 0)    

I: Unimplemented signal (signal: 50, status: 0)

I: Unimplemented signal (signal: 54, status: 0)

I: Unimplemented signal (signal: 50, status: 0)

4531 4476 4710 3625 3903 2864 2990 5111     <- RMS values (some serial debug)

E: k_mem_slab_max_used_get: 3                     <- slab usage

After hours or days:

I: Unimplemented signal (signal: 54, status: 0)

E: Failed to allocate next RX buffer: -12    <-- get_next_rx_buffer, return of k_mem_slab_alloc

E: No room in RX queue                             <--  k_msgq_put

E: Failed to read data: -5 590                      <-- i2s_read

I: Unimplemented signal (signal: 54, status: 0)

E: Failed to _trigger i2s interface: -5

After those errors, I can’t trigger i2s interface anymore, nor reconfigure it.   The application seems to be fine since the router keeps sending/receiving Zigbee messages but the audio thread can’t use I2S anymore.

BYTES_PER_SAMPLE = 4

SAMPLES_PER_BLOCK = 2800 ( SAMPLE_FREQUENCY / 10 )

#define BLOCK_SIZE  (BYTES_PER_SAMPLE * SAMPLES_PER_BLOCK)

#define BLOCK_COUNT (4)

/** @endcond */ /* internals_doc */

/*! @brief Create a kernel memory slab to store I2S data. Required for I2S driver. */

K_MEM_SLAB_DEFINE_STATIC(mem_slab, BLOCK_SIZE, BLOCK_COUNT, 4);

Since I have a dedicated slab for the I2S driver, it couldn't run out o memory, right? Could you give some insight to debug and solve this problem?

[Elfving]

Hello Renan, and sorry about the wait.

So this does sound a bit like a memory leak somewhere, or maybe a buffer that is not being released, on either on the Zigbee or i2s side. We could try to test this by lowering the memory, and see if that would provoke the problem quicker.

Though it is interesting that this is only a problem in the router devices. Is the firmware regarding the I2S driver also the same on the two different devices (end nodes and routers)?

Regards,

Elfving

[Renan Auguto Starke]

Hello Elfving,

Thank you for your reply. Regarding the question about I2S firmware, the nodes and routers use exactly the same code. The difference relies on the prj.conf and Zigbee clusters (routers don’t report battery information for instance). The router firmware is based on the zb_range_extender example but I have some cluster personalization (same as nodes).

Regarding memory usage, perhaps an increase in CONFIG_HEAP_MEM_POOL_SIZE and CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE can solve this problem?

some parts of prf.conf :

# Make sure printk is not printing to the UART console
# CONFIG_CONSOLE=y
# CONFIG_UART_CONSOLE=y

CONFIG_HEAP_MEM_POOL_SIZE=2048
CONFIG_MAIN_THREAD_PRIORITY=7

# This example requires more workqueue stack
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048

# Zigbee role
# CONFIG_ZIGBEE_ROLE_END_DEVICE=y
CONFIG_ZIGBEE_ROLE_ROUTER=y

/**
 * @brief Zephyr static thread. Issues noise measures and signal a Zigbee cluster update. 
 * Change k_sleep parameter to modify task measure interval.
 * 
 */
void i2s_audio_thread(void)
{
	int ret = 0;

	while (1) {		
		/* Read on-chip temperature */
		read_onchip_temperature();	
		
		/* Reads audio for 1 minute calculating noise for each octave band */
		filtered_rms_audio_reading();
		
		/* Singnal Zigbee cluser library to update registers values */
		schedule_cluster_update();

		/* Sleep for 14 minutes.
		 * 1 minute of reading plus 14 sleep minutes gives 
		 * 15 minutes for each measure. */
		k_sleep(K_MINUTES(14));
		//k_sleep(K_MINUTES(2));

	}
}

/**
 * @brief Get noise level in db using small data blocks. Noise 
 * is each band with octave filters.
 * 
 * RMS is calculated for each block, accumulated and stored in audio_levels struct.
 * 
 * @return 0 if success, error code if failure.
 */
int filtered_rms_audio_reading()
{
	float32_t global_rms = 0;
	void *mem_block;
	uint32_t block_size;	
	int ret;

	/* Blinks LED during audio measure */
	static bool led_on = true;
	dk_set_led(4, led_on);

	/* Microphone parameters */
	const mic_specs_t my_mic = INMP441;
		
	memset(data_block,0,sizeof(data_block));
	memset(&audio_levels,0,sizeof(audio_levels));
		
	/* Start I2S hardware */
	ret = i2s_trigger(host_i2s_rx_dev, I2S_DIR_RX, I2S_TRIGGER_START);

	if (ret < 0) {
		LOG_ERR("Failed to _trigger i2s interface: %d\n", ret);			
		return ret;
	}

	/* Discard some data blocks, microphone may have startup time 
	* (i.e. INMP441 up to 83ms) */
	LOG_DBG("Ignoring %d data blocks", INITIAL_BLOCKS);
	for (int j=0; j < INITIAL_BLOCKS; j++){
		ret = i2s_read(host_i2s_rx_dev, &mem_block, &block_size);
		
		if (ret < 0) {
			LOG_ERR("Failed to read data: %d\n", ret);			
			goto fail;
		}
		
		k_mem_slab_free(&mem_slab, &mem_block);
	}

	/* Read data blocks. Change BLOCKS_FOR_ONE_SECOND as necessary  */
	for (int i=0; i < BLOCKS_FOR_ONE_SECOND; i++){
	
		ret = i2s_read(host_i2s_rx_dev, &mem_block, &block_size);
		if (ret < 0) {
			LOG_ERR("Failed to read data: %d %d\n", ret, i);
			goto fail;
		}
				
		/* Convert everything to float */
		float_convert(mem_block, block_size/sizeof(int));
		/* Filter for all bands */
		for (int i = BAND_125; i < N_BANDS; i++) 
			octave_band_estimation(mem_block, (float *)data_block, block_size/sizeof(int), &audio_levels, i);
		
		/* Free kernel data for next blocks */
		k_mem_slab_free(&mem_slab, &mem_block);

		/* Blinks lead each second */
		if (i % 10 == 0) {
			led_on = !led_on;
			dk_set_led(4, led_on);
		}		
	}	

	/* Stop I2S Hardware */
	ret = i2s_trigger(host_i2s_rx_dev, I2S_DIR_RX, I2S_TRIGGER_STOP);
	if (ret < 0) {
		LOG_ERR("Failed to trigger (stop) i2s interface (read done): %d\n", ret);
	}
	
	/* Calculate reference amplitude value */
	const float mic_ref_ampl = pow(10, (my_mic.mic_sensitivity/20.0)) * \
								((1 << (SAMPLE_BIT_WIDTH - 1)) - 1);
	
	/* Calculate rms value for each band */
	for (int i = BAND_125; i < N_BANDS; i++) {
					
		arm_sqrt_f32(audio_levels.all_rms[i] / (float32_t)BLOCKS_FOR_ONE_SECOND, &audio_levels.all_rms[i]);
		global_rms += audio_levels.all_rms[i] * audio_levels.all_rms[i];
		audio_levels.all_rms[i] = my_mic.mic_offset_db + my_mic.mic_ref_db + 20 * log10(audio_levels.all_rms[i]/mic_ref_ampl);
	} 

	//arm_sqrt_f32(global_rms / (float32_t)N_BANDS, &global_rms);
	arm_sqrt_f32(global_rms, &global_rms);
	audio_levels.global_rms = my_mic.mic_offset_db + my_mic.mic_ref_db + 20 * log10(global_rms/mic_ref_ampl);

	/* Debug uart export */
	char buffer[64] = {0};
	int noise[8] = {0};
	/* Convert everything to int using 2 decimal values 
		* %f crashes app. libc bug?					*/
	for (int i=0; i < 8; i++)
		noise[i] = audio_levels.all_rms[i] * 100;
	
	#ifdef UART_DEBUG
	snprintf(buffer,64,"%d %d %d %d ", 		
		noise[0], noise[1], noise[2], noise[3]);		
	print_uart(buffer);
	
	snprintf(buffer,64,"%d %d %d %d\n", 
		noise[4], noise[5], noise[6], noise[7]);
	print_uart(buffer);
	#endif

	int max_slabs = k_mem_slab_max_used_get(&mem_slab);
	LOG_ERR("k_mem_slab_max_used_get: %d\n", max_slabs);

	/* Reset everything */
	global_rms = 0;
	memset(buffer,0,sizeof(buffer));

	/* Turn off LED */
	dk_set_led(4, false);

	/* Update values */
	k_mutex_lock(&audio_data_mutex, K_FOREVER);
	memcpy(&audio_levels_protected, &audio_levels, sizeof(noise_levels_t));	
	k_mutex_unlock(&audio_data_mutex);

	return 0;

fail:
	/* Reset values */
	k_mutex_lock(&audio_data_mutex, K_FOREVER);
	memset(&audio_levels_protected,0,sizeof(noise_levels_t));	
	k_mutex_unlock(&audio_data_mutex);

	max_slabs = k_mem_slab_max_used_get(&mem_slab);
	LOG_ERR("k_mem_slab_max_used_get (failed): %d\n", max_slabs);

	k_mem_slab_free(&mem_slab, &mem_block);
	int trigger_stop = i2s_trigger(host_i2s_rx_dev, I2S_DIR_RX, I2S_TRIGGER_STOP);
	if (trigger_stop < 0) {
		LOG_ERR("Failed to trigger (stop) i2s interface (fail): %d\n", ret);

		audio_init();
	}

	return ret;
}

[Elfving]

Renan Auguto Starke said:

Regarding memory usage, perhaps an increase in CONFIG_HEAP_MEM_POOL_SIZE and CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE can solve this problem?

Maybe, but I am afraid that could also just post-pone it in case that it is due to a memory leak.

Try lowering it, and see if it once again crashes after a bit, but sooner.

Regards,

Elfving

[Renan Auguto Starke]

Hi Elfving,

I’ve increased CONFIG_HEAP_MEM_POOL_SIZE and CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE to 4096 and, as you said, it just postponed the problem.

Furthermore the problem happens as soon as I increase the number of end-devices connected to that particular router.

Now I will try to lower MEM_POLL and WQ_STACK_SIZE.

0xf4ce36405c52c777 is the router.

Logs:

4934 4145 3934 4036 4078 3694 3978 5163   <- RMS values

E: k_mem_slab_max_used_get: 3               <- I2S SLAB usage

W: Parent is unreachable

W: Parent is unreachable

W: Parent is unreachable

W: Parent is unreachable

W: Parent is unreachable

W: Parent is unreachable

W: Parent is unreachable

W: Parent is unreachable

I: Unimplemented signal (signal: 50, status: 0)

E: Failed to allocate next RX buffer: -12                        <- No more memory

E: Failed to read data: -5 140

E: k_mem_slab_max_used_get (failed): 4

E: Failed to trigger (stop) i2s interface (fail): -5

From no on, I2S interface is dead, but the ZB stack is still working.

[Elfving]

It might be out of buffers. Try checking with:

zb_buf_is_oom_state() which should return true if it out of buffers 

and zb_buf_memory_low() which shows if there are few buffers left.

Are you doing something obvious on the app side that consumes memory?

Regards,

Elfving