BT ring buffering

main/Kconfig.projbuild

@@ -195,7 +195,14 @@ menu "Squeezelite-ESP32"
 		    	int "Time out duration when trying to connect to an A2DP audio sink"
 		        default 1000
 		        help
-		            Increasing this value will give more chance for less stable connections to be established.	    		            
+		            Increasing this value will give more chance for less stable connections to be established.	   
+            config A2DP_DISCONNECT_MS
+            	int "Time in ms before disconnecting from A2DP audio sink. Set to 0 for no disconnect."
+            	default 10000
+            	help
+            		Controls how long to wait before disconnecting from the A2DP audio sink after playback is stopped
+            		Longer delay will ensure better responsiveness at the expense of locking the audio sink for a longer period. 
+            		A shorter period may cause the player to disconnect between tracks change.
 		endif # BTAUDIO   
 	endmenu
 

main/esp32.c

@@ -16,7 +16,7 @@
 #include "nvs_flash.h"
 #include "esp_system.h"
 #include "esp_log.h"
-
+#include "perf_trace.h"
 
 #include "esp_bt.h"
 #include "bt_app_core.h"
@@ -28,13 +28,17 @@
 #include "esp_pthread.h"
 #include "pthread.h"
 #define BT_AV_TAG               "BT_AV"
-u8_t *bt_optr;
 extern log_level loglevel;
 extern struct outputstate output;
 extern struct buffer *outputbuf;
 extern struct buffer *streambuf;
+extern struct buffer *btbuf;
+
+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
@@ -56,12 +60,13 @@ int64_t connecting_timeout = 0;
 #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(o, long,LONG); DECLARE_MIN_MAX(s, long,LONG); DECLARE_MIN_MAX(d, long,LONG);
-#define RESET_ALL_MIN_MAX RESET_MIN_MAX(d,LONG); RESET_MIN_MAX(o,LONG); RESET_MIN_MAX(s,LONG); RESET_MIN_MAX(req,LONG);
+//#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);
 
+static void filter_inquiry_scan_result(esp_bt_gap_cb_param_t *param);
 
 void get_mac(u8_t mac[]) {
     esp_read_mac(mac, ESP_MAC_WIFI_STA);
@@ -151,6 +156,7 @@ char * APP_AV_STATE_DESC[] = {
 enum {
     APP_AV_MEDIA_STATE_IDLE,
     APP_AV_MEDIA_STATE_STARTING,
+	APP_AV_MEDIA_STATE_BUFFERING,
     APP_AV_MEDIA_STATE_STARTED,
     APP_AV_MEDIA_STATE_STOPPING,
 	APP_AV_MEDIA_STATE_WAIT_DISCONNECT
@@ -165,8 +171,6 @@ static void bt_av_hdl_stack_evt(uint16_t event, void *p_param);
 static void bt_app_a2d_cb(esp_a2d_cb_event_t event, esp_a2d_cb_param_t *param);
 
 /// callback function for A2DP source audio data stream
-static int32_t bt_app_a2d_data_cb(uint8_t *data, int32_t len);
-
 static void a2d_app_heart_beat(void *arg);
 
 /// A2DP application state machine
@@ -187,17 +191,6 @@ static uint32_t s_pkt_cnt = 0;
 
 static TimerHandle_t s_tmr;
 
-static char *bda2str(esp_bd_addr_t bda, char *str, size_t size)
-{
-    if (bda == NULL || str == NULL || size < 18) {
-        return NULL;
-    }
-
-    uint8_t *p = bda;
-    sprintf(str, "%02x:%02x:%02x:%02x:%02x:%02x",
-            p[0], p[1], p[2], p[3], p[4], p[5]);
-    return str;
-}
 void hal_bluetooth_init(log_level level)
 {
 
@@ -251,7 +244,219 @@ 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;
+
+	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);
+	LOCK_BT;
+	SET_MIN_MAX(_buf_used(btbuf)/BYTES_PER_FRAME,bt);
+	do {
+
+		avail_data=min(_buf_cont_read(btbuf),wanted_len);
+		if(avail_data>0){
+			memcpy(data,btbuf->readp,avail_data);
+			_buf_inc_readp(btbuf,avail_data);
+			wanted_len-=avail_data;
+			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;
+		}
+	} 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);
+	LOCK;
+	   	output.device_frames = 0;
+	   	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;
+	return len-wanted_len;
+}
+
+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);
+}
 
+void bt_app_gap_cb(esp_bt_gap_cb_event_t event, esp_bt_gap_cb_param_t *param)
+{
+
+    switch (event) {
+    case ESP_BT_GAP_DISC_RES_EVT: {
+        filter_inquiry_scan_result(param);
+        break;
+    }
+    case ESP_BT_GAP_DISC_STATE_CHANGED_EVT: {
+        if (param->disc_st_chg.state == ESP_BT_GAP_DISCOVERY_STOPPED)
+        {
+            if (s_a2d_state == APP_AV_STATE_DISCOVERED)
+            {
+            	LOG_INFO("Discovery completed.  Ready to start connecting to %s. ",s_peer_bdname);
+            	s_a2d_state = APP_AV_STATE_UNCONNECTED;
+            }
+            else
+            {
+                // not discovered, continue to discover
+                LOG_INFO("Device discovery failed, continue to discover...");
+                esp_bt_gap_start_discovery(ESP_BT_INQ_MODE_GENERAL_INQUIRY, 10, 0);
+            }
+        }
+        else if (param->disc_st_chg.state == ESP_BT_GAP_DISCOVERY_STARTED) {
+            LOG_INFO("Discovery started.");
+        }
+        else
+        {
+        	LOG_DEBUG("This shouldn't happen.  Discovery has only 2 states (for now).");
+        }
+        break;
+    }
+    case ESP_BT_GAP_RMT_SRVCS_EVT:
+    	LOG_DEBUG_EVENT(ESP_BT_GAP_RMT_SRVCS_EVT);
+    	break;
+    case ESP_BT_GAP_RMT_SRVC_REC_EVT:
+    	LOG_DEBUG_EVENT(ESP_BT_GAP_RMT_SRVC_REC_EVT);
+        break;
+    case ESP_BT_GAP_AUTH_CMPL_EVT: {
+    	if (param->auth_cmpl.stat == ESP_BT_STATUS_SUCCESS) {
+            LOG_INFO("authentication success: %s", param->auth_cmpl.device_name);
+            //esp_log_buffer_hex(param->auth_cmpl.bda, ESP_BD_ADDR_LEN);
+        } else {
+            LOG_ERROR("authentication failed, status:%d", param->auth_cmpl.stat);
+        }
+        break;
+    }
+    case ESP_BT_GAP_PIN_REQ_EVT: {
+    	LOG_INFO("ESP_BT_GAP_PIN_REQ_EVT min_16_digit:%d", param->pin_req.min_16_digit);
+        if (param->pin_req.min_16_digit) {
+            LOG_INFO("Input pin code: 0000 0000 0000 0000");
+            esp_bt_pin_code_t pin_code = {0};
+            esp_bt_gap_pin_reply(param->pin_req.bda, true, 16, pin_code);
+        } else {
+            LOG_INFO("Input pin code: 1234");
+            esp_bt_pin_code_t pin_code;
+            pin_code[0] = '1';
+            pin_code[1] = '2';
+            pin_code[2] = '3';
+            pin_code[3] = '4';
+            esp_bt_gap_pin_reply(param->pin_req.bda, true, 4, pin_code);
+        }
+        break;
+    }
+
+#if (CONFIG_BT_SSP_ENABLED == true)
+    case ESP_BT_GAP_CFM_REQ_EVT:
+        LOG_INFO("ESP_BT_GAP_CFM_REQ_EVT Please compare the numeric value: %d", param->cfm_req.num_val);
+        esp_bt_gap_ssp_confirm_reply(param->cfm_req.bda, true);
+        break;
+    case ESP_BT_GAP_KEY_NOTIF_EVT:
+        LOG_INFO("ESP_BT_GAP_KEY_NOTIF_EVT passkey:%d", param->key_notif.passkey);
+        break;
+        LOG_INFO("ESP_BT_GAP_KEY_REQ_EVT Please enter passkey!");
+        break;
+#endif
+
+    default: {
+        LOG_INFO("event: %d", event);
+        break;
+    }
+    }
+    return;
+}
+
+static void a2d_app_heart_beat(void *arg)
+{
+    bt_app_work_dispatch(bt_app_av_sm_hdlr, BT_APP_HEART_BEAT_EVT, NULL, 0, NULL);
+}
+
+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);
+    	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);
+        break;
+    case APP_AV_STATE_UNCONNECTED:
+        bt_app_av_state_unconnected(event, param);
+        break;
+    case APP_AV_STATE_CONNECTING:
+        bt_app_av_state_connecting(event, param);
+        break;
+    case APP_AV_STATE_CONNECTED:
+        bt_app_av_state_connected(event, param);
+        break;
+    case APP_AV_STATE_DISCONNECTING:
+        bt_app_av_state_disconnecting(event, param);
+        break;
+    default:
+        LOG_ERROR("%s invalid state %d", __func__, s_a2d_state);
+        break;
+    }
+}
+
+static char *bda2str(esp_bd_addr_t bda, char *str, size_t size)
+{
+    if (bda == NULL || str == NULL || size < 18) {
+        return NULL;
+    }
+
+    uint8_t *p = bda;
+    sprintf(str, "%02x:%02x:%02x:%02x:%02x:%02x",
+            p[0], p[1], p[2], p[3], p[4], p[5]);
+    return str;
+}
 static bool get_name_from_eir(uint8_t *eir, uint8_t *bdname, uint8_t *bdname_len)
 {
     uint8_t *rmt_bdname = NULL;
@@ -336,12 +541,12 @@ static void filter_inquiry_scan_result(esp_bt_gap_cb_param_t *param)
     if (eir) {
     	LOG_INFO_NO_LF("\n--Getting details from eir.\n");
         get_name_from_eir(eir, s_peer_bdname, NULL);
-        LOG_INFO("--\nDevice name is %s",s_peer_bdname);
+        LOG_INFO_NO_LF("\n--Device name is %s\n",s_peer_bdname);
     }
 
     if (strcmp((char *)s_peer_bdname, CONFIG_A2DP_SINK_NAME) == 0) {
-    	LOG_INFO("Found a target device, address %s, name %s", bda_str, s_peer_bdname);
-
+    	LOG_INFO_NO_LF("Found a target device! address %s, name %s", bda_str, s_peer_bdname);
+    	LOG_INFO_NO_LF("\n=======================\n");
         if(esp_bt_gap_cancel_discovery()!=ESP_ERR_INVALID_STATE)
         {
         	LOG_INFO("Cancel device discovery ...");
@@ -360,101 +565,6 @@ static void filter_inquiry_scan_result(esp_bt_gap_cb_param_t *param)
 }
 
 
-void bt_app_gap_cb(esp_bt_gap_cb_event_t event, esp_bt_gap_cb_param_t *param)
-{
-
-    switch (event) {
-    case ESP_BT_GAP_DISC_RES_EVT: {
-        filter_inquiry_scan_result(param);
-        break;
-    }
-    case ESP_BT_GAP_DISC_STATE_CHANGED_EVT: {
-        if (param->disc_st_chg.state == ESP_BT_GAP_DISCOVERY_STOPPED)
-        {
-            if (s_a2d_state == APP_AV_STATE_DISCOVERED)
-            {
-                if(esp_a2d_source_connect(s_peer_bda)!=ESP_ERR_INVALID_STATE)
-                {
-                	s_a2d_state = APP_AV_STATE_CONNECTING;
-					LOG_INFO("Device discovery stopped. a2dp connecting to peer: %s", s_peer_bdname);
-					A2DP_TIMER_INIT;
-                }
-                else
-                {
-                	// not discovered, continue to discover
-					LOG_INFO("Attempt at connecting failed, resuming discover...");
-					esp_bt_gap_start_discovery(ESP_BT_INQ_MODE_GENERAL_INQUIRY, 10, 0);
-                }
-            }
-            else
-            {
-                // not discovered, continue to discover
-                LOG_INFO("Device discovery failed, continue to discover...");
-                esp_bt_gap_start_discovery(ESP_BT_INQ_MODE_GENERAL_INQUIRY, 10, 0);
-            }
-        }
-        else if (param->disc_st_chg.state == ESP_BT_GAP_DISCOVERY_STARTED) {
-            LOG_INFO("Discovery started.");
-        }
-        else
-        {
-        	LOG_DEBUG("This shouldn't happen.  Discovery has only 2 states (for now).");
-        }
-        break;
-    }
-    case ESP_BT_GAP_RMT_SRVCS_EVT:
-    	LOG_DEBUG_EVENT(ESP_BT_GAP_RMT_SRVCS_EVT);
-    	break;
-    case ESP_BT_GAP_RMT_SRVC_REC_EVT:
-    	LOG_DEBUG_EVENT(ESP_BT_GAP_RMT_SRVC_REC_EVT);
-        break;
-    case ESP_BT_GAP_AUTH_CMPL_EVT: {
-    	if (param->auth_cmpl.stat == ESP_BT_STATUS_SUCCESS) {
-            LOG_INFO("authentication success: %s", param->auth_cmpl.device_name);
-            //esp_log_buffer_hex(param->auth_cmpl.bda, ESP_BD_ADDR_LEN);
-        } else {
-            LOG_ERROR("authentication failed, status:%d", param->auth_cmpl.stat);
-        }
-        break;
-    }
-    case ESP_BT_GAP_PIN_REQ_EVT: {
-    	LOG_INFO("ESP_BT_GAP_PIN_REQ_EVT min_16_digit:%d", param->pin_req.min_16_digit);
-        if (param->pin_req.min_16_digit) {
-            LOG_INFO("Input pin code: 0000 0000 0000 0000");
-            esp_bt_pin_code_t pin_code = {0};
-            esp_bt_gap_pin_reply(param->pin_req.bda, true, 16, pin_code);
-        } else {
-            LOG_INFO("Input pin code: 1234");
-            esp_bt_pin_code_t pin_code;
-            pin_code[0] = '1';
-            pin_code[1] = '2';
-            pin_code[2] = '3';
-            pin_code[3] = '4';
-            esp_bt_gap_pin_reply(param->pin_req.bda, true, 4, pin_code);
-        }
-        break;
-    }
-
-#if (CONFIG_BT_SSP_ENABLED == true)
-    case ESP_BT_GAP_CFM_REQ_EVT:
-        LOG_INFO("ESP_BT_GAP_CFM_REQ_EVT Please compare the numeric value: %d", param->cfm_req.num_val);
-        esp_bt_gap_ssp_confirm_reply(param->cfm_req.bda, true);
-        break;
-    case ESP_BT_GAP_KEY_NOTIF_EVT:
-        LOG_INFO("ESP_BT_GAP_KEY_NOTIF_EVT passkey:%d", param->key_notif.passkey);
-        break;
-        LOG_INFO("ESP_BT_GAP_KEY_REQ_EVT Please enter passkey!");
-        break;
-#endif
-
-    default: {
-        LOG_INFO("event: %d", event);
-        break;
-    }
-    }
-    return;
-}
-
 static void bt_av_hdl_stack_evt(uint16_t event, void *p_param)
 {
 
@@ -497,90 +607,6 @@ static void bt_av_hdl_stack_evt(uint16_t event, void *p_param)
     }
 }
 
-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);
-}
-
-static int32_t bt_app_a2d_data_cb(uint8_t *data, int32_t len)
-{
-	frames_t frames;
-	static int count = 0;
-
-	DECLARE_ALL_MIN_MAX;
-
-	if (len < 0 || data == NULL ) {
-        return 0;
-    }
-
-	// bail out if A2DP isn't connected
-	LOCK;
-//	if(s_media_state != APP_AV_MEDIA_STATE_STARTED)
-//    {
-//		UNLOCK;
-//    	return 0;
-//    }
-
-
-//
-///*	Normally, we would want BT to not call us back unless we are not in BUFFERING state.
-//	That requires BT to not start until we are > OUTPUT_BUFFER
-//	// come back later, we are buffering (or stopped, need to handle that case ...) but we don't want silence */
-//	if (output.state == OUTPUT_BUFFER) {
-//		UNLOCK;
-//		int32_t silence_bytes = (len >MAX_SILENCE_FRAMES * BYTES_PER_FRAME?MAX_SILENCE_FRAMES * BYTES_PER_FRAME:len;
-//		memcpy(bt_optr, (u8_t *)silencebuf, silence_bytes);
-//		return actual_len;
-//	}
-// 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
-   	frames = len / BYTES_PER_FRAME;
-   	output.device_frames = 0;
-   	output.updated = gettime_ms();
-   	output.frames_played_dmp = output.frames_played;
-	//if (output.threshold < 20) output.threshold = 20;
-
-	frames_t wanted_frames=len/BYTES_PER_FRAME;
-	bt_optr = data; // needed for the _write_frames callback
-	do {
-			frames = _output_frames(wanted_frames);
-			wanted_frames -= frames;
-		} while (wanted_frames > 0 && frames != 0);
-
-		if (wanted_frames > 0) {
-			LOG_DEBUG("need to pad with silence");
-			memset(bt_optr, 0, wanted_frames * BYTES_PER_FRAME);
-		}
-
-
-	UNLOCK;
-
-	SET_MIN_MAX(_buf_used(outputbuf),o);
-	SET_MIN_MAX(_buf_used(streambuf),s);
-	SET_MIN_MAX(frames,req);
-
-	if (!(count++ & 0x1ff)) {
-		LOG_INFO( "count:%d"
-							"\n              ----------+----------+-----------+  +----------+----------+----------------+"
-							"\n                    max |      min |    current|  |      max |      min |        current |"
-							"\n                   (ms) |     (ms) |       (ms)|  | (frames) | (frames) |        (frames)|"
-							"\n              ----------+----------+-----------+  +----------+----------+----------------+"
-							"\nout           %10d|%10d|%11d|"                 "  |%10d|%10d|%16d|"
-							"\nstream        %10d|%10d|%11d|"                 "  |%10d|%10d|%16d|"
-							"\nN/A           %10d|%10d|%11d|"                 "  |%10d|%10d|%16d|"
-							"\nrequested     %10d|%10d|%11d|"                 "  |%10d|%10d|%16d|"
-							"\n              ----------+----------+-----------+  +----------+----------+----------------+",
-							count,
-							BYTES_TO_MS(max_o), BYTES_TO_MS(min_o),BYTES_TO_MS(o),max_o,min_o,o,
-							BYTES_TO_MS(max_s), BYTES_TO_MS(min_s),BYTES_TO_MS(s),max_s,min_s,s,
-							BYTES_TO_MS(max_d),BYTES_TO_MS(min_d),BYTES_TO_MS(d),max_d,min_d,d,
-							FRAMES_TO_MS(req),FRAMES_TO_MS(req),FRAMES_TO_MS(req), req, req,req);
-		RESET_ALL_MIN_MAX;
-	}
-
-	return frames * BYTES_PER_FRAME;
-}
-
 #ifdef BTAUDIO
 bool test_open(const char *device, unsigned rates[], bool userdef_rates) {
 
@@ -602,41 +628,146 @@ bool test_open(const char *device, unsigned rates[], bool userdef_rates) {
 	return true;
 }
 #endif
-static void a2d_app_heart_beat(void *arg)
-{
-    bt_app_work_dispatch(bt_app_av_sm_hdlr, BT_APP_HEART_BEAT_EVT, NULL, 0, NULL);
-}
-
-static void bt_app_av_sm_hdlr(uint16_t event, void *param)
+static void bt_app_av_media_proc(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_DEBUG("state %s, evt 0x%x, output state: %d", APP_AV_STATE_DESC[s_a2d_state], event, output.state);
-    	break;
-    case APP_AV_STATE_DISCOVERED:
-    	LOG_DEBUG("state %s, evt 0x%x, output state: %d", APP_AV_STATE_DESC[s_a2d_state], event, output.state);
-        break;
-    case APP_AV_STATE_UNCONNECTED:
-        bt_app_av_state_unconnected(event, param);
-        break;
-    case APP_AV_STATE_CONNECTING:
-        bt_app_av_state_connecting(event, param);
+    esp_a2d_cb_param_t *a2d = NULL;
+    LOCK;
+    output_state out_state=output.state;
+    UNLOCK;
+	unsigned bt_buffer_used=_buf_used(btbuf);
+    switch (s_media_state) {
+    case APP_AV_MEDIA_STATE_IDLE: {
+    	if (event == BT_APP_HEART_BEAT_EVT) {
+            if(out_state > OUTPUT_STOPPED)
+            {
+            	LOG_INFO("buffering output, a2dp media ready and connected. Starting checking if ready...");
+            	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 &&
+					a2d->media_ctrl_stat.status == ESP_A2D_MEDIA_CTRL_ACK_SUCCESS
+					) {
+				LOG_INFO("a2dp media ready, waiting for media buffering ...");
+				s_media_state = APP_AV_MEDIA_STATE_BUFFERING;
+			}
+        }
         break;
-    case APP_AV_STATE_CONNECTED:
-        bt_app_av_state_connected(event, 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);
+             }
+
+          }
+      	else{
+      		LOG_WARN("Received unknown event while in state APP_AV_MEDIA_STATE_BUFFERING");
+      	}
+
+          break;
+      }
+
+
+    case APP_AV_MEDIA_STATE_STARTING: {
+    	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_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
+                LOG_INFO("a2dp media start failed.");
+                s_media_state = APP_AV_MEDIA_STATE_IDLE;
+            }
+        }
         break;
-    case APP_AV_STATE_DISCONNECTING:
-        bt_app_av_state_disconnecting(event, param);
+    }
+    case APP_AV_MEDIA_STATE_STARTED: {
+        if (event == BT_APP_HEART_BEAT_EVT) {
+        	if(out_state <= OUTPUT_STOPPED) {
+                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;
+            }
+        	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("              **********+**********+***********+***********+  +**********+**********+****************+****************+****************+");
+					RESET_ALL_MIN_MAX;
+				}
+
+        	}
+        }
         break;
-    default:
-        LOG_ERROR("%s invalid state %d", __func__, s_a2d_state);
+    }
+    case APP_AV_MEDIA_STATE_STOPPING: {
+    	LOG_DEBUG_EVENT(APP_AV_MEDIA_STATE_STOPPING);
+        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_STOP &&
+                    a2d->media_ctrl_stat.status == ESP_A2D_MEDIA_CTRL_ACK_SUCCESS) {
+                LOG_INFO("a2dp media stopped successfully...");
+                //s_media_state = APP_AV_MEDIA_STATE_WAIT_DISCONNECT;
+              //  if(CONFIG_A2DP_DISCONNECT_MS==0){
+                	// we're not going to disconnect.
+                	s_media_state = APP_AV_MEDIA_STATE_IDLE;
+//                }
+//                else
+//                {
+//                	disconnect_time = gettime_ms()+CONFIG_A2DP_DISCONNECT_MS;
+//                	s_media_state = APP_AV_MEDIA_STATE_WAIT_DISCONNECT;
+//                }
+            } else {
+                LOG_INFO("a2dp media stopping...");
+                esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_STOP);
+            }
+        }
         break;
     }
+
+    case APP_AV_MEDIA_STATE_WAIT_DISCONNECT:{
+    	if(gettime_ms()>disconnect_time){
+    		// we've reached timeout
+			esp_a2d_source_disconnect(s_peer_bda);
+			s_a2d_state = APP_AV_STATE_DISCONNECTING;
+    	}
+    }
+    }
 }
 
 static void bt_app_av_state_unconnected(uint16_t event, void *param)
 {
+//	LOCK;
+//	output_state out_state= output.state;
+//	UNLOCK;
 	switch (event) {
     case ESP_A2D_CONNECTION_STATE_EVT:
     	LOG_DEBUG_EVENT(ESP_A2D_CONNECTION_STATE_EVT);
@@ -651,33 +782,36 @@ static void bt_app_av_state_unconnected(uint16_t event, void *param)
     	LOG_DEBUG_EVENT(ESP_A2D_MEDIA_CTRL_ACK_EVT);
     	break;
     case BT_APP_HEART_BEAT_EVT: {
-        uint8_t *p = s_peer_bda;
-        LOG_INFO("BT_APP_HEART_BEAT_EVT a2dp connecting to peer: %02x:%02x:%02x:%02x:%02x:%02x",p[0], p[1], p[2], p[3], p[4], p[5]);
+       // uint8_t *p = s_peer_bda;
+       // LOG_INFO("BT_APP_HEART_BEAT_EVT a2dp connecting to peer: %02x:%02x:%02x:%02x:%02x:%02x",p[0], p[1], p[2], p[3], p[4], p[5]);
         switch (esp_bluedroid_get_status()) {
 		case ESP_BLUEDROID_STATUS_UNINITIALIZED:
-			LOG_INFO("BlueDroid Status is ESP_BLUEDROID_STATUS_UNINITIALIZED.");
+			LOG_SDEBUG("BlueDroid Status is ESP_BLUEDROID_STATUS_UNINITIALIZED.");
 			break;
 		case ESP_BLUEDROID_STATUS_INITIALIZED:
-			LOG_INFO("BlueDroid Status is ESP_BLUEDROID_STATUS_INITIALIZED.");
+			LOG_SDEBUG("BlueDroid Status is ESP_BLUEDROID_STATUS_INITIALIZED.");
 			break;
 		case ESP_BLUEDROID_STATUS_ENABLED:
-			LOG_INFO("BlueDroid Status is ESP_BLUEDROID_STATUS_ENABLED.");
+			LOG_SDEBUG("BlueDroid Status is ESP_BLUEDROID_STATUS_ENABLED.");
 			break;
 			default:
 				break;
 		}
-        if(esp_a2d_source_connect(s_peer_bda)!=ESP_ERR_INVALID_STATE)
-		{
-			s_a2d_state = APP_AV_STATE_CONNECTING;
-			LOG_INFO("a2dp connecting to peer: %s", s_peer_bdname);
-			A2DP_TIMER_INIT;
-		}
-		else
-		{
-			// not discovered, continue to discover
-			LOG_INFO("Attempt at connecting failed, resuming discover...");
-			esp_bt_gap_start_discovery(ESP_BT_INQ_MODE_GENERAL_INQUIRY, 10, 0);
-		}
+//        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) {
+				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);
+				A2DP_TIMER_INIT;
+			}
+			else {
+				// there was an issue connecting... continue to discover
+				LOG_ERROR("Attempt at connecting failed, restart at discover...");
+				esp_bt_gap_start_discovery(ESP_BT_INQ_MODE_GENERAL_INQUIRY, 10, 0);
+	//		}
+        }
         break;
     }
     default:
@@ -694,9 +828,9 @@ static void bt_app_av_state_connecting(uint16_t event, void *param)
     case ESP_A2D_CONNECTION_STATE_EVT: {
         a2d = (esp_a2d_cb_param_t *)(param);
         if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED) {
-            LOG_INFO("a2dp connected! Stopping scan. ");
             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. ");
             esp_bt_gap_set_scan_mode(ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE);
         } else if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_DISCONNECTED) {
             s_a2d_state =  APP_AV_STATE_UNCONNECTED;
@@ -716,7 +850,8 @@ static void bt_app_av_state_connecting(uint16_t event, void *param)
     	if (IS_A2DP_TIMER_OVER)
     	{
             s_a2d_state = APP_AV_STATE_UNCONNECTED;
-            LOG_DEBUG("Connect timed out.  Setting state to Unconnected. ");
+            LOG_ERROR("A2DP Connect time out!  Setting state to Unconnected. ");
+            A2DP_TIMER_INIT;
         }
     	LOG_SDEBUG("BT_APP_HEART_BEAT_EVT");
         break;
@@ -727,93 +862,6 @@ static void bt_app_av_state_connecting(uint16_t event, void *param)
 }
 
 
-static void bt_app_av_media_proc(uint16_t event, void *param)
-{
-    esp_a2d_cb_param_t *a2d = NULL;
-    switch (s_media_state) {
-    case APP_AV_MEDIA_STATE_IDLE: {
-    	if (event == BT_APP_HEART_BEAT_EVT) {
-            if(output.state < OUTPUT_STOPPED )
-        	{
-        		// TODO: anything to do while we are waiting? Should we check if we're still connected?
-        	}
-            else if(output.state >= OUTPUT_BUFFER )
-            {
-            	LOG_INFO("buffering output, a2dp media ready and connected. Starting checking if ready...");
-            	esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_CHECK_SRC_RDY);
-            }
-//            else if(running_test)
-//			{
-//            	LOG_INFO("buffering output, a2dp media ready and connected. Starting checking if ready...");
-//
-//            	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 &&
-					a2d->media_ctrl_stat.status == ESP_A2D_MEDIA_CTRL_ACK_SUCCESS
-					) {
-				LOG_INFO("a2dp media ready, starting media playback ...");
-				s_media_state = APP_AV_MEDIA_STATE_STARTING;
-				esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_START);
-
-			}
-        }
-        break;
-    }
-    case APP_AV_MEDIA_STATE_STARTING: {
-    	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_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
-                LOG_INFO("a2dp media start failed.");
-                s_media_state = APP_AV_MEDIA_STATE_IDLE;
-            }
-        }
-        break;
-    }
-    case APP_AV_MEDIA_STATE_STARTED: {
-        if (event == BT_APP_HEART_BEAT_EVT) {
-        	if(output.state <= OUTPUT_STOPPED) {
-                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;
-            }
-        }
-        break;
-    }
-    case APP_AV_MEDIA_STATE_STOPPING: {
-    	LOG_DEBUG_EVENT(APP_AV_MEDIA_STATE_STOPPING);
-        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_STOP &&
-                    a2d->media_ctrl_stat.status == ESP_A2D_MEDIA_CTRL_ACK_SUCCESS) {
-                LOG_INFO("a2dp media stopped successfully...");
-                //s_media_state = APP_AV_MEDIA_STATE_WAIT_DISCONNECT;
-
-                s_media_state = APP_AV_MEDIA_STATE_IDLE;
-                // todo:  should we disconnect?
-//                esp_a2d_source_disconnect(s_peer_bda);
-//                s_a2d_state = APP_AV_STATE_DISCONNECTING;
-            } else {
-                LOG_INFO("a2dp media stopping...");
-                esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_STOP);
-            }
-        }
-        break;
-    }
-    }
-}
-
 static void bt_app_av_state_connected(uint16_t event, void *param)
 {
     esp_a2d_cb_param_t *a2d = NULL;

main/main.c

@@ -803,7 +803,7 @@ int main(int argc, char **argv) {
 
 #if CONFIG_DACAUDIO
 	output_close_dac();	
-#elif BTAUDIO
+#elif CONFIG_BTAUDIO
 	output_close_bt();
 #else
 	if (!strcmp(output_device, "-")) {

main/output_bt.c

@@ -1,5 +1,5 @@
 #include "squeezelite.h"
-
+#include "perf_trace.h"
 
 static log_level loglevel;
 
@@ -8,22 +8,54 @@ 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)
+#define LOCK_BT   mutex_lock(btbuf->mutex)
+#define UNLOCK_BT mutex_unlock(btbuf->mutex)
 
 #define FRAME_BLOCK MAX_SILENCE_FRAMES
+#define BUFFERING_FRAME_BLOCK FRAME_BLOCK*2
 
 extern u8_t *silencebuf;
 
-extern u8_t *bt_optr;
 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);
-#if BTAUDIO
-void set_volume(unsigned left, unsigned right) {
+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);
+#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);
+
+
+#if CONFIG_BTAUDIO
+void set_volume_bt(unsigned left, unsigned right) {
 	LOG_DEBUG("setting internal gain left: %u right: %u", left, right);
 	LOCK;
 	output.gainL = left;
@@ -32,7 +64,7 @@ void set_volume(unsigned left, unsigned right) {
 }
 #endif
 
-
+static thread_type thread_bt;
 void output_init_bt(log_level level, char *device, unsigned output_buf_size, char *params, unsigned rates[], unsigned rate_delay, unsigned idle) {
 	loglevel = level;
 
@@ -55,9 +87,127 @@ 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);
+	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);
+	}
+
+
+#if LINUX || OSX || FREEBSD || POSIX
+	pthread_attr_t attr;
+	pthread_attr_init(&attr);
+#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
+#if WIN
+	thread = CreateThread(NULL, OUTPUT_THREAD_STACK_SIZE, (LPTHREAD_START_ROUTINE)&output_thread_bt, NULL, 0, NULL);
+#endif
+	LOG_INFO("Init completed.");
 
 }
 
+/****************************************************************************************
+ * Main output thread
+ */
+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;
+
+	DECLARE_ALL_MIN_MAX;
+
+	while (running) {
+		frames=0;
+		available_frames_space=0;
+
+		TIME_MEASUREMENT_START(timer_start);
+		TIME_MEASUREMENT_START(total_start);
+		TIME_MEASUREMENT_START(mutex_start);
+		LOCK;
+		SET_MIN_MAX(TIME_MEASUREMENT_GET(mutex_start),mutex1);
+		if (output.state == OUTPUT_OFF) {
+			UNLOCK;
+			LOG_SDEBUG("Output state is off.");
+			usleep(500000);
+			continue;
+		}
+		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)
+		{
+			UNLOCK;
+			UNLOCK_BT;
+			usleep(10000);
+			continue;
+		}
+		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);
+
+		/*
+		 * 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("              ----------+----------+-----------+-----------+-----------+");
+			RESET_ALL_MIN_MAX;
+			count=0;
+		}
+		TIMED_SECTION_END;
+		/*
+		 * End Statistics reporting
+		 */
+
+
+	}
+
+
+	return 0;
+}
 void output_close_bt(void) {
 	LOG_INFO("close output");
 	LOCK;
@@ -83,7 +233,9 @@ static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t g
 		}
 
 #if BYTES_PER_FRAME == 4
-		memcpy(bt_optr, outputbuf->readp, out_frames * BYTES_PER_FRAME);
+
+		memcpy(btbuf->writep, outputbuf->readp, out_frames * BYTES_PER_FRAME);
+
 #else
 	{
 		frames_t count = out_frames;
@@ -100,11 +252,8 @@ static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t g
 		DEBUG_LOG_TIMED(200,"Silence flag true. Writing silence to audio out.");
 
 		u8_t *buf = silencebuf;
-
-		memcpy(bt_optr, buf, out_frames * 4);
+		memcpy(btbuf->writep, buf, out_frames * BYTES_PER_FRAME);
 	}
-
-	bt_optr += out_frames * 4;
-
+	_buf_inc_writep(btbuf,out_frames * BYTES_PER_FRAME);
 	return (int)out_frames;
 }

main/output_dac.c

@@ -28,6 +28,22 @@
 	RESET_MIN_MAX(i2savailable,LONG);\
 	RESET_MIN_MAX(i2s_time,LONG);
 
+// Prevent compile errors if dac output is
+// included in the build and not actually activated in menuconfig
+#ifndef CONFIG_I2S_BCK_IO
+#define CONFIG_I2S_BCK_IO -1
+#endif
+#ifndef CONFIG_I2S_WS_IO
+#define CONFIG_I2S_WS_IO -1
+#endif
+#ifndef CONFIG_I2S_DO_IO
+#define CONFIG_I2S_DO_IO -1
+#endif
+#ifndef CONFIG_I2S_NUM
+#define CONFIG_I2S_NUM -1
+#endif
+
+
 static log_level loglevel;
 size_t dac_buffer_size =0;
 static bool running = true;
@@ -59,12 +75,12 @@ 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();
-
+extern void wait_for_frames(size_t frames, uint8_t pct);
 
 /****************************************************************************************
  * set output volume
  */
-void set_volume(unsigned left, unsigned right) {
+void set_volume_dac(unsigned left, unsigned right) {
 	LOG_DEBUG("setting internal gain left: %u right: %u", left, right);
 	LOCK;
 	output.gainL = left;
@@ -83,7 +99,7 @@ void output_init_dac(log_level level, char *device, unsigned output_buf_size, ch
 	LOG_DEBUG("Setting output parameters.");
 
 	memset(&output, 0, sizeof(output));
-
+#ifdef CONFIG_I2S_BITS_PER_CHANNEL
 	switch (CONFIG_I2S_BITS_PER_CHANNEL) {
 		case 24:
 			output.format = S24_BE;
@@ -98,6 +114,9 @@ void output_init_dac(log_level level, char *device, unsigned output_buf_size, ch
 			LOG_ERROR("Unsupported bit depth %d",CONFIG_I2S_BITS_PER_CHANNEL);
 			break;
 	}
+#else
+	output.format = S16_LE;
+#endif
 	// ensure output rate is specified to avoid test open
 	if (!rates[0]) {
 		rates[0] = 44100;
@@ -227,13 +246,7 @@ static int _dac_write_frames(frames_t out_frames, bool silence, s32_t gainL, s32
 }
 
 
-/****************************************************************************************
- * Wait for a duration based on a frame count
- */
-void wait_for_frames(size_t frames)
-{
-	usleep((1000* frames/output.current_sample_rate*.90) );
-}
+
 
 /****************************************************************************************
  * Main output thread
@@ -393,7 +406,7 @@ static void *output_thread() {
 		/*
 		 * End Statistics reporting
 		 */
-		wait_for_frames(BYTES_TO_FRAME(i2s_bytes_written));
+		wait_for_frames(BYTES_TO_FRAME(i2s_bytes_written),75);
 	}
 
 

main/perf_trace.h

@@ -1,16 +1,21 @@
 
 #pragma once
 #define FRAMES_TO_MS(f) output.current_sample_rate>0?1000*f/output.current_sample_rate:LONG_MIN
+#ifdef BYTES_TO_FRAME
 #define BYTES_TO_MS(b) FRAMES_TO_MS(BYTES_TO_FRAME(b))
-#define LINE_MIN_MAX_FORMAT          "%14s%10d|%10d|%11d|"                 "  |%10d|%10d|%16d|"
-#define LINE_MIN_MAX_DURATION_FORMAT "%14s%10d|%10d|%11d|"
-#define LINE_MIN_MAX_FORMAT_STREAM   "%14s%10s|%10s|%11s|"                 "  |%10d|%10d|%16d|"
-#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 LINE_MIN_MAX(name,var) name,BYTES_TO_MS(max_##var), BYTES_TO_MS(min_##var),BYTES_TO_MS( var),max_##var,min_##var,var
-#define LINE_MIN_MAX_STREAM(name,var) name,"n/a","n/a","n/a",max_##var,min_##var,var
-#define LINE_MIN_MAX_DURATION(name,var) name,max_##var, min_##var, var
+#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 TIME_MEASUREMENT_START(x) x=esp_timer_get_time()
 #define TIME_MEASUREMENT_GET(x) (esp_timer_get_time()-x)/1000

main/slimproto.c

@@ -436,8 +436,13 @@ static void process_audg(u8_t *pkt, int len) {
 	audg->gainR = unpackN(&audg->gainR);
 
 	LOG_DEBUG("audg gainL: %u gainR: %u adjust: %u", audg->gainL, audg->gainR, audg->adjust);
-
+#if CONFIG_BTAUDIO
+	set_volume_bt(audg->adjust ? audg->gainL : FIXED_ONE, audg->adjust ? audg->gainR : FIXED_ONE);
+#elif CONFIG_DACAUDIO
+	set_volume_dac(audg->adjust ? audg->gainL : FIXED_ONE, audg->adjust ? audg->gainR : FIXED_ONE);
+#else
 	set_volume(audg->adjust ? audg->gainL : FIXED_ONE, audg->adjust ? audg->gainR : FIXED_ONE);
+#endif
 }
 
 static void process_setd(u8_t *pkt, int len) {

main/squeezelite.h

@@ -751,7 +751,7 @@ void _pa_open(void);
 
 // output_dac.c
 #if CONFIG_DACAUDIO
-void set_volume(unsigned left, unsigned right);
+void set_volume_dac(unsigned left, unsigned right);
 bool test_open(const char *device, unsigned rates[], bool userdef_rates);
 void output_init_dac(log_level level, char *device, unsigned output_buf_size, char *params, unsigned rates[], unsigned rate_delay, unsigned idle);
 void output_close_dac(void);
@@ -760,7 +760,7 @@ void hal_bluetooth_init(log_level loglevel);
 
 //output_bt.c
 #if  CONFIG_BTAUDIO
-void set_volume(unsigned left, unsigned right);
+void set_volume_bt(unsigned left, unsigned right);
 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);

main/utils.c

@@ -615,3 +615,11 @@ uint8_t get_bytes_per_frame(output_format fmt)
 	assert(bpf>0);
 	return bpf;
 }
+/****************************************************************************************
+ * Wait for a duration based on a frame count
+ */
+extern struct outputstate output;
+void wait_for_frames(size_t frames, uint8_t pct)
+{
+	usleep((1000* frames/output.current_sample_rate*pct/100) );
+}