BT ring buffering

main/bt_app_core.c

@@ -97,13 +97,18 @@ static void bt_app_task_handler(void *arg)
                 free(msg.param);
             }
         }
+        else
+        {
+        	LOG_DEBUG("No messaged received from queue.");
+        }
     }
 }
 
 void bt_app_task_start_up(void)
 {
     s_bt_app_task_queue = xQueueCreate(10, sizeof(bt_app_msg_t));
-    xTaskCreate(bt_app_task_handler, "BtAppT", 2048, NULL, configMAX_PRIORITIES - 3, &s_bt_app_task_handle);
+    assert(s_bt_app_task_queue!=NULL);
+    assert(xTaskCreate(bt_app_task_handler, "BtAppT", 2048, NULL, configMAX_PRIORITIES - 3, &s_bt_app_task_handle)==pdPASS);
     return;
 }
 

main/decode.c

@@ -199,7 +199,7 @@ void decode_init(log_level level, const char *include_codecs, const char *exclud
 	LOG_DEBUG("include codecs: %s exclude codecs: %s", include_codecs ? include_codecs : "", exclude_codecs);
 
 	mutex_create(decode.mutex);
-
+	PTHREAD_SET_NAME("decode");
 #if LINUX || OSX || FREEBSD || POSIX
 	pthread_attr_t attr;
 	pthread_attr_init(&attr);

main/embedded.h

@@ -1,4 +1,6 @@
 #pragma once
 #if defined(ESP_PLATFORM)
 #include "sdkconfig.h"
+#include "esp_pthread.h"
+#define PTHREAD_SET_NAME(n) 	{ esp_pthread_cfg_t cfg = esp_pthread_get_default_config(); cfg.thread_name= n; cfg.inherit_cfg = true; esp_pthread_set_cfg(&cfg); }
 #endif

main/esp32.c

@@ -27,19 +27,63 @@
 #include "esp_avrc_api.h"
 #include "esp_pthread.h"
 #include "pthread.h"
+
+const char *  art_a2dp_connected[]={"\n\n",
+		"           ___  _____  _____     _____                            _           _ _ \n",
+		"     /\\   |__ \\|  __ \\|  __ \\   / ____|                          | |         | | |\n",
+		"    /  \\     ) | |  | | |__) | | |     ___  _ __  _ __   ___  ___| |_ ___  __| | |\n",
+		"   / /\\ \\   / /| |  | |  ___/  | |    / _ \\| '_ \\| '_ \\ / _ \\/ __| __/ _ \\/ _` | |\n",
+		"  / ____ \\ / /_| |__| | |      | |___| (_) | | | | | | |  __/ (__| ||  __/ (_| |_|\n",
+		" /_/    \\_\\____|_____/|_|       \\_____\\___/|_| |_|_| |_|\\___|\\___|\\__\\___|\\__,_(_)\n\n",
+		"\0"};
+const char * art_a2dp_connecting[]= {"\n\n",
+		 "           ___  _____  _____     _____                            _   _                   \n",
+		 "     /\\   |__ \\|  __ \\|  __ \\   / ____|                          | | (_)                  \n",
+		 "    /  \\     ) | |  | | |__) | | |     ___  _ __  _ __   ___  ___| |_ _ _ __   __ _       \n",
+		 "   / /\\ \\   / /| |  | |  ___/  | |    / _ \\| '_ \\| '_ \\ / _ \\/ __| __| | '_ \\ / _` |      \n",
+		 "  / ____ \\ / /_| |__| | |      | |___| (_) | | | | | | |  __/ (__| |_| | | | | (_| |_ _ _ \n",
+		 " /_/    \\_\\____|_____/|_|       \\_____\\___/|_| |_|_| |_|\\___|\\___|\\__|_|_| |_|\\__, (_|_|_)\n",
+		 "                                                                               __/ |       \n",
+		 "                                                                              |___/        \n\n",
+		 "\0"};
+
+char * get_output_state_desc(output_state state){
+	switch (state) {
+	case OUTPUT_OFF:
+		return STR(OUTPUT_OFF);
+	case OUTPUT_STOPPED:
+		return STR(OUTPUT_STOPPED);
+	case OUTPUT_BUFFER:
+		return STR(OUTPUT_BUFFER);
+	case OUTPUT_RUNNING:
+		return STR(OUTPUT_RUNNING);
+	case OUTPUT_PAUSE_FRAMES:
+		return STR(OUTPUT_PAUSE_FRAMES);
+	case OUTPUT_SKIP_FRAMES:
+		return STR(OUTPUT_SKIP_FRAMES);
+	case OUTPUT_START_AT:
+		return STR(OUTPUT_START_AT);
+	default:
+		return "OUTPUT_UNKNOWN_STATE";
+	}
+	return "";
+}
 #define BT_AV_TAG               "BT_AV"
 extern log_level loglevel;
 extern struct outputstate output;
 extern struct buffer *outputbuf;
-extern struct buffer *streambuf;
+#ifdef USE_BT_RING_BUFFER
+#define LOCK_BT   mutex_lock(btbuf->mutex)
+#define UNLOCK_BT mutex_unlock(btbuf->mutex)
 extern struct buffer *btbuf;
-
+#else
+extern uint8_t * btout;
+#endif
 time_t disconnect_time=0;
 #define LOCK   mutex_lock(outputbuf->mutex)
 #define UNLOCK mutex_unlock(outputbuf->mutex)
-#define LOCK_BT   mutex_lock(btbuf->mutex)
-#define UNLOCK_BT mutex_unlock(btbuf->mutex)
 int64_t connecting_timeout = 0;
+
 #ifndef CONFIG_A2DP_SINK_NAME
 #define CONFIG_A2DP_SINK_NAME "btspeaker" // fix some compile errors when BT is not chosen
 #endif
@@ -52,19 +96,24 @@ int64_t connecting_timeout = 0;
 #ifndef CONFIG_A2DP_CONTROL_DELAY_MS
 #define CONFIG_A2DP_CONTROL_DELAY_MS 1000
 #endif
+
+static void bt_app_av_state_connecting(uint16_t event, void *param);
+
 #define A2DP_TIMER_INIT connecting_timeout = esp_timer_get_time() +(CONFIG_A2DP_CONNECT_TIMEOUT_MS * 1000)
 #define IS_A2DP_TIMER_OVER esp_timer_get_time() >= connecting_timeout
 
 #define FRAME_TO_BYTES(f) f*BYTES_PER_FRAME
 #define BYTES_TO_FRAME(b) b/BYTES_PER_FRAME
-#define FRAMES_TO_MS(f) 1000*f/output.current_sample_rate
-#define BYTES_TO_MS(b) FRAMES_TO_MS(BYTES_TO_FRAME(b))
 
-//#define SET_MIN_MAX(val,var) var=val; if(var<min_##var) min_##var=var; if(var>max_##var) max_##var=var
-//#define RESET_MIN_MAX(var,mv) min_##var=mv##_MAX; max_##var=mv##_MIN
-//#define DECLARE_MIN_MAX(var,t,mv) static t min_##var = mv##_MAX, max_##var = mv##_MIN; t var=0
-#define DECLARE_ALL_MIN_MAX DECLARE_MIN_MAX(req, long,LONG); DECLARE_MIN_MAX(rec, long,LONG); DECLARE_MIN_MAX(bt, long,LONG);DECLARE_MIN_MAX(lock_bt_time, long,LONG);DECLARE_MIN_MAX(under, long,LONG);DECLARE_MIN_MAX(o, long,LONG);
-#define RESET_ALL_MIN_MAX RESET_MIN_MAX(req,LONG); RESET_MIN_MAX(rec,LONG); RESET_MIN_MAX(bt,LONG);RESET_MIN_MAX(lock_bt_time,LONG);RESET_MIN_MAX(under,LONG);RESET_MIN_MAX(o,LONG);
+
+#define RESET_ALL_MIN_MAX RESET_MIN_MAX(req); RESET_MIN_MAX(rec); RESET_MIN_MAX(bt);RESET_MIN_MAX_DURATION(lock_bt_time);RESET_MIN_MAX(under); RESET_MIN_MAX_DURATION(lock_out_time)
+
+DECLARE_MIN_MAX(req);
+DECLARE_MIN_MAX(rec);
+DECLARE_MIN_MAX(bt);
+DECLARE_MIN_MAX_DURATION(lock_bt_time);
+DECLARE_MIN_MAX(under);
+DECLARE_MIN_MAX_DURATION(lock_out_time);
 
 static void filter_inquiry_scan_result(esp_bt_gap_cb_param_t *param);
 
@@ -186,7 +235,6 @@ static esp_bd_addr_t s_peer_bda = {0};
 static uint8_t s_peer_bdname[ESP_BT_GAP_MAX_BDNAME_LEN + 1];
 static int s_a2d_state = APP_AV_STATE_IDLE;
 static int s_media_state = APP_AV_MEDIA_STATE_IDLE;
-static int s_intv_cnt = 0;
 static uint32_t s_pkt_cnt = 0;
 
 static TimerHandle_t s_tmr;
@@ -198,6 +246,7 @@ void hal_bluetooth_init(log_level level)
 	 * Bluetooth audio source init Start
 	 */
 	loglevel = level;
+	bt_set_log_level(level);
 	//running_test = false;
 	ESP_ERROR_CHECK(esp_bt_controller_mem_release(ESP_BT_MODE_BLE));
 
@@ -244,27 +293,23 @@ void hal_bluetooth_init(log_level level)
 	esp_bt_gap_set_pin(pin_type, 0, pin_code);
 
 }
-DECLARE_ALL_MIN_MAX ;
-
 static int32_t bt_app_a2d_data_cb(uint8_t *data, int32_t len)
 {
-	static int count = 0;
-	unsigned avail_data=0,wanted_len=0;
+#ifdef USE_BT_RING_BUFFER
+	int32_t avail_data=0,wanted_len=0, start_timer=0;
 
 	if (len < 0 || data == NULL ) {
         return 0;
     }
 
 
-	//
 	// This is how the BTC layer calculates the number of bytes to
 	// for us to send. (BTC_SBC_DEC_PCM_DATA_LEN * sizeof(OI_INT16) - availPcmBytes
-
 	wanted_len=len;
-
-	SET_MIN_MAX(len/BYTES_PER_FRAME,req);
+	TIME_MEASUREMENT_START(start_timer);
+	SET_MIN_MAX(len,req);
 	LOCK_BT;
-	SET_MIN_MAX(_buf_used(btbuf)/BYTES_PER_FRAME,bt);
+	SET_MIN_MAX_SIZED(_buf_used(btbuf),bt,btbuf->size);
 	do {
 
 		avail_data=min(_buf_cont_read(btbuf),wanted_len);
@@ -275,54 +320,57 @@ static int32_t bt_app_a2d_data_cb(uint8_t *data, int32_t len)
 			data+=avail_data;
 		}
 		else {
-	//		SET_MIN_MAX(wanted_len, under);
-			//LOG_WARN("BT Buffering underrun! %7d bytes Requested, %7d bytes missing.", len,wanted_len);
-//			LOG_INFO( "count:%d, current sample rate: %d",count,output.current_sample_rate);
-//			LOG_INFO( "              ----------+----------+-----------+  +----------+----------+----------------+");
-//					LOG_INFO( "                    max |      min |    current|  |      max |      min |        current |");
-//					LOG_INFO( "                   (ms) |     (ms) |       (ms)|  |  (bytes) |  (bytes) |        (bytes) |");
-//					LOG_INFO( "              ----------+----------+-----------+  +----------+----------+----------------+");
-//					LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req));
-//					LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec));
-//					LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("available",bt));
-//					LOG_INFO("              ----------+----------+-----------+  +----------+----------+----------------+");
-		//			LOG_INFO("");
-		//			LOG_INFO("              max (us)  | min (us) |current(us)|  ");
-		//			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;
+			assert(wanted_len>0);
+			assert(avail_data==0);
+			SET_MIN_MAX(wanted_len, under);
 		}
 	} while (wanted_len > 0 && avail_data != 0);
+
 	UNLOCK_BT;
-	SET_MIN_MAX((len-wanted_len)/BYTES_PER_FRAME, rec);
-	SET_MIN_MAX(wanted_len/BYTES_PER_FRAME, under);
-	SET_MIN_MAX(_buf_used(outputbuf)/BYTES_PER_FRAME,o);
+	SET_MIN_MAX(TIME_MEASUREMENT_GET(start_timer),lock_bt_time);
+	SET_MIN_MAX((len-wanted_len), rec);
+	TIME_MEASUREMENT_START(start_timer);
+	output_bt_check_buffer();
+	SET_MIN_MAX(TIME_MEASUREMENT_GET(start_timer),lock_out_time);
+	return len-wanted_len;
+
+#else
+	int32_t avail_data=0,wanted_len=0, start_timer=0;
+
+	if (len < 0 || data == NULL ) {
+		return 0;
+	}
+	btout=data;
+
+	// This is how the BTC layer calculates the number of bytes to
+	// for us to send. (BTC_SBC_DEC_PCM_DATA_LEN * sizeof(OI_INT16) - availPcmBytes
+	wanted_len=len;
+	SET_MIN_MAX(len,req);
+	TIME_MEASUREMENT_START(start_timer);
 	LOCK;
-	   	output.device_frames = 0;
-	   	output.updated = gettime_ms();
-	   	output.frames_played_dmp = output.frames_played;
+	SET_MIN_MAX_SIZED(_buf_used(outputbuf),bt,outputbuf->size);
+	do {
+
+		avail_data = _output_frames( wanted_len/BYTES_PER_FRAME )*BYTES_PER_FRAME; // Keep the transfer buffer full
+		wanted_len-=avail_data;
+	} while (wanted_len > 0 && avail_data != 0);
+	if(wanted_len>0)
+	{
+		SET_MIN_MAX(wanted_len, under);
+	}
+	output.device_frames = 0; // todo: check if this is the right way do to this.
+	output.updated = gettime_ms();
+	output.frames_played_dmp = output.frames_played;
 	UNLOCK;
-	//count++;
-//	TIMED_SECTION_START(5000);
-//		//LOG_INFO( "count:%d, current sample rate: %d, bytes per frame: %d",count,output.current_sample_rate);
-//		LOG_INFO( "              ----------+----------+-----------+  +----------+----------+----------------+");
-//		LOG_INFO( "                    max |      min |    current|  |      max |      min |        current |");
-//		LOG_INFO( "                   (ms) |     (ms) |       (ms)|  |  (bytes) |  (bytes) |        (bytes) |");
-//		LOG_INFO( "              ----------+----------+-----------+  +----------+----------+----------------+");
-//		LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("output",o));
-//		LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("available",bt));
-//		LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req));
-//		LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec));
-//		LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("underrun",under));
-//		LOG_INFO("              ----------+----------+-----------+  +----------+----------+----------------+");
-//		RESET_ALL_MIN_MAX;
-//	TIMED_SECTION_END;
+	SET_MIN_MAX(TIME_MEASUREMENT_GET(start_timer),lock_out_time);
+	SET_MIN_MAX((len-wanted_len), rec);
+	TIME_MEASUREMENT_START(start_timer);
+	output_bt_check_buffer();
+
 	return len-wanted_len;
-}
 
+#endif
+}
 static void bt_app_a2d_cb(esp_a2d_cb_event_t event, esp_a2d_cb_param_t *param)
 {
     bt_app_work_dispatch(bt_app_av_sm_hdlr, event, param, sizeof(esp_a2d_cb_param_t), NULL);
@@ -423,10 +471,10 @@ static void bt_app_av_sm_hdlr(uint16_t event, void *param)
     //LOG_DEBUG("%s state %s, evt 0x%x, output state: %d", __func__, APP_AV_STATE_DESC[s_a2d_state], event, output.state);
     switch (s_a2d_state) {
     case APP_AV_STATE_DISCOVERING:
-    	LOG_SDEBUG("state %s, evt 0x%x, output state: %d", APP_AV_STATE_DESC[s_a2d_state], event, output.state);
+    	LOG_SDEBUG("state %s, evt 0x%x, output state: %s", APP_AV_STATE_DESC[s_a2d_state], event, get_output_state_desc(output.state));
     	break;
     case APP_AV_STATE_DISCOVERED:
-    	LOG_SDEBUG("state %s, evt 0x%x, output state: %d", APP_AV_STATE_DESC[s_a2d_state], event, output.state);
+    	LOG_SDEBUG("state %s, evt 0x%x, output state: %s", APP_AV_STATE_DESC[s_a2d_state], event, get_output_state_desc(output.state));
         break;
     case APP_AV_STATE_UNCONNECTED:
         bt_app_av_state_unconnected(event, param);
@@ -633,16 +681,22 @@ static void bt_app_av_media_proc(uint16_t event, void *param)
     esp_a2d_cb_param_t *a2d = NULL;
     LOCK;
     output_state out_state=output.state;
+    unsigned start_frames = output.start_frames;
     UNLOCK;
-	unsigned bt_buffer_used=_buf_used(btbuf);
+#ifdef USE_BT_RING_BUFFER
+    LOCK_BT;
+    unsigned bt_buffer_used=_buf_used(btbuf);
+    UNLOCK_BT;
+#endif
     switch (s_media_state) {
     case APP_AV_MEDIA_STATE_IDLE: {
     	if (event == BT_APP_HEART_BEAT_EVT) {
-            if(out_state > OUTPUT_STOPPED)
+            if(out_state > OUTPUT_OFF)
             {
-            	LOG_INFO("buffering output, a2dp media ready and connected. Starting checking if ready...");
+            	LOG_INFO("Output state is %s, a2dp media ready and connected. Checking if A2DP is ready.", get_output_state_desc(out_state));
             	esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_CHECK_SRC_RDY);
             }
+
         } else if (event == ESP_A2D_MEDIA_CTRL_ACK_EVT) {
         	a2d = (esp_a2d_cb_param_t *)(param);
 			if (a2d->media_ctrl_stat.cmd == ESP_A2D_MEDIA_CTRL_CHECK_SRC_RDY &&
@@ -656,21 +710,39 @@ static void bt_app_av_media_proc(uint16_t event, void *param)
     }
     case APP_AV_MEDIA_STATE_BUFFERING: {
       	if (event == BT_APP_HEART_BEAT_EVT) {
-             if(out_state > OUTPUT_BUFFER ){
-            	 // Buffer is ready, local buffer has some data, start playback!
-
-            	 // ensure that we can get a lock on the buffer.
-            	 // when we release start, the data call back
-            	 // will be begging for data
-				LOG_INFO("Buffering complete, a2dp media ready and connected. Starting playback! ");
-				s_media_state = APP_AV_MEDIA_STATE_STARTING;
-				esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_START);
-				LOG_INFO("Signaling of ESP_A2D_MEDIA_CTRL_START complete. ");
-             }
-             else{
-            	 LOG_INFO("Buffering... BT Buffer: %d bytes ",bt_buffer_used);
-             }
+      		switch (out_state) {
+				case OUTPUT_RUNNING :
+				case OUTPUT_PAUSE_FRAMES :
+				case OUTPUT_SKIP_FRAMES:
+				case OUTPUT_START_AT:
+#ifndef USE_BT_RING_BUFFER
+				case OUTPUT_BUFFER:
+#endif
+	            	 // Buffer is ready, local buffer has some data, start playback!
+					LOG_INFO("Buffering complete, out state is %s, a2dp media ready and connected. Starting playback! ", get_output_state_desc(out_state));
+					s_media_state = APP_AV_MEDIA_STATE_STARTING;
+					esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_START);
+#ifdef USE_BT_RING_BUFFER
+					break;
+
+					case OUTPUT_BUFFER:
 
+					LOG_DEBUG("Buffering... BT Buffer: %d bytes. Start threshold: %u,  ",bt_buffer_used, start_frames*BYTES_PER_FRAME);
+#endif
+					break;
+				case OUTPUT_STOPPED:
+				case OUTPUT_OFF:
+					LOG_DEBUG("Output state is %s. Changing app status to ",get_output_state_desc(out_state));
+	                s_media_state = APP_AV_MEDIA_STATE_STOPPING;
+	                esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_STOP);
+#ifdef USE_BT_RING_BUFFER
+	                output_bt_check_buffer();
+#endif
+	                break;
+				default:
+					LOG_ERROR("Unknown output status while waiting for buffering to complete %d",out_state);
+					break;
+			}
           }
       	else{
       		LOG_WARN("Received unknown event while in state APP_AV_MEDIA_STATE_BUFFERING");
@@ -686,7 +758,6 @@ static void bt_app_av_media_proc(uint16_t event, void *param)
             if (a2d->media_ctrl_stat.cmd == ESP_A2D_MEDIA_CTRL_START &&
                     a2d->media_ctrl_stat.status == ESP_A2D_MEDIA_CTRL_ACK_SUCCESS) {
                 LOG_INFO("a2dp media started successfully.");
-                s_intv_cnt = 0;
                 s_media_state = APP_AV_MEDIA_STATE_STARTED;
             } else {
                 // not started succesfully, transfer to idle state
@@ -702,25 +773,32 @@ static void bt_app_av_media_proc(uint16_t event, void *param)
                 LOG_INFO("Output state is stopped. Stopping a2dp media ...");
                 s_media_state = APP_AV_MEDIA_STATE_STOPPING;
                 esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_STOP);
-                s_intv_cnt = 0;
+#ifdef USE_BT_RING_BUFFER
+				output_bt_check_buffer();
+#endif
             }
         	else
         	{
         		static time_t lastTime=0;
         		if (lastTime <= gettime_ms() )
 				{
-					lastTime = gettime_ms() + 5000;
-					//LOG_INFO( "count:%d, current sample rate: %d, bytes per frame: %d",count,output.current_sample_rate);
-					LOG_INFO( "              **********+**********+***********+***********+  +**********+**********+****************+****************+****************+");
-					LOG_INFO( "                    max |      min |       avg |    current|  |      max |      min |        average |          count |        current |");
-					LOG_INFO( "                   (ms) |     (ms) |       (ms)|      (ms) |  |  (bytes) |  (bytes) |        (bytes) |                |        (bytes) |");
-					LOG_INFO( "              **********+**********+***********+***********+  +**********+**********+****************+****************+****************+");
-					LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("output",o));
-					LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("available",bt));
-					LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req));
-					LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec));
-					LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("underrun",under));
-					LOG_INFO("              **********+**********+***********+***********+  +**********+**********+****************+****************+****************+");
+					lastTime = gettime_ms() + 15000;
+					LOG_DEBUG( "              +==========+==========+================+=====+================+");
+					LOG_DEBUG( "              |      max |      min |        average | avg |          count |");
+					LOG_DEBUG( "              |  (bytes) |  (bytes) |        (bytes) | pct |                |");
+					LOG_DEBUG( "              +==========+==========+================+=====+================+");
+					LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("available",bt));
+					LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req));
+					LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec));
+					LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("underrun",under));
+					LOG_DEBUG( "              +==========+==========+================+=====+================+");
+					LOG_DEBUG("\n");
+					LOG_DEBUG("              ==========+==========+===========+===========+  ");
+					LOG_DEBUG("              max (us)  | min (us) |   avg(us) |  count    |  ");
+					LOG_DEBUG("              ==========+==========+===========+===========+  ");
+					LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("BT Buf Lock",lock_bt_time));
+					LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Out Buf Lock",lock_out_time));
+					LOG_DEBUG("              ==========+==========+===========+===========+");
 					RESET_ALL_MIN_MAX;
 				}
 
@@ -771,9 +849,18 @@ static void bt_app_av_state_unconnected(uint16_t event, void *param)
 	switch (event) {
     case ESP_A2D_CONNECTION_STATE_EVT:
     	LOG_DEBUG_EVENT(ESP_A2D_CONNECTION_STATE_EVT);
+    	// this could happen if connection was established
+    	// right after we timed out. Pass the call down to the connecting
+    	// handler.
+    	esp_a2d_cb_param_t *a2d = (esp_a2d_cb_param_t *)(param);
+    	if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED){
+    		bt_app_av_state_connecting(event, param);
+    	}
+
     	break;
     case ESP_A2D_AUDIO_STATE_EVT:
     	LOG_DEBUG_EVENT(ESP_A2D_AUDIO_STATE_EVT);
+
     	break;
     case ESP_A2D_AUDIO_CFG_EVT:
     	LOG_DEBUG_EVENT(ESP_A2D_AUDIO_CFG_EVT);
@@ -794,16 +881,17 @@ static void bt_app_av_state_unconnected(uint16_t event, void *param)
 		case ESP_BLUEDROID_STATUS_ENABLED:
 			LOG_SDEBUG("BlueDroid Status is ESP_BLUEDROID_STATUS_ENABLED.");
 			break;
-			default:
-				break;
+		default:
+			break;
 		}
 //        if(out_state > OUTPUT_STOPPED){
         	// only attempt a connect when playback isn't stopped
-			if(esp_a2d_source_connect(s_peer_bda)!=ESP_ERR_INVALID_STATE) {
+			if(esp_a2d_source_connect(s_peer_bda)==ESP_OK) {
 				s_a2d_state = APP_AV_STATE_CONNECTING;
-				//esp_bt_gap_set_scan_mode(ESP_BT_CONNECTABLE, ESP_BT_GENERAL_DISCOVERABLE);
-				//LOG_INFO("squeezelite playback resumed. connecting to A2DP peer: %s", s_peer_bdname);
-				LOG_INFO("connecting to A2DP peer: %s", s_peer_bdname);
+				for(uint8_t l=0;art_a2dp_connecting[l][0]!='\0';l++){
+					LOG_INFO_NO_LF("%s",art_a2dp_connecting[l]);
+				}
+				LOG_INFO("********** A2DP CONNECTING TO %s", s_peer_bdname);
 				A2DP_TIMER_INIT;
 			}
 			else {
@@ -830,8 +918,12 @@ static void bt_app_av_state_connecting(uint16_t event, void *param)
         if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED) {
             s_a2d_state =  APP_AV_STATE_CONNECTED;
             s_media_state = APP_AV_MEDIA_STATE_IDLE;
-            LOG_INFO("a2dp connected! Setting BT mode to non_connectable and non_discoverable. ");
+			for(uint8_t l=0;art_a2dp_connected[l][0]!='\0';l++){
+				LOG_INFO_NO_LF("%s",art_a2dp_connected[l]);
+			}
+			LOG_DEBUG("Setting scan mode to ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE");
             esp_bt_gap_set_scan_mode(ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE);
+            LOG_DEBUG("Done setting scan mode. App state is now CONNECTED and media state IDLE.");
         } else if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_DISCONNECTED) {
             s_a2d_state =  APP_AV_STATE_UNCONNECTED;
         }
@@ -888,7 +980,7 @@ static void bt_app_av_state_connected(uint16_t event, void *param)
     	LOG_DEBUG_EVENT(ESP_A2D_AUDIO_CFG_EVT);
         break;
     case ESP_A2D_MEDIA_CTRL_ACK_EVT:{
-        	LOG_DEBUG_EVENT(ESP_A2D_MEDIA_CTRL_ACK_EVT);
+        	LOG_SDEBUG_EVENT(ESP_A2D_MEDIA_CTRL_ACK_EVT);
             bt_app_av_media_proc(event, param);
             break;
         }

main/esp_app_main.c

@@ -30,6 +30,47 @@
 #include "nvs_flash.h"
 #include "sys/socket.h"
 #include "string.h"
+thread_cond_type wifi_connect_suspend_cond;
+mutex_type wifi_connect_suspend_mutex;
+char * art_wifi[]={
+		"\n",
+		"o          `O ooOoOOo OOooOoO ooOoOOo\n",
+		"O           o    O    o          O   \n",
+		"o           O    o    O          o   \n",
+		"O           O    O    oOooO      O   \n",
+		"o     o     o    o    O          o   \n",
+		"O     O     O    O    o          O   \n",
+		"`o   O o   O'    O    o          O   \n",
+		" `OoO' `OoO'  ooOOoOo O'      ooOOoOo\n",
+		"\n",
+		""
+};
+char * art_wifi_connecting[]={
+		" .oOOOo.",
+		".O     o                                        o               \n",
+		"o                                           O                   \n",
+		"o                                          oOo                  \n",
+		"o         .oOo. 'OoOo. 'OoOo. .oOo. .oOo    o   O  'OoOo. .oOoO \n",
+		"O         O   o  o   O  o   O OooO' O       O   o   o   O o   O \n",
+		"`o     .o o   O  O   o  O   o O     o       o   O   O   o O   o \n",
+		" `OoooO'  `OoO'  o   O  o   O `OoO' `OoO'   `oO o'  o   O `OoOo \n",
+		"                                                              O \n",
+		"                                                           OoO' \n",
+		"\n",
+		""
+};
+char * art_wifi_connected[]={
+		" .oOOOo.                                                   o       oO\n",
+		".O     o                                                  O        OO\n",
+		"o                                           O             o        oO\n",
+		"o                                          oOo            o        Oo\n",
+		"o         .oOo. 'OoOo. 'OoOo. .oOo. .oOo    o   .oOo. .oOoO        oO\n",
+		"O         O   o  o   O  o   O OooO' O       O   OooO' o   O          \n",
+		"`o     .o o   O  O   o  O   o O     o       o   O     O   o        Oo\n",
+		" `OoooO'  `OoO'  o   O  o   O `OoO' `OoO'   `oO `OoO' `OoO'o       oO\n",
+		"\n",
+		""
+};
 
 /*Set the SSID and Password via "make menuconfig"*/
 #define DEFAULT_SSID CONFIG_WIFI_SSID
@@ -80,7 +121,13 @@ static void event_handler(void* arg, esp_event_base_t event_base,
         esp_wifi_connect();
     } else if (event_base == IP_EVENT && event_id == IP_EVENT_STA_GOT_IP) {
         ip_event_got_ip_t* event = (ip_event_got_ip_t*) event_data;
-        ESP_LOGI(TAG, "got ip: %s", ip4addr_ntoa(&event->ip_info.ip));
+        ESP_LOGI(TAG, "got ip: %s.", ip4addr_ntoa(&event->ip_info.ip));
+        logprint("Signaling wifi connected. Locking.\n");
+    	mutex_lock(wifi_connect_suspend_mutex);
+    	logprint("Signaling wifi connected. Broadcasting.\n");
+		mutex_broadcast_cond(wifi_connect_suspend_cond);
+    	logprint("Signaling wifi connected. Unlocking.\n");
+		mutex_unlock(wifi_connect_suspend_mutex);
     }
 }
 
@@ -88,6 +135,12 @@ static void event_handler(void* arg, esp_event_base_t event_base,
 /* Initialize Wi-Fi as sta and set scan method */
 static void wifi_scan(void)
 {
+	for(uint8_t l=0;art_wifi[l][0]!='\0';l++){
+		logprint("%s",art_wifi[l]);
+	}
+	for(uint8_t l=0;art_wifi_connecting[l][0]!='\0';l++){
+		logprint("%s",art_wifi_connecting[l]);
+		}
     tcpip_adapter_init();
     ESP_ERROR_CHECK(esp_event_loop_create_default());
 
@@ -143,18 +196,13 @@ void app_main()
 
 	};
 
+
 	// can't do strtok on FLASH strings
 	argv = malloc(sizeof(_argv));
 	for (i = 0; i < sizeof(_argv)/sizeof(char*); i++) {
 		argv[i] = strdup(_argv[i]);
 	}
 
-	logprint("%s %s:%d Calling main with parameters: " , logtime(), __FUNCTION__, __LINE__);
-
-	for (i = 0; i < sizeof(_argv)/sizeof(char*); i++) {
-		logprint("%s " , _argv[i]);
-	}
-	logprint("\n");
 
     // Initialize NVS
     esp_err_t ret = nvs_flash_init();
@@ -163,8 +211,30 @@ void app_main()
         ret = nvs_flash_init();
     }
     ESP_ERROR_CHECK( ret );
-	
+
+	mutex_create_p(wifi_connect_suspend_mutex);
+	mutex_cond_init(wifi_connect_suspend_cond);
+
+	logprint("Starting WiFi.\n");
 	wifi_scan();
-	
+	logprint("Waiting for WiFi to connect. Locking Mutex.\n");
+	mutex_lock(wifi_connect_suspend_mutex);
+	logprint("Waiting for WiFi to connect. cond_wait.\n");
+	pthread_cond_wait(&wifi_connect_suspend_cond,&wifi_connect_suspend_mutex);
+	logprint("Waiting for WiFi to connect. Unlocking Mutex.\n");
+	mutex_unlock(wifi_connect_suspend_mutex);
+	for(uint8_t l=0;art_wifi[l][0]!='\0';l++){
+		logprint("%s",art_wifi[l]);
+	}
+	for(uint8_t l=0;art_wifi_connected[l][0]!='\0';l++){
+		logprint("%s",art_wifi_connected[l]);
+		}
+	logprint("%s %s:%d Calling main with parameters: " , logtime(), __FUNCTION__, __LINE__);
+
+	for (i = 0; i < sizeof(_argv)/sizeof(char*); i++) {
+		logprint("%s " , _argv[i]);
+	}
+	logprint("\n");
+
 	main(sizeof(_argv)/sizeof(char*), argv);
 }

main/output_bt.c

@@ -8,50 +8,57 @@ static bool running = true;
 extern struct outputstate output;
 extern struct buffer *outputbuf;
 extern struct buffer *streambuf;
-size_t bt_buffer_size=0;
-
-static struct buffer bt_buf_structure;
-struct buffer *btbuf=&bt_buf_structure;
 
 
 #define LOCK   mutex_lock(outputbuf->mutex)
 #define UNLOCK mutex_unlock(outputbuf->mutex)
+
+#ifdef USE_BT_RING_BUFFER
+size_t bt_buffer_size=0;
+uint8_t bt_buf_used_threshold = 25;
+uint16_t output_bt_thread_heartbeat_ms=1000;
+thread_type thread_bt;
 #define LOCK_BT   mutex_lock(btbuf->mutex)
 #define UNLOCK_BT mutex_unlock(btbuf->mutex)
+thread_cond_type output_bt_suspend_cond;
+mutex_type output_bt_suspend_mutex;
+static struct buffer bt_buf_structure;
+struct buffer *btbuf=&bt_buf_structure;
+static void *output_thread_bt();
+extern void wait_for_frames(size_t frames, uint8_t pct);
+#else
+uint8_t * btout;
+#endif
 
 #define FRAME_BLOCK MAX_SILENCE_FRAMES
-#define BUFFERING_FRAME_BLOCK FRAME_BLOCK*2
-
 extern u8_t *silencebuf;
 
 void hal_bluetooth_init(log_level);
-static void *output_thread_bt();
+
 static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t gainR,
 								s32_t cross_gain_in, s32_t cross_gain_out, ISAMPLE_T **cross_ptr);
-extern void wait_for_frames(size_t frames, uint8_t pct);
-
 #define DECLARE_ALL_MIN_MAX \
-	DECLARE_MIN_MAX(req, long,LONG); \
-	DECLARE_MIN_MAX(rec, long,LONG); \
-	DECLARE_MIN_MAX(o, long,LONG); \
-	DECLARE_MIN_MAX(s, long,LONG); \
-	DECLARE_MIN_MAX(d, long,LONG); \
-	DECLARE_MIN_MAX(locbtbuff, long,LONG); \
-	DECLARE_MIN_MAX(mutex1, long,LONG); \
-	DECLARE_MIN_MAX(mutex2, long,LONG); \
-	DECLARE_MIN_MAX(total, long,LONG); \
-DECLARE_MIN_MAX(buffering, long,LONG);
+	DECLARE_MIN_MAX(req);\
+	DECLARE_MIN_MAX(rec);\
+	DECLARE_MIN_MAX(o);\
+	DECLARE_MIN_MAX(s);\
+	DECLARE_MIN_MAX(locbtbuff);\
+	DECLARE_MIN_MAX(under);\
+	DECLARE_MIN_MAX_DURATION(mutex1);\
+	DECLARE_MIN_MAX_DURATION(mutex2);\
+	DECLARE_MIN_MAX_DURATION(buffering);\
+	DECLARE_MIN_MAX_DURATION(sleep_time);
 #define RESET_ALL_MIN_MAX \
-	RESET_MIN_MAX(d,LONG); \
-	RESET_MIN_MAX(o,LONG); \
-	RESET_MIN_MAX(s,LONG); \
-	RESET_MIN_MAX(locbtbuff, LONG); \
-	RESET_MIN_MAX(req,LONG);  \
-	RESET_MIN_MAX(rec,LONG);  \
-	RESET_MIN_MAX(mutex1,LONG);  \
-	RESET_MIN_MAX(mutex2,LONG);  \
-	RESET_MIN_MAX(total,LONG);  \
-	RESET_MIN_MAX(buffering,LONG);
+	RESET_MIN_MAX(o); \
+	RESET_MIN_MAX(s); \
+	RESET_MIN_MAX(locbtbuff); \
+	RESET_MIN_MAX(req);  \
+	RESET_MIN_MAX(rec);  \
+	RESET_MIN_MAX(under);  \
+	RESET_MIN_MAX_DURATION(mutex1);  \
+	RESET_MIN_MAX_DURATION(mutex2);  \
+	RESET_MIN_MAX_DURATION(sleep_time);  \
+	RESET_MIN_MAX_DURATION(buffering);
 
 
 #if CONFIG_BTAUDIO
@@ -64,7 +71,58 @@ void set_volume_bt(unsigned left, unsigned right) {
 }
 #endif
 
-static thread_type thread_bt;
+
+
+void output_bt_check_buffer()
+{
+#ifdef USE_BT_RING_BUFFER
+	LOCK_BT;
+	uint8_t tot_buf_used_pct=100*_buf_used(btbuf)/btbuf->size;
+	UNLOCK_BT;
+	if(tot_buf_used_pct<bt_buf_used_threshold)
+	{
+		// tell the thread to resume
+		LOG_SDEBUG("Below threshold. Locking suspend mutex.");
+		mutex_lock(output_bt_suspend_mutex);
+		LOG_SDEBUG("Broadcasting suspend condition.");
+		mutex_broadcast_cond(output_bt_suspend_cond);
+		LOG_SDEBUG("Unlocking suspend mutex.");
+		mutex_unlock(output_bt_suspend_mutex);
+	}
+#endif
+}
+void output_bt_suspend()
+{
+#ifdef USE_BT_RING_BUFFER
+	struct timespec   ts;
+	struct timeval    tp;
+	int               rc;
+
+
+	// if suspended, suspend until resumed
+	LOG_SDEBUG("Locking suspend mutex.");
+	mutex_lock(output_bt_suspend_mutex);
+	LOG_SDEBUG("Waiting on condition to be signaled.");
+
+	// suspend for up to a predetermined wait time.
+	// this will allow flushing the BT buffer when the
+	// playback stops.
+	gettimeofday(&tp, NULL);
+	/* Convert from timeval to timespec */
+	ts.tv_sec  = tp.tv_sec;
+	ts.tv_nsec = tp.tv_usec * 1000;
+	ts.tv_nsec +=  output_bt_thread_heartbeat_ms*1000000; // micro seconds to nanosecs
+
+	rc = pthread_cond_timedwait(&output_bt_suspend_cond,&output_bt_suspend_mutex,&ts);
+	if(rc==ETIMEDOUT)
+	{
+		LOG_SDEBUG("Wait timed out. Resuming output.");
+	}
+    LOG_SDEBUG("Unlocking suspend mutex.");
+    mutex_unlock(output_bt_suspend_mutex);
+#endif
+}
+
 void output_init_bt(log_level level, char *device, unsigned output_buf_size, char *params, unsigned rates[], unsigned rate_delay, unsigned idle) {
 	loglevel = level;
 
@@ -72,10 +130,6 @@ void output_init_bt(log_level level, char *device, unsigned output_buf_size, cha
 
 	memset(&output, 0, sizeof(output));
 
-	output.start_frames = FRAME_BLOCK; //CONFIG_ //FRAME_BLOCK * 2;
-	output.write_cb = &_write_frames;
-	output.rate_delay = rate_delay;
-
 	// ensure output rate is specified to avoid test open
 	if (!rates[0]) {
 		rates[0] = 44100;
@@ -86,15 +140,16 @@ void output_init_bt(log_level level, char *device, unsigned output_buf_size, cha
  */
 	device = CONFIG_OUTPUT_NAME;
 	output_init_common(level, device, output_buf_size, rates, idle);
-
-	bt_buffer_size = 3*FRAME_BLOCK*get_bytes_per_frame(output.format);
+#ifdef USE_BT_RING_BUFFER
 	LOG_DEBUG("Allocating local BT transfer buffer of %u bytes.",bt_buffer_size);
 	buf_init(btbuf, bt_buffer_size );
 	if (!btbuf->buf) {
 		LOG_ERROR("unable to malloc BT buffer");
 		exit(0);
 	}
-
+	mutex_create_p(output_bt_suspend_mutex);
+	mutex_cond_init(output_bt_suspend_cond);
+	PTHREAD_SET_NAME("output_bt");
 
 #if LINUX || OSX || FREEBSD || POSIX
 	pthread_attr_t attr;
@@ -102,11 +157,18 @@ void output_init_bt(log_level level, char *device, unsigned output_buf_size, cha
 #ifdef PTHREAD_STACK_MIN
 	pthread_attr_setstacksize(&attr, PTHREAD_STACK_MIN + OUTPUT_THREAD_STACK_SIZE);
 #endif
+
 	pthread_create(&thread_bt, &attr, output_thread_bt, NULL);
-	pthread_attr_destroy(&attr);
 #endif
+	pthread_attr_destroy(&attr);
+
 #if WIN
 	thread = CreateThread(NULL, OUTPUT_THREAD_STACK_SIZE, (LPTHREAD_START_ROUTINE)&output_thread_bt, NULL, 0, NULL);
+#endif
+#else
+	output.start_frames =  FRAME_BLOCK;
+	output.write_cb = &_write_frames;
+	output.rate_delay = rate_delay;
 #endif
 	LOG_INFO("Init completed.");
 
@@ -115,111 +177,135 @@ void output_init_bt(log_level level, char *device, unsigned output_buf_size, cha
 /****************************************************************************************
  * Main output thread
  */
+#ifdef USE_BT_RING_BUFFER
 static void *output_thread_bt() {
-	frames_t frames=0;
-	frames_t available_frames_space=0;
-	uint32_t timer_start=0, mutex_start=0, total_start=0;
-	static int count = 0;
 
+	frames_t frames=0;
+	frames_t requested_frames=0;
+	uint32_t timer_start=0, mutex_start=0;
+	unsigned btbuf_used=0;
+	output_state state;
 	DECLARE_ALL_MIN_MAX;
-
 	while (running) {
 		frames=0;
-		available_frames_space=0;
-
+		requested_frames=0;
 		TIME_MEASUREMENT_START(timer_start);
-		TIME_MEASUREMENT_START(total_start);
+
+		// Get output state
 		TIME_MEASUREMENT_START(mutex_start);
 		LOCK;
+		state=output.state;
 		SET_MIN_MAX(TIME_MEASUREMENT_GET(mutex_start),mutex1);
-		if (output.state == OUTPUT_OFF) {
+
+		if(state < OUTPUT_STOPPED ){
+			// Flushing the buffer will automatically
+			// lock the mutex
+			LOG_SDEBUG("Flushing BT buffer");
+			buf_flush(btbuf);
+		}
+		if (state == OUTPUT_OFF) {
 			UNLOCK;
 			LOG_SDEBUG("Output state is off.");
-			usleep(500000);
+			usleep(200000);
 			continue;
 		}
+		output.device_frames = 0; // todo: check if this is the right way do to this.
+		output.updated = gettime_ms();
+		output.frames_played_dmp = output.frames_played;
+
 		TIME_MEASUREMENT_START(mutex_start);
 		LOCK_BT;
 		SET_MIN_MAX(TIME_MEASUREMENT_GET(mutex_start),mutex2);
-		available_frames_space = min(_buf_space(btbuf), _buf_cont_write(btbuf))/BYTES_PER_FRAME;
-		SET_MIN_MAX( available_frames_space,req);
-		SET_MIN_MAX(_buf_used(outputbuf)/BYTES_PER_FRAME,o);
-		SET_MIN_MAX(_buf_used(streambuf)/BYTES_PER_FRAME,s);
-		if(available_frames_space==0)
+		btbuf_used=_buf_used(btbuf);
+		SET_MIN_MAX_SIZED(btbuf_used,locbtbuff,btbuf->size);
+
+
+		// only output more frames if we need them
+		// so we can release the mutex as quickly as possible
+		requested_frames = min(_buf_space(btbuf), _buf_cont_write(btbuf))/BYTES_PER_FRAME;
+		SET_MIN_MAX( requested_frames*BYTES_PER_FRAME,req);
+		SET_MIN_MAX_SIZED(_buf_used(outputbuf),o,outputbuf->size);
+		SET_MIN_MAX_SIZED(_buf_used(streambuf),s,streambuf->size);
+		if(requested_frames>0)
 		{
-			UNLOCK;
-			UNLOCK_BT;
-			usleep(10000);
-			continue;
+			frames = _output_frames( requested_frames ); // Keep the transfer buffer full
+			SET_MIN_MAX(frames*BYTES_PER_FRAME,rec);
+			if(requested_frames>frames){
+				SET_MIN_MAX((requested_frames-frames)*BYTES_PER_FRAME,under);
+			}
 		}
-		frames = _output_frames( available_frames_space ); // Keep the transfer buffer full
-		SET_MIN_MAX(_buf_used(btbuf),locbtbuff);
+
 		UNLOCK;
 		UNLOCK_BT;
-		//LOG_SDEBUG("Current buffer free: %10d, cont read: %10d",_buf_space(btbuf),_buf_cont_read(btbuf));
 		SET_MIN_MAX( TIME_MEASUREMENT_GET(timer_start),buffering);
-		SET_MIN_MAX( available_frames_space,req);
-		SET_MIN_MAX(frames,rec);
-//		if(frames>0 ){
-//			// let's hold processing a bit, while frames are being processed
-//			// we're waiting long enough to avoid hogging the CPU too much
-//			// while we're ramping up this transfer buffer
-//			wait_for_frames(frames,95);
-//		}
-		wait_for_frames(FRAME_BLOCK,100);
+		SET_MIN_MAX( requested_frames,req);
+
+		// When playback has started, we want to
+		// hold the BT out thread
+		// so the BT data callback isn't constantly interrupted.
+		TIME_MEASUREMENT_START(timer_start);
+		if(state>OUTPUT_BUFFER){
+			output_bt_suspend();
+		}
+		SET_MIN_MAX(TIME_MEASUREMENT_GET(timer_start),sleep_time);
 
 		/*
 		 * Statistics reporting
 		 */
-#define STATS_PERIOD_MS 10000
-		count++;
-		TIMED_SECTION_START_MS(STATS_PERIOD_MS);
-		if(count>1){
-			LOG_INFO( "count:%d, current sample rate: %d, avg cycle duration (ms): %d",count,output.current_sample_rate, STATS_PERIOD_MS/count);
-			LOG_INFO( "              ----------+----------+-----------+-----------+  +----------+----------+----------------+----------------+----------------+");
-			LOG_INFO( "                    max |      min |       avg |    current|  |      max |      min |        average |        count   |        current |");
-			LOG_INFO( "                   (ms) |     (ms) |       (ms)|      (ms) |  |  (bytes) |  (bytes) |        (bytes) |                |        (bytes) |");
-			LOG_INFO( "              ----------+----------+-----------+-----------+  +----------+----------+----------------+----------------+----------------+");
-			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,LINE_MIN_MAX("requested",req));
-			LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec));
-			LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("local bt buf",locbtbuff));
-			LOG_INFO("              ----------+----------+-----------+-----------+  +----------+----------+----------------+----------------+");
-			LOG_INFO("");
-			LOG_INFO("              ----------+----------+-----------+-----------+-----------+  ");
-			LOG_INFO("              max (us)  | min (us) |   avg(us) |  count    |current(us)|  ");
-			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("Output mux(us)",mutex1));
-			LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("BT mux(us)",mutex2));
-			LOG_INFO("              ----------+----------+-----------+-----------+-----------+");
+		static time_t lastTime=0;
+		if (lastTime <= gettime_ms() )
+		{
+#define STATS_PERIOD_MS 15000
+			lastTime = gettime_ms() + STATS_PERIOD_MS;
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT_HEAD1);
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT_HEAD2);
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT_HEAD3);
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT_HEAD4);
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT_STREAM, LINE_MIN_MAX_STREAM("stream",s));
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("output",o));
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("local bt buf",locbtbuff));
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT_FOOTER );
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req));
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec));
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("Underrun",under));
+			LOG_DEBUG(LINE_MIN_MAX_FORMAT_FOOTER );
+			LOG_DEBUG("");
+			LOG_DEBUG("              ----------+----------+-----------+-----------+  ");
+			LOG_DEBUG("              max (us)  | min (us) |   avg(us) |  count    |  ");
+			LOG_DEBUG("              ----------+----------+-----------+-----------+  ");
+			LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Buffering(us)",buffering));
+			LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Output mux(us)",mutex1));
+			LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("BT mux(us)",mutex2));
+			LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("sleep(us)",mutex2));
+			LOG_DEBUG("              ----------+----------+-----------+-----------+");
 			RESET_ALL_MIN_MAX;
-			count=0;
 		}
-		TIMED_SECTION_END;
 		/*
 		 * End Statistics reporting
 		 */
 
 
-	}
-
 
-	return 0;
+	}
+	return NULL;
 }
+#endif
 void output_close_bt(void) {
 	LOG_INFO("close output");
 	LOCK;
 	running = false;
 	UNLOCK;
-
+#ifdef USE_BT_RING_BUFFER
+	LOCK_BT;
+	buf_destroy(btbuf);
+	UNLOCK_BT;
+#endif
 	output_close_common();
 }
 
 static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t gainR,
 						 s32_t cross_gain_in, s32_t cross_gain_out, ISAMPLE_T **cross_ptr) {
-
+#ifdef USE_BT_RING_BUFFER
 	if (!silence ) {
 		DEBUG_LOG_TIMED(200,"Not silence, Writing audio out.");
 		// TODO need 16 bit fix
@@ -235,7 +321,42 @@ static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t g
 #if BYTES_PER_FRAME == 4
 
 		memcpy(btbuf->writep, outputbuf->readp, out_frames * BYTES_PER_FRAME);
+		_buf_inc_writep(btbuf,out_frames * BYTES_PER_FRAME);
+
+#else
+	{
+		frames_t count = out_frames;
+		s32_t *_iptr = (s32_t*) outputbuf->readp;
+		s16_t *_optr = (s16_t*) bt_optr;
+		while (count--) {
+			*_optr++ = *_iptr++ >> 16;
+			*_optr++ = *_iptr++ >> 16;
+		}
+	}
+#endif
+
+	} else if(output.state >OUTPUT_BUFFER){
+		// Don't fill our local buffer with silence frames.
+		u8_t *buf = silencebuf;
+		memcpy(btbuf->writep, buf, out_frames * BYTES_PER_FRAME);
+		_buf_inc_writep(btbuf,out_frames * BYTES_PER_FRAME);
+	}
+#else
+	assert(btout!=NULL);
+	if (!silence ) {
+		DEBUG_LOG_TIMED(200,"Not silence, Writing audio out.");
+		// TODO need 16 bit fix
 
+		if (output.fade == FADE_ACTIVE && output.fade_dir == FADE_CROSS && *cross_ptr) {
+			_apply_cross(outputbuf, out_frames, cross_gain_in, cross_gain_out, cross_ptr);
+		}
+
+		if (gainL != FIXED_ONE || gainR!= FIXED_ONE) {
+			_apply_gain(outputbuf, out_frames, gainL, gainR);
+		}
+
+#if BYTES_PER_FRAME == 4
+		memcpy(btout, outputbuf->readp, out_frames * BYTES_PER_FRAME);
 #else
 	{
 		frames_t count = out_frames;
@@ -249,11 +370,11 @@ static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t g
 #endif
 
 	} else {
-		DEBUG_LOG_TIMED(200,"Silence flag true. Writing silence to audio out.");
 
 		u8_t *buf = silencebuf;
-		memcpy(btbuf->writep, buf, out_frames * BYTES_PER_FRAME);
+		memcpy(btout, buf, out_frames * BYTES_PER_FRAME);
 	}
-	_buf_inc_writep(btbuf,out_frames * BYTES_PER_FRAME);
+#endif
+
 	return (int)out_frames;
 }

main/output_dac.c

@@ -6,27 +6,25 @@
 
 
 #define DECLARE_ALL_MIN_MAX \
-	DECLARE_MIN_MAX(req, long,LONG); \
-	DECLARE_MIN_MAX(rec, long,LONG); \
-	DECLARE_MIN_MAX(over, long,LONG); \
-	DECLARE_MIN_MAX(o, long,LONG); \
-	DECLARE_MIN_MAX(s, long,LONG); \
-	DECLARE_MIN_MAX(d, long,LONG); \
-	DECLARE_MIN_MAX(loci2sbuf, long,LONG); \
-	DECLARE_MIN_MAX(buffering, long,LONG);\
-	DECLARE_MIN_MAX(i2s_time, long,LONG); \
-	DECLARE_MIN_MAX(i2savailable, long,LONG);
+	DECLARE_MIN_MAX(req); \
+	DECLARE_MIN_MAX(rec); \
+	DECLARE_MIN_MAX(over); \
+	DECLARE_MIN_MAX(o); \
+	DECLARE_MIN_MAX(s); \
+	DECLARE_MIN_MAX(loci2sbuf); \
+	DECLARE_MIN_MAX(buffering); \
+	DECLARE_MIN_MAX(i2s_time); \
+	DECLARE_MIN_MAX(i2savailable);
 #define RESET_ALL_MIN_MAX \
-	RESET_MIN_MAX(d,LONG); \
-	RESET_MIN_MAX(o,LONG); \
-	RESET_MIN_MAX(s,LONG); \
-	RESET_MIN_MAX(loci2sbuf, LONG); \
-	RESET_MIN_MAX(req,LONG);  \
-	RESET_MIN_MAX(rec,LONG);  \
-	RESET_MIN_MAX(over,LONG);  \
-	RESET_MIN_MAX(over,LONG);  \
-	RESET_MIN_MAX(i2savailable,LONG);\
-	RESET_MIN_MAX(i2s_time,LONG);
+	RESET_MIN_MAX(o); \
+	RESET_MIN_MAX(s); \
+	RESET_MIN_MAX(loci2sbuf); \
+	RESET_MIN_MAX(req);  \
+	RESET_MIN_MAX(rec);  \
+	RESET_MIN_MAX(over);  \
+	RESET_MIN_MAX(over);  \
+	RESET_MIN_MAX(i2savailable);\
+	RESET_MIN_MAX(i2s_time);
 
 // Prevent compile errors if dac output is
 // included in the build and not actually activated in menuconfig
@@ -74,7 +72,7 @@ static thread_type thread;
 
 static int _dac_write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t gainR,
 								s32_t cross_gain_in, s32_t cross_gain_out, ISAMPLE_T **cross_ptr);
-static void *output_thread();
+static void *output_thread_dac();
 extern void wait_for_frames(size_t frames, uint8_t pct);
 
 /****************************************************************************************
@@ -160,8 +158,8 @@ void output_init_dac(log_level level, char *device, unsigned output_buf_size, ch
 		LOG_ERROR("unable to malloc i2s buffer");
 		exit(0);
 	}
-	LOG_SDEBUG("Current buffer free: %d",_buf_space(dacbuffer));
 
+PTHREAD_SET_NAME("output_dac");
 
 #if LINUX || OSX || FREEBSD || POSIX
 	pthread_attr_t attr;
@@ -278,7 +276,7 @@ static void *output_thread() {
 				isI2SStarted=false;
 				i2s_stop(CONFIG_I2S_NUM);
 			}
-			usleep(500000);
+			usleep(200000);
 			continue;
 		}
 		LOG_SDEBUG("Current buffer free: %10d, cont read: %10d",_buf_space(dacbuffer),_buf_cont_read(dacbuffer));
@@ -343,35 +341,7 @@ static void *output_thread() {
 		/*
 		 * Statistics reporting
 		 */
-#define STATS_PERIOD_MS 5000
-		count++;
-		TIMED_SECTION_START_MS(STATS_PERIOD_MS);
 
-		LOG_INFO( "count:%d, current sample rate: %d, bytes per frame: %d, avg cycle duration (ms): %d",count,output.current_sample_rate, out_bytes_per_frame,STATS_PERIOD_MS/count);
-		LOG_INFO( "              ----------+----------+-----------+  +----------+----------+----------------+");
-		LOG_INFO( "                    max |      min |    current|  |      max |      min |        current |");
-		LOG_INFO( "                   (ms) |     (ms) |       (ms)|  |  (bytes) |  (bytes) |        (bytes) |");
-		LOG_INFO( "              ----------+----------+-----------+  +----------+----------+----------------+");
-		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,LINE_MIN_MAX("i2swrite",i2savailable));
-		LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("local free",loci2sbuf));
-		LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req));
-		LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec));
-		LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("overflow",over));
-		LOG_INFO("              ----------+----------+-----------+  +----------+----------+----------------+");
-		LOG_INFO("");
-		LOG_INFO("              max (us)  | min (us) |current(us)|  ");
-		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;
-		count=0;
-		TIMED_SECTION_END;
-		/*
-		 * End Statistics reporting
-		 */
 		//wait_for_frames(BYTES_TO_FRAME(i2s_bytes_written));
 
 		/*
@@ -406,9 +376,7 @@ static void *output_thread() {
 		/*
 		 * End Statistics reporting
 		 */
-		wait_for_frames(BYTES_TO_FRAME(i2s_bytes_written),75);
-	}
-
+//		wait_for_frames(BYTES_TO_FRAME(i2s_bytes_written),75);
 
 	return 0;
 }

main/output_dac.c.tes

@@ -15,7 +15,6 @@ extern struct buffer *streambuf;
 #define FRAME_BLOCK MAX_SILENCE_FRAMES
 
 extern u8_t *silencebuf;
-extern u8_t *buf;
 
 #define I2S_NUM         (0)
 #define WAVE_FREQ_HZ    (100)

main/perf_trace.h

@@ -1,24 +1,48 @@
 
 #pragma once
-#define FRAMES_TO_MS(f) output.current_sample_rate>0?1000*f/output.current_sample_rate:LONG_MIN
+#define PERF_MAX LONG_MAX
+#define MIN_MAX_VAL(x) x==PERF_MAX?0:x
+#define CURR_SAMPLE_RATE output.current_sample_rate>0?output.current_sample_rate:1
+#define FRAMES_TO_MS(f) (uint32_t)f*(uint32_t)1000/(uint32_t)(CURR_SAMPLE_RATE)
 #ifdef BYTES_TO_FRAME
 #define BYTES_TO_MS(b) FRAMES_TO_MS(BYTES_TO_FRAME(b))
 #else
 #define BYTES_TO_MS(b) FRAMES_TO_MS(b/BYTES_PER_FRAME)
 #endif
-#define LINE_MIN_MAX_FORMAT          "%14s%10d|%10d|%11d|%11d|"                 "  |%10d|%10d|%16d|%16d|%16d|"
-#define LINE_MIN_MAX_DURATION_FORMAT "%14s%10d|%10d|%11d|%11d|%11d|"
-#define LINE_MIN_MAX_FORMAT_STREAM   "%14s%10s|%10s|%11s|%11s|"                 "  |%10d|%10d|%16d|%16d|%16d|"
 #define SET_MIN_MAX(val,var) var=val; if(var<min_##var) min_##var=var; if(var>max_##var) max_##var=var; count_##var++; avgtot_##var+= var
-#define RESET_MIN_MAX(var,mv) min_##var=mv##_MAX; max_##var=mv##_MIN; avgtot_##var=0;count_##var=0
-#define DECLARE_MIN_MAX(var,t,mv) static t min_##var = mv##_MAX, max_##var = mv##_MIN; uint32_t avgtot_##var = 0, count_##var=0; t var=0
-#define LINE_MIN_MAX_AVG(var) count_##var>0?avgtot_##var/count_##var:-1
-#define LINE_MIN_MAX(name,var) name,BYTES_TO_MS(max_##var), BYTES_TO_MS(min_##var),BYTES_TO_MS( var),BYTES_TO_MS( LINE_MIN_MAX_AVG(var)),max_##var,min_##var,LINE_MIN_MAX_AVG(var),count_##var,var
-#define LINE_MIN_MAX_STREAM(name,var) name,"n/a","n/a","n/a","n/a",max_##var,min_##var,LINE_MIN_MAX_AVG(var),count_##var,var
-#define LINE_MIN_MAX_DURATION(name,var) name,max_##var, min_##var, LINE_MIN_MAX_AVG(var), count_##var,var
+#define SET_MIN_MAX_SIZED(val,var,siz) var=val; if(var<min_##var) min_##var=var; if(var>max_##var) max_##var=var; count_##var++; avgtot_##var+= var;size_##var=siz
+#define RESET_MIN_MAX(var) min_##var=PERF_MAX; max_##var=0; avgtot_##var=0;count_##var=0;var=0;size_##var=0
+#define RESET_MIN_MAX_DURATION(var) min_##var=PERF_MAX; max_##var=0; avgtot_##var=0;count_##var=0;var=0
+#define DECLARE_MIN_MAX(var) static uint32_t min_##var = PERF_MAX, max_##var = 0, size_##var = 0,avgtot_##var = 0, count_##var=0; uint32_t var=0
+#define DECLARE_MIN_MAX_DURATION(var) static uint32_t min_##var = PERF_MAX, max_##var = 0, avgtot_##var = 0, count_##var=0; uint32_t var=0
+#define LINE_MIN_MAX_AVG(var) (count_##var>0?avgtot_##var/count_##var:0)
+
+#define LINE_MIN_MAX_FORMAT_HEAD1  "              +----------+----------+----------------+-----+----------------+"
+#define LINE_MIN_MAX_FORMAT_HEAD2  "              |      max |      min |        average |     |        count   |"
+#define LINE_MIN_MAX_FORMAT_HEAD3  "              |  (bytes) |  (bytes) |        (bytes) |     |                |"
+#define LINE_MIN_MAX_FORMAT_HEAD4  "              +----------+----------+----------------+-----+----------------+"
+#define LINE_MIN_MAX_FORMAT_FOOTER "              +----------+----------+----------------+-----+----------------+"
+#define LINE_MIN_MAX_FORMAT                  "%14s|%10u|%10u|%16u|%5u|%16u|"
+#define LINE_MIN_MAX(name,var) name,\
+								MIN_MAX_VAL(max_##var),\
+								MIN_MAX_VAL(min_##var),\
+								LINE_MIN_MAX_AVG(var),\
+								size_##var!=0?100*LINE_MIN_MAX_AVG(var)/size_##var:0,\
+								count_##var
+
+#define LINE_MIN_MAX_FORMAT_STREAM           "%14s|%10u|%10u|%16u|%5u|%16u|"
+#define LINE_MIN_MAX_STREAM(name,var) name,\
+										MIN_MAX_VAL(max_##var),\
+										MIN_MAX_VAL(min_##var),\
+										LINE_MIN_MAX_AVG(var),\
+										size_##var!=0?100*LINE_MIN_MAX_AVG(var)/size_##var:0,\
+										count_##var
+#define LINE_MIN_MAX_DURATION_FORMAT "%14s%10u|%10u|%11u|%11u|"
+#define LINE_MIN_MAX_DURATION(name,var) name,MIN_MAX_VAL(max_##var),MIN_MAX_VAL(min_##var), LINE_MIN_MAX_AVG(var), count_##var
+
 
 #define TIME_MEASUREMENT_START(x) x=esp_timer_get_time()
-#define TIME_MEASUREMENT_GET(x) (esp_timer_get_time()-x)/1000
+#define TIME_MEASUREMENT_GET(x) (esp_timer_get_time()-x)
 
 #define TIMED_SECTION_START_MS_FORCE(x,force) if(hasTimeElapsed(x,force)) {
 #define TIMED_SECTION_START_MS(x) 		if(hasTimeElapsed(x,false)){

main/squeezelite.h

@@ -46,6 +46,9 @@
 #define POSIX 1
 #include "embedded.h"
 #endif
+#ifndef PTHREAD_SET_NAME
+#define PTHREAD_SET_NAME(n)
+#endif
 
 // build detection
 #if defined(linux)
@@ -334,6 +337,10 @@ typedef int64_t   s64_t;
 #define mutex_lock(m) pthread_mutex_lock(&m)
 #define mutex_unlock(m) pthread_mutex_unlock(&m)
 #define mutex_destroy(m) pthread_mutex_destroy(&m)
+#define mutex_broadcast_cond(m) pthread_cond_broadcast(&m)
+#define mutex_cond_wait(c,m) pthread_cond_wait(&c, &m)
+#define mutex_cond_init(c) pthread_cond_init(&c, NULL)
+#define thread_cond_type pthread_cond_t
 #define thread_type pthread_t
 
 #endif
@@ -765,6 +772,7 @@ bool test_open(const char *device, unsigned rates[], bool userdef_rates);
 void output_init_bt(log_level level, char *device, unsigned output_buf_size, char *params, unsigned rates[], unsigned rate_delay, unsigned idle);
 void output_close_bt(void);
 void hal_bluetooth_init(log_level loglevel);
+void output_bt_check_buffer();
 #endif
 
 

main/stream.c

@@ -405,7 +405,7 @@ void stream_init(log_level level, unsigned stream_buf_size) {
 #if LINUX || FREEBSD
 	touch_memory(streambuf->buf, streambuf->size);
 #endif
-
+PTHREAD_SET_NAME("stream");
 #if LINUX || OSX || FREEBSD || POSIX
 	pthread_attr_t attr;
 	pthread_attr_init(&attr);