From 142761eba37d2389d54a20ffdf8b0f68791afe00 Mon Sep 17 00:00:00 2001 From: Sebastien Leclerc Date: Thu, 6 Jun 2019 21:55:22 -0400 Subject: [PATCH] BT ring buffering --- main/Kconfig.projbuild | 9 +- main/esp32.c | 714 ++++++++++++++++++++++------------------- main/main.c | 2 +- main/output_bt.c | 173 +++++++++- main/output_dac.c | 35 +- main/perf_trace.h | 23 +- main/slimproto.c | 7 +- main/squeezelite.h | 4 +- main/utils.c | 8 + 9 files changed, 605 insertions(+), 370 deletions(-) diff --git a/main/Kconfig.projbuild b/main/Kconfig.projbuild index 1b824452..e85d8278 100644 --- a/main/Kconfig.projbuild +++ b/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 diff --git a/main/esp32.c b/main/esp32.c index 3c41a617..6f41bbd8 100644 --- a/main/esp32.c +++ b/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(varmax_##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(varmax_##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) +static void bt_app_av_media_proc(uint16_t event, void *param) { - bt_app_work_dispatch(bt_app_av_sm_hdlr, BT_APP_HEART_BEAT_EVT, NULL, 0, NULL); -} + 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_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! -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_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); + // 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_UNCONNECTED: - bt_app_av_state_unconnected(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; - 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); + } + 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; diff --git a/main/main.c b/main/main.c index 2ae6f3bc..293b9b49 100644 --- a/main/main.c +++ b/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, "-")) { diff --git a/main/output_bt.c b/main/output_bt.c index e96e25a7..37da605c 100644 --- a/main/output_bt.c +++ b/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; } diff --git a/main/output_dac.c b/main/output_dac.c index 2fe277e8..927d64cc 100644 --- a/main/output_dac.c +++ b/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); } diff --git a/main/perf_trace.h b/main/perf_trace.h index cf3a0052..898cc82e 100644 --- a/main/perf_trace.h +++ b/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(varmax_##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(varmax_##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 diff --git a/main/slimproto.c b/main/slimproto.c index ec53d283..e7b9cc4c 100644 --- a/main/slimproto.c +++ b/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) { diff --git a/main/squeezelite.h b/main/squeezelite.h index 61f96eaf..54495cda 100644 --- a/main/squeezelite.h +++ b/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); diff --git a/main/utils.c b/main/utils.c index c5f7f58a..be10c379 100644 --- a/main/utils.c +++ b/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) ); +}