fix spdif+spotify stuttering and refactor stats => add pseudo_idle chained callbacks

components/services/monitor.c

@@ -14,6 +14,7 @@
 #include "freertos/timers.h"
 #include "esp_system.h"
 #include "esp_log.h"
+#include "esp_task.h"
 #include "monitor.h"
 #include "driver/gpio.h"
 #include "buttons.h"
@@ -25,15 +26,14 @@
 #include "cJSON.h"
 #include "tools.h"
 
+#define PSEUDO_IDLE_STACK_SIZE	(3*1024)
+
 #define MONITOR_TIMER	(10*1000)
 #define SCRATCH_SIZE	256
 
 static const char *TAG = "monitor";
 
-static TimerHandle_t monitor_timer;
-
-static monitor_gpio_t jack = { CONFIG_JACK_GPIO, 0 };
-static monitor_gpio_t spkfault = { CONFIG_SPKFAULT_GPIO, 0 };
+void (*pseudo_idle_svc)(uint32_t now);
 
 void (*jack_handler_svc)(bool inserted);
 bool jack_inserted_svc(void);
@@ -41,36 +41,39 @@ bool jack_inserted_svc(void);
 void (*spkfault_handler_svc)(bool inserted);
 bool spkfault_svc(void);
 
+static monitor_gpio_t jack = { CONFIG_JACK_GPIO, 0 };
+static monitor_gpio_t spkfault = { CONFIG_SPKFAULT_GPIO, 0 };
+static bool monitor_stats;
 
 /****************************************************************************************
- * 
+ *
  */
 static void task_stats( cJSON* top ) {
-#ifdef CONFIG_FREERTOS_USE_TRACE_FACILITY 
+#ifdef CONFIG_FREERTOS_USE_TRACE_FACILITY
 #pragma message("Compiled with trace facility")
 	static struct {
 		TaskStatus_t *tasks;
 		uint32_t total, n;
 	} current, previous;
+    
 	cJSON * tlist=cJSON_CreateArray();
 	current.n = uxTaskGetNumberOfTasks();
 	current.tasks = malloc_init_external( current.n * sizeof( TaskStatus_t ) );
 	current.n = uxTaskGetSystemState( current.tasks, current.n, &current.total );
 	cJSON_AddNumberToObject(top,"ntasks",current.n);
-	
-	static EXT_RAM_ATTR char scratch[SCRATCH_SIZE];
-	*scratch = '\0';
+
+	char scratch[SCRATCH_SIZE] = { 0 };
 
 #ifdef CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS
 #pragma message("Compiled with runtime stats")
 	uint32_t elapsed = current.total - previous.total;
-    
+
 	for(int i = 0, n = 0; i < current.n; i++ ) {
 		for (int j = 0; j < previous.n; j++) {
 			if (current.tasks[i].xTaskNumber == previous.tasks[j].xTaskNumber) {
-				n += snprintf(scratch + n, SCRATCH_SIZE - n, "%16s (%u) %2u%% s:%5u", current.tasks[i].pcTaskName, 
+				n += snprintf(scratch + n, SCRATCH_SIZE - n, "%16s (%u) %2u%% s:%5u", current.tasks[i].pcTaskName,
 																		   current.tasks[i].eCurrentState,
-																		   100 * (current.tasks[i].ulRunTimeCounter - previous.tasks[j].ulRunTimeCounter) / elapsed, 
+																		   100 * (current.tasks[i].ulRunTimeCounter - previous.tasks[j].ulRunTimeCounter) / elapsed,
 																		   current.tasks[i].usStackHighWaterMark);
 				cJSON * t=cJSON_CreateObject();
 				cJSON_AddNumberToObject(t,"cpu",100 * (current.tasks[i].ulRunTimeCounter - previous.tasks[j].ulRunTimeCounter) / elapsed);
@@ -84,11 +87,11 @@ static void task_stats( cJSON* top ) {
 				if (i % 3 == 2 || i == current.n - 1) {
 					ESP_LOGI(TAG, "%s", scratch);
 					n = 0;
-				}	
+				}
 				break;
 			}
 		}
-	}	
+	}
 #else
 #pragma message("Compiled WITHOUT runtime stats")
 
@@ -105,21 +108,26 @@ static void task_stats( cJSON* top ) {
 		if (i % 3 == 2 || i == current.n - 1) {
 			ESP_LOGI(TAG, "%s", scratch);
 			n = 0;
-		}	
+		}
 	}
-#endif	
+#endif
 	cJSON_AddItemToObject(top,"tasks",tlist);
 	if (previous.tasks) free(previous.tasks);
 	previous = current;
-#else 
-#pragma message("Compiled WITHOUT trace facility")	
-#endif	
+#else
+#pragma message("Compiled WITHOUT trace facility")
+#endif
 }
- 
+
 /****************************************************************************************
- * 
+ *
  */
-static void monitor_callback(TimerHandle_t xTimer) {
+static void monitor_trace(uint32_t now) {
+    static uint32_t last;
+
+    if (now < last + MONITOR_TIMER) return;
+    last = now;
+
 	cJSON * top=cJSON_CreateObject();
 	cJSON_AddNumberToObject(top,"free_iram",heap_caps_get_free_size(MALLOC_CAP_INTERNAL));
 	cJSON_AddNumberToObject(top,"min_free_iram",heap_caps_get_minimum_free_size(MALLOC_CAP_INTERNAL));
@@ -133,7 +141,7 @@ static void monitor_callback(TimerHandle_t xTimer) {
 			heap_caps_get_minimum_free_size(MALLOC_CAP_SPIRAM),
 			heap_caps_get_free_size(MALLOC_CAP_DMA),
 			heap_caps_get_minimum_free_size(MALLOC_CAP_DMA));
-			
+
 	task_stats(top);
 	char * top_a= cJSON_PrintUnformatted(top);
 	if(top_a){
@@ -144,7 +152,7 @@ static void monitor_callback(TimerHandle_t xTimer) {
 }
 
 /****************************************************************************************
- * 
+ *
  */
 static void jack_handler_default(void *id, button_event_e event, button_press_e mode, bool long_press) {
 	ESP_LOGI(TAG, "Jack %s", event == BUTTON_PRESSED ? "inserted" : "removed");
@@ -152,7 +160,7 @@ static void jack_handler_default(void *id, button_event_e event, button_press_e
 }
 
 /****************************************************************************************
- * 
+ *
  */
 bool jack_inserted_svc (void) {
 	if (jack.gpio != -1) return button_is_pressed(jack.gpio, NULL);
@@ -160,7 +168,7 @@ bool jack_inserted_svc (void) {
 }
 
 /****************************************************************************************
- * 
+ *
  */
 static void spkfault_handler_default(void *id, button_event_e event, button_press_e mode, bool long_press) {
 	ESP_LOGD(TAG, "Speaker status %s", event == BUTTON_PRESSED ? "faulty" : "normal");
@@ -170,22 +178,22 @@ static void spkfault_handler_default(void *id, button_event_e event, button_pres
 }
 
 /****************************************************************************************
- * 
+ *
  */
 bool spkfault_svc (void) {
 	return button_is_pressed(spkfault.gpio, NULL);
 }
 
 /****************************************************************************************
- * 
+ *
  */
 #ifndef CONFIG_JACK_LOCKED
 static void set_jack_gpio(int gpio, char *value) {
 	if (strcasestr(value, "jack")) {
 		char *p;
-		jack.gpio = gpio;	
+		jack.gpio = gpio;
 		if ((p = strchr(value, ':')) != NULL) jack.active = atoi(p + 1);
-	}	
+	}
 	else {
 		jack.gpio = -1;
 	}
@@ -193,15 +201,15 @@ static void set_jack_gpio(int gpio, char *value) {
 #endif
 
 /****************************************************************************************
- * 
+ *
  */
 #ifndef CONFIG_SPKFAULT_LOCKED
 static void set_spkfault_gpio(int gpio, char *value) {
 	if (strcasestr(value, "spkfault")) {
 		char *p;
-		spkfault.gpio = gpio;	
+		spkfault.gpio = gpio;
 		if ((p = strchr(value, ':')) != NULL) spkfault.active = atoi(p + 1);
-	}	
+	}
 	else {
 		spkfault.gpio = -1;
 	}
@@ -209,28 +217,41 @@ static void set_spkfault_gpio(int gpio, char *value) {
 #endif
 
 /****************************************************************************************
- * 
+ *
+ */
+static void pseudo_idle(void *arg) {
+    while (1) {
+        vTaskDelay(pdMS_TO_TICKS(1000));
+        uint32_t now = pdTICKS_TO_MS(xTaskGetTickCount());
+
+        if (monitor_stats) monitor_trace(now);
+        if (pseudo_idle_svc) pseudo_idle_svc(now);
+    }
+}
+
+/****************************************************************************************
+ *
  */
 void monitor_svc_init(void) {
 	ESP_LOGI(TAG, "Initializing monitoring");
-	
+
 #ifdef CONFIG_JACK_GPIO_LEVEL
 	jack.active = CONFIG_JACK_GPIO_LEVEL;
 #endif
 
 #ifndef CONFIG_JACK_LOCKED
 	parse_set_GPIO(set_jack_gpio);
-#endif	
+#endif
 
 	// re-use button management for jack handler, it's a GPIO after all
 	if (jack.gpio != -1) {
-		ESP_LOGI(TAG,"Adding jack (%s) detection GPIO %d", jack.active ? "high" : "low", jack.gpio);					 
+		ESP_LOGI(TAG,"Adding jack (%s) detection GPIO %d", jack.active ? "high" : "low", jack.gpio);
 		button_create(NULL, jack.gpio, jack.active ? BUTTON_HIGH : BUTTON_LOW, false, 250, jack_handler_default, 0, -1);
-	}	
-	
+	}
+
 #ifdef CONFIG_SPKFAULT_GPIO_LEVEL
 	spkfault.active = CONFIG_SPKFAULT_GPIO_LEVEL;
-#endif	
+#endif
 
 #ifndef CONFIG_SPKFAULT_LOCKED
 	parse_set_GPIO(set_spkfault_gpio);
@@ -238,18 +259,15 @@ void monitor_svc_init(void) {
 
 	// re-use button management for speaker fault handler, it's a GPIO after all
 	if (spkfault.gpio != -1) {
-		ESP_LOGI(TAG,"Adding speaker fault (%s) detection GPIO %d", spkfault.active ? "high" : "low", spkfault.gpio);					 
+		ESP_LOGI(TAG,"Adding speaker fault (%s) detection GPIO %d", spkfault.active ? "high" : "low", spkfault.gpio);
 		button_create(NULL, spkfault.gpio, spkfault.active ? BUTTON_HIGH : BUTTON_LOW, false, 0, spkfault_handler_default, 0, -1);
-	}	
+	}
 
 	// do we want stats
 	char *p = config_alloc_get_default(NVS_TYPE_STR, "stats", "n", 0);
-	if (p && (*p == '1' || *p == 'Y' || *p == 'y')) {
-		monitor_timer = xTimerCreate("monitor", MONITOR_TIMER / portTICK_RATE_MS, pdTRUE, NULL, monitor_callback);
-		xTimerStart(monitor_timer, portMAX_DELAY);
-	}	
+	monitor_stats = p && (*p == '1' || *p == 'Y' || *p == 'y');
 	FREE_AND_NULL(p);
-	
+
 	ESP_LOGI(TAG, "Heap internal:%zu (min:%zu) external:%zu (min:%zu) dma:%zu (min:%zu)",
 			heap_caps_get_free_size(MALLOC_CAP_INTERNAL),
 			heap_caps_get_minimum_free_size(MALLOC_CAP_INTERNAL),
@@ -257,18 +275,24 @@ void monitor_svc_init(void) {
 			heap_caps_get_minimum_free_size(MALLOC_CAP_SPIRAM),
 			heap_caps_get_free_size(MALLOC_CAP_DMA),
 			heap_caps_get_minimum_free_size(MALLOC_CAP_DMA));
+
+    // pseudo-idle callback => don't use FreeRTOS idle callbacks so we can block (should not but ...)
+	StaticTask_t* xTaskBuffer = (StaticTask_t*) heap_caps_malloc(sizeof(StaticTask_t), MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT);
+	static EXT_RAM_ATTR StackType_t xStack[PSEUDO_IDLE_STACK_SIZE] __attribute__ ((aligned (4)));
+	xTaskCreateStatic( (TaskFunction_t) pseudo_idle, "pseudo_idle", PSEUDO_IDLE_STACK_SIZE,
+						NULL, ESP_TASK_PRIO_MIN, xStack, xTaskBuffer );
 }
 
 /****************************************************************************************
- * 
+ *
  */
  monitor_gpio_t * get_spkfault_gpio(){
-	return &spkfault	; 
- } 
+	return &spkfault	;
+ }
 
 /****************************************************************************************
- * 
+ *
  */
  monitor_gpio_t * get_jack_insertion_gpio(){
 	return &jack;
-} 
+}

components/services/monitor.h

@@ -14,6 +14,8 @@ typedef struct {
 	int active;
 }  monitor_gpio_t;	
 
+extern void (*pseudo_idle_svc)(uint32_t now);
+
 extern void (*jack_handler_svc)(bool inserted);
 extern bool jack_inserted_svc(void);
 

components/squeezelite/equalizer.c

@@ -129,7 +129,9 @@ void equalizer_set_volume(unsigned left, unsigned right) {
     // do classic dB conversion and scale it 0..100
 	if (volume) volume = log2(volume);
 	volume = volume / 16.0 * 100.0;
-    if (volume != equalizer.volume) {
+    
+    // LMS has the bad habit to send multiple volume commands
+    if (volume != equalizer.volume && equalizer.loudness) {
         equalizer.volume = volume;
         calculate_loudness();
         equalizer.update = true;
@@ -144,15 +146,17 @@ void equalizer_set_gain(int8_t *gain) {
 #if BYTES_PER_FRAME == 4
     char config[EQ_BANDS * 4 + 1] = { };
 	int n = 0;
-
-	for (int i = 0; i < EQ_BANDS; i++) {
+    
+    for (int i = 0; i < EQ_BANDS; i++) {
 		equalizer.gain[i] = gain[i];
 		n += sprintf(config + n, "%d,", gain[i]);
 	}
 
 	config[n-1] = '\0';
 	config_set_value(NVS_TYPE_STR, "equalizer", config);
-	equalizer.update = true;
+    
+    // update only if something changed
+    if (!memcmp(equalizer.gain, gain, EQ_BANDS)) equalizer.update = true;
 
     LOG_INFO("equalizer gain %s", config);
 #else
@@ -165,14 +169,16 @@ void equalizer_set_gain(int8_t *gain) {
  */
 void equalizer_set_loudness(uint8_t loudness) {
 #if BYTES_PER_FRAME == 4
-    // update loudness gains as a factor of loudness and volume
-	equalizer.loudness = loudness / 10.0;
-    calculate_loudness();
-
     char p[4];
     itoa(loudness, p, 10);
     config_set_value(NVS_TYPE_STR, "loudness", p);
-    equalizer.update = true;
+    
+    // update loudness gains as a factor of loudness and volume
+    if (equalizer.loudness != loudness / 10.0) {
+        equalizer.loudness = loudness / 10.0;
+        calculate_loudness();
+        equalizer.update = true;
+    }
 
     LOG_INFO("loudness %u", (unsigned) loudness);
 #else

components/squeezelite/output_i2s.c

@@ -55,8 +55,10 @@ sure that using rate_delay would fix that
 #define SPDIF_BLOCK	256
 
 // must have an integer ratio with FRAME_BLOCK (see spdif comment)
-#define DMA_BUF_LEN		512	
-#define DMA_BUF_COUNT	12
+#define DMA_SIZE        6144
+// FRAME_BLOCK must be a multiple of DMA_BUF_LEN no matter what
+#define DMA_BUF_LEN		FRAME_BLOCK
+#define DMA_BUF_COUNT	(DMA_SIZE / DMA_BUF_LEN)
 
 #define DECLARE_ALL_MIN_MAX 	\
 	DECLARE_MIN_MAX(o); 		\
@@ -73,7 +75,7 @@ sure that using rate_delay would fix that
 	RESET_MIN_MAX(buffering);
 	
 #define STATS_PERIOD_MS 5000
-#define STAT_STACK_SIZE	(3*1024)
+static void (*pseudo_idle_chain)(uint32_t now);
 
 #ifndef CONFIG_AMP_GPIO_LEVEL
 #define CONFIG_AMP_GPIO_LEVEL 1
@@ -101,8 +103,7 @@ static struct {
 	size_t count;
 } spdif;
 static size_t dma_buf_frames;
-static TaskHandle_t stats_task, output_i2s_task;
-static bool stats;
+static TaskHandle_t output_i2s_task;
 static struct {
 	int gpio, active;
 } amp_control = { CONFIG_AMP_GPIO, CONFIG_AMP_GPIO_LEVEL },
@@ -113,7 +114,7 @@ DECLARE_ALL_MIN_MAX;
 static int _i2s_write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t gainR, u8_t flags,
 								s32_t cross_gain_in, s32_t cross_gain_out, ISAMPLE_T **cross_ptr);
 static void output_thread_i2s(void *arg);
-static void output_thread_i2s_stats(void *arg);
+static void i2s_stats(uint32_t now);
 static void spdif_convert(ISAMPLE_T *src, size_t frames, u32_t *dst, size_t *count);
 static void (*jack_handler_chain)(bool inserted);
 
@@ -251,8 +252,6 @@ void output_init_i2s(log_level level, char *device, unsigned output_buf_size, ch
         return;
     }
     
-	/* BEWARE: i2s.c must be patched otherwise L/R are swapped in 32 bits mode */
-	 
 	// common I2S initialization
 	i2s_config.mode = I2S_MODE_MASTER | I2S_MODE_TX;
 	i2s_config.channel_format = I2S_CHANNEL_FMT_RIGHT_LEFT;
@@ -410,17 +409,11 @@ void output_init_i2s(log_level level, char *device, unsigned output_buf_size, ch
 	
 	// do we want stats
 	p = config_alloc_get_default(NVS_TYPE_STR, "stats", "n", 0);
-	stats = p && (*p == '1' || *p == 'Y' || *p == 'y');
-	free(p);
-	
-	// memory still used but at least task is not created
-	if (stats) {
-		// we allocate TCB but stack is static to avoid SPIRAM fragmentation
-		StaticTask_t* xTaskBuffer = (StaticTask_t*) heap_caps_malloc(sizeof(StaticTask_t), MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT);
-		static EXT_RAM_ATTR StackType_t xStack[STAT_STACK_SIZE] __attribute__ ((aligned (4)));
-		stats_task = xTaskCreateStatic( (TaskFunction_t) output_thread_i2s_stats, "output_i2s_sts", STAT_STACK_SIZE, 
-										 NULL, ESP_TASK_PRIO_MIN, xStack, xTaskBuffer);
-	}	
+	if (p && (*p == '1' || *p == 'Y' || *p == 'y')) {
+        pseudo_idle_chain = pseudo_idle_svc;
+        pseudo_idle_svc = i2s_stats;
+	}
+    free(p);
 }
 
 
@@ -433,7 +426,6 @@ void output_close_i2s(void) {
 	UNLOCK;
 	
 	while (!ended) vTaskDelay(20 / portTICK_PERIOD_MS);
-	if (stats) vTaskDelete(stats_task);
 	
 	i2s_driver_uninstall(CONFIG_I2S_NUM);
 	free(obuf);
@@ -488,7 +480,7 @@ static void output_thread_i2s(void *arg) {
 	uint32_t fullness = gettime_ms();
 	bool synced;
 	output_state state = OUTPUT_OFF - 1;
-	
+    
 	while (running) {
 			
 		TIME_MEASUREMENT_START(timer_start);
@@ -537,7 +529,10 @@ static void output_thread_i2s(void *arg) {
 		_output_frames( iframes );
 		// oframes must be a global updated by the write callback
 		output.frames_in_process = oframes;
-						
+        
+        // force some sin
+        //memcpy(obuf, __obuf, oframes*BYTES_PER_FRAME);
+        						
 		SET_MIN_MAX_SIZED(oframes,rec,iframes);
 		SET_MIN_MAX_SIZED(_buf_used(outputbuf),o,outputbuf->size);
 		SET_MIN_MAX_SIZED(_buf_used(streambuf),s,streambuf->size);
@@ -628,33 +623,34 @@ static void output_thread_i2s(void *arg) {
 /****************************************************************************************
  * Stats output thread
  */
-static void output_thread_i2s_stats(void *arg) {
-	while (1) {
-		// no need to lock
-		output_state state = output.state;
-		
-		if(stats && state>OUTPUT_STOPPED){
-			LOG_INFO( "Output State: %d, current sample rate: %d, bytes per frame: %d",state,output.current_sample_rate, BYTES_PER_FRAME);
-			LOG_INFO( LINE_MIN_MAX_FORMAT_HEAD1);
-			LOG_INFO( LINE_MIN_MAX_FORMAT_HEAD2);
-			LOG_INFO( LINE_MIN_MAX_FORMAT_HEAD3);
-			LOG_INFO( LINE_MIN_MAX_FORMAT_HEAD4);
-			LOG_INFO(LINE_MIN_MAX_FORMAT_STREAM, LINE_MIN_MAX_STREAM("stream",s));
-			LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("output",o));
-			LOG_INFO(LINE_MIN_MAX_FORMAT_FOOTER);
-			LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec));
-			LOG_INFO(LINE_MIN_MAX_FORMAT_FOOTER);
-			LOG_INFO("");
-			LOG_INFO("              ----------+----------+-----------+-----------+  ");
-			LOG_INFO("              max (us)  | min (us) |   avg(us) |  count    |  ");
-			LOG_INFO("              ----------+----------+-----------+-----------+  ");
-			LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Buffering(us)",buffering));
-			LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("i2s tfr(us)",i2s_time));
-			LOG_INFO("              ----------+----------+-----------+-----------+");
-			RESET_ALL_MIN_MAX;
-		}
-		vTaskDelay( pdMS_TO_TICKS( STATS_PERIOD_MS ) );
-	}
+static void i2s_stats(uint32_t now) {
+    static uint32_t last;
+    
+    // first chain to next handler
+    if (pseudo_idle_chain) pseudo_idle_chain(now);
+    
+    // then see if we need to act
+    if (output.state <= OUTPUT_STOPPED || now < last + STATS_PERIOD_MS) return;  
+    last = now;
+    
+	LOG_INFO( "Output State: %d, current sample rate: %d, bytes per frame: %d", output.state, output.current_sample_rate, BYTES_PER_FRAME);
+	LOG_INFO( LINE_MIN_MAX_FORMAT_HEAD1);
+	LOG_INFO( LINE_MIN_MAX_FORMAT_HEAD2);
+	LOG_INFO( LINE_MIN_MAX_FORMAT_HEAD3);
+	LOG_INFO( LINE_MIN_MAX_FORMAT_HEAD4);
+	LOG_INFO(LINE_MIN_MAX_FORMAT_STREAM, LINE_MIN_MAX_STREAM("stream",s));
+	LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("output",o));
+	LOG_INFO(LINE_MIN_MAX_FORMAT_FOOTER);
+	LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec));
+	LOG_INFO(LINE_MIN_MAX_FORMAT_FOOTER);
+	LOG_INFO("");
+	LOG_INFO("              ----------+----------+-----------+-----------+  ");
+	LOG_INFO("              max (us)  | min (us) |   avg(us) |  count    |  ");
+	LOG_INFO("              ----------+----------+-----------+-----------+  ");
+	LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Buffering(us)",buffering));
+	LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("i2s tfr(us)",i2s_time));
+	LOG_INFO("              ----------+----------+-----------+-----------+");
+	RESET_ALL_MIN_MAX;
 }
 
 /****************************************************************************************