diff --git a/main/bt_app_core.c b/main/bt_app_core.c index 490274ca..924fa719 100644 --- a/main/bt_app_core.c +++ b/main/bt_app_core.c @@ -97,13 +97,18 @@ static void bt_app_task_handler(void *arg) free(msg.param); } } + else + { + LOG_DEBUG("No messaged received from queue."); + } } } void bt_app_task_start_up(void) { s_bt_app_task_queue = xQueueCreate(10, sizeof(bt_app_msg_t)); - xTaskCreate(bt_app_task_handler, "BtAppT", 2048, NULL, configMAX_PRIORITIES - 3, &s_bt_app_task_handle); + assert(s_bt_app_task_queue!=NULL); + assert(xTaskCreate(bt_app_task_handler, "BtAppT", 2048, NULL, configMAX_PRIORITIES - 3, &s_bt_app_task_handle)==pdPASS); return; } diff --git a/main/decode.c b/main/decode.c index 43e35c07..84cc4a45 100644 --- a/main/decode.c +++ b/main/decode.c @@ -199,7 +199,7 @@ void decode_init(log_level level, const char *include_codecs, const char *exclud LOG_DEBUG("include codecs: %s exclude codecs: %s", include_codecs ? include_codecs : "", exclude_codecs); mutex_create(decode.mutex); - + PTHREAD_SET_NAME("decode"); #if LINUX || OSX || FREEBSD || POSIX pthread_attr_t attr; pthread_attr_init(&attr); diff --git a/main/embedded.h b/main/embedded.h index 8975304b..84e060ac 100644 --- a/main/embedded.h +++ b/main/embedded.h @@ -1,4 +1,6 @@ #pragma once #if defined(ESP_PLATFORM) #include "sdkconfig.h" +#include "esp_pthread.h" +#define PTHREAD_SET_NAME(n) { esp_pthread_cfg_t cfg = esp_pthread_get_default_config(); cfg.thread_name= n; cfg.inherit_cfg = true; esp_pthread_set_cfg(&cfg); } #endif diff --git a/main/esp32.c b/main/esp32.c index 6f41bbd8..f22a4a87 100644 --- a/main/esp32.c +++ b/main/esp32.c @@ -27,19 +27,63 @@ #include "esp_avrc_api.h" #include "esp_pthread.h" #include "pthread.h" + +const char * art_a2dp_connected[]={"\n\n", + " ___ _____ _____ _____ _ _ _ \n", + " /\\ |__ \\| __ \\| __ \\ / ____| | | | | |\n", + " / \\ ) | | | | |__) | | | ___ _ __ _ __ ___ ___| |_ ___ __| | |\n", + " / /\\ \\ / /| | | | ___/ | | / _ \\| '_ \\| '_ \\ / _ \\/ __| __/ _ \\/ _` | |\n", + " / ____ \\ / /_| |__| | | | |___| (_) | | | | | | | __/ (__| || __/ (_| |_|\n", + " /_/ \\_\\____|_____/|_| \\_____\\___/|_| |_|_| |_|\\___|\\___|\\__\\___|\\__,_(_)\n\n", + "\0"}; +const char * art_a2dp_connecting[]= {"\n\n", + " ___ _____ _____ _____ _ _ \n", + " /\\ |__ \\| __ \\| __ \\ / ____| | | (_) \n", + " / \\ ) | | | | |__) | | | ___ _ __ _ __ ___ ___| |_ _ _ __ __ _ \n", + " / /\\ \\ / /| | | | ___/ | | / _ \\| '_ \\| '_ \\ / _ \\/ __| __| | '_ \\ / _` | \n", + " / ____ \\ / /_| |__| | | | |___| (_) | | | | | | | __/ (__| |_| | | | | (_| |_ _ _ \n", + " /_/ \\_\\____|_____/|_| \\_____\\___/|_| |_|_| |_|\\___|\\___|\\__|_|_| |_|\\__, (_|_|_)\n", + " __/ | \n", + " |___/ \n\n", + "\0"}; + +char * get_output_state_desc(output_state state){ + switch (state) { + case OUTPUT_OFF: + return STR(OUTPUT_OFF); + case OUTPUT_STOPPED: + return STR(OUTPUT_STOPPED); + case OUTPUT_BUFFER: + return STR(OUTPUT_BUFFER); + case OUTPUT_RUNNING: + return STR(OUTPUT_RUNNING); + case OUTPUT_PAUSE_FRAMES: + return STR(OUTPUT_PAUSE_FRAMES); + case OUTPUT_SKIP_FRAMES: + return STR(OUTPUT_SKIP_FRAMES); + case OUTPUT_START_AT: + return STR(OUTPUT_START_AT); + default: + return "OUTPUT_UNKNOWN_STATE"; + } + return ""; +} #define BT_AV_TAG "BT_AV" extern log_level loglevel; extern struct outputstate output; extern struct buffer *outputbuf; -extern struct buffer *streambuf; +#ifdef USE_BT_RING_BUFFER +#define LOCK_BT mutex_lock(btbuf->mutex) +#define UNLOCK_BT mutex_unlock(btbuf->mutex) extern struct buffer *btbuf; - +#else +extern uint8_t * btout; +#endif time_t disconnect_time=0; #define LOCK mutex_lock(outputbuf->mutex) #define UNLOCK mutex_unlock(outputbuf->mutex) -#define LOCK_BT mutex_lock(btbuf->mutex) -#define UNLOCK_BT mutex_unlock(btbuf->mutex) int64_t connecting_timeout = 0; + #ifndef CONFIG_A2DP_SINK_NAME #define CONFIG_A2DP_SINK_NAME "btspeaker" // fix some compile errors when BT is not chosen #endif @@ -52,19 +96,24 @@ int64_t connecting_timeout = 0; #ifndef CONFIG_A2DP_CONTROL_DELAY_MS #define CONFIG_A2DP_CONTROL_DELAY_MS 1000 #endif + +static void bt_app_av_state_connecting(uint16_t event, void *param); + #define A2DP_TIMER_INIT connecting_timeout = esp_timer_get_time() +(CONFIG_A2DP_CONNECT_TIMEOUT_MS * 1000) #define IS_A2DP_TIMER_OVER esp_timer_get_time() >= connecting_timeout #define FRAME_TO_BYTES(f) f*BYTES_PER_FRAME #define BYTES_TO_FRAME(b) b/BYTES_PER_FRAME -#define FRAMES_TO_MS(f) 1000*f/output.current_sample_rate -#define BYTES_TO_MS(b) FRAMES_TO_MS(BYTES_TO_FRAME(b)) -//#define SET_MIN_MAX(val,var) var=val; if(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); + +#define RESET_ALL_MIN_MAX RESET_MIN_MAX(req); RESET_MIN_MAX(rec); RESET_MIN_MAX(bt);RESET_MIN_MAX_DURATION(lock_bt_time);RESET_MIN_MAX(under); RESET_MIN_MAX_DURATION(lock_out_time) + +DECLARE_MIN_MAX(req); +DECLARE_MIN_MAX(rec); +DECLARE_MIN_MAX(bt); +DECLARE_MIN_MAX_DURATION(lock_bt_time); +DECLARE_MIN_MAX(under); +DECLARE_MIN_MAX_DURATION(lock_out_time); static void filter_inquiry_scan_result(esp_bt_gap_cb_param_t *param); @@ -186,7 +235,6 @@ static esp_bd_addr_t s_peer_bda = {0}; static uint8_t s_peer_bdname[ESP_BT_GAP_MAX_BDNAME_LEN + 1]; static int s_a2d_state = APP_AV_STATE_IDLE; static int s_media_state = APP_AV_MEDIA_STATE_IDLE; -static int s_intv_cnt = 0; static uint32_t s_pkt_cnt = 0; static TimerHandle_t s_tmr; @@ -198,6 +246,7 @@ void hal_bluetooth_init(log_level level) * Bluetooth audio source init Start */ loglevel = level; + bt_set_log_level(level); //running_test = false; ESP_ERROR_CHECK(esp_bt_controller_mem_release(ESP_BT_MODE_BLE)); @@ -244,27 +293,23 @@ void hal_bluetooth_init(log_level level) esp_bt_gap_set_pin(pin_type, 0, pin_code); } -DECLARE_ALL_MIN_MAX ; - static int32_t bt_app_a2d_data_cb(uint8_t *data, int32_t len) { - static int count = 0; - unsigned avail_data=0,wanted_len=0; +#ifdef USE_BT_RING_BUFFER + int32_t avail_data=0,wanted_len=0, start_timer=0; if (len < 0 || data == NULL ) { return 0; } - // // This is how the BTC layer calculates the number of bytes to // for us to send. (BTC_SBC_DEC_PCM_DATA_LEN * sizeof(OI_INT16) - availPcmBytes - wanted_len=len; - - SET_MIN_MAX(len/BYTES_PER_FRAME,req); + TIME_MEASUREMENT_START(start_timer); + SET_MIN_MAX(len,req); LOCK_BT; - SET_MIN_MAX(_buf_used(btbuf)/BYTES_PER_FRAME,bt); + SET_MIN_MAX_SIZED(_buf_used(btbuf),bt,btbuf->size); do { avail_data=min(_buf_cont_read(btbuf),wanted_len); @@ -275,54 +320,57 @@ static int32_t bt_app_a2d_data_cb(uint8_t *data, int32_t len) data+=avail_data; } else { - // SET_MIN_MAX(wanted_len, under); - //LOG_WARN("BT Buffering underrun! %7d bytes Requested, %7d bytes missing.", len,wanted_len); -// LOG_INFO( "count:%d, current sample rate: %d",count,output.current_sample_rate); -// LOG_INFO( " ----------+----------+-----------+ +----------+----------+----------------+"); -// LOG_INFO( " max | min | current| | max | min | current |"); -// LOG_INFO( " (ms) | (ms) | (ms)| | (bytes) | (bytes) | (bytes) |"); -// LOG_INFO( " ----------+----------+-----------+ +----------+----------+----------------+"); -// LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req)); -// LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec)); -// LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("available",bt)); -// LOG_INFO(" ----------+----------+-----------+ +----------+----------+----------------+"); - // LOG_INFO(""); - // LOG_INFO(" max (us) | min (us) |current(us)| "); - // LOG_INFO(" ----------+----------+-----------+ "); - // LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Buffering(us)",buffering)); - // LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("i2s tfr(us)",i2s_time)); - // LOG_INFO(" ----------+----------+-----------+ "); - - RESET_ALL_MIN_MAX; + assert(wanted_len>0); + assert(avail_data==0); + SET_MIN_MAX(wanted_len, under); } } while (wanted_len > 0 && avail_data != 0); - UNLOCK_BT; - SET_MIN_MAX((len-wanted_len)/BYTES_PER_FRAME, rec); - SET_MIN_MAX(wanted_len/BYTES_PER_FRAME, under); - SET_MIN_MAX(_buf_used(outputbuf)/BYTES_PER_FRAME,o); - 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; -} + UNLOCK_BT; + SET_MIN_MAX(TIME_MEASUREMENT_GET(start_timer),lock_bt_time); + SET_MIN_MAX((len-wanted_len), rec); + TIME_MEASUREMENT_START(start_timer); + output_bt_check_buffer(); + SET_MIN_MAX(TIME_MEASUREMENT_GET(start_timer),lock_out_time); + return len-wanted_len; + +#else + int32_t avail_data=0,wanted_len=0, start_timer=0; + + if (len < 0 || data == NULL ) { + return 0; + } + btout=data; + + // This is how the BTC layer calculates the number of bytes to + // for us to send. (BTC_SBC_DEC_PCM_DATA_LEN * sizeof(OI_INT16) - availPcmBytes + wanted_len=len; + SET_MIN_MAX(len,req); + TIME_MEASUREMENT_START(start_timer); + LOCK; + SET_MIN_MAX_SIZED(_buf_used(outputbuf),bt,outputbuf->size); + do { + + avail_data = _output_frames( wanted_len/BYTES_PER_FRAME )*BYTES_PER_FRAME; // Keep the transfer buffer full + wanted_len-=avail_data; + } while (wanted_len > 0 && avail_data != 0); + if(wanted_len>0) + { + SET_MIN_MAX(wanted_len, under); + } + output.device_frames = 0; // todo: check if this is the right way do to this. + output.updated = gettime_ms(); + output.frames_played_dmp = output.frames_played; + UNLOCK; + SET_MIN_MAX(TIME_MEASUREMENT_GET(start_timer),lock_out_time); + SET_MIN_MAX((len-wanted_len), rec); + TIME_MEASUREMENT_START(start_timer); + output_bt_check_buffer(); + + return len-wanted_len; + +#endif +} static void bt_app_a2d_cb(esp_a2d_cb_event_t event, esp_a2d_cb_param_t *param) { bt_app_work_dispatch(bt_app_av_sm_hdlr, event, param, sizeof(esp_a2d_cb_param_t), NULL); @@ -423,10 +471,10 @@ static void bt_app_av_sm_hdlr(uint16_t event, void *param) //LOG_DEBUG("%s state %s, evt 0x%x, output state: %d", __func__, APP_AV_STATE_DESC[s_a2d_state], event, output.state); switch (s_a2d_state) { case APP_AV_STATE_DISCOVERING: - LOG_SDEBUG("state %s, evt 0x%x, output state: %d", APP_AV_STATE_DESC[s_a2d_state], event, output.state); + LOG_SDEBUG("state %s, evt 0x%x, output state: %s", APP_AV_STATE_DESC[s_a2d_state], event, get_output_state_desc(output.state)); break; case APP_AV_STATE_DISCOVERED: - LOG_SDEBUG("state %s, evt 0x%x, output state: %d", APP_AV_STATE_DESC[s_a2d_state], event, output.state); + LOG_SDEBUG("state %s, evt 0x%x, output state: %s", APP_AV_STATE_DESC[s_a2d_state], event, get_output_state_desc(output.state)); break; case APP_AV_STATE_UNCONNECTED: bt_app_av_state_unconnected(event, param); @@ -633,16 +681,22 @@ static void bt_app_av_media_proc(uint16_t event, void *param) esp_a2d_cb_param_t *a2d = NULL; LOCK; output_state out_state=output.state; + unsigned start_frames = output.start_frames; UNLOCK; - unsigned bt_buffer_used=_buf_used(btbuf); +#ifdef USE_BT_RING_BUFFER + LOCK_BT; + unsigned bt_buffer_used=_buf_used(btbuf); + UNLOCK_BT; +#endif switch (s_media_state) { case APP_AV_MEDIA_STATE_IDLE: { if (event == BT_APP_HEART_BEAT_EVT) { - if(out_state > OUTPUT_STOPPED) + if(out_state > OUTPUT_OFF) { - LOG_INFO("buffering output, a2dp media ready and connected. Starting checking if ready..."); + LOG_INFO("Output state is %s, a2dp media ready and connected. Checking if A2DP is ready.", get_output_state_desc(out_state)); esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_CHECK_SRC_RDY); } + } else if (event == ESP_A2D_MEDIA_CTRL_ACK_EVT) { a2d = (esp_a2d_cb_param_t *)(param); if (a2d->media_ctrl_stat.cmd == ESP_A2D_MEDIA_CTRL_CHECK_SRC_RDY && @@ -656,21 +710,39 @@ static void bt_app_av_media_proc(uint16_t event, void *param) } case APP_AV_MEDIA_STATE_BUFFERING: { if (event == BT_APP_HEART_BEAT_EVT) { - if(out_state > OUTPUT_BUFFER ){ - // Buffer is ready, local buffer has some data, start playback! + switch (out_state) { + case OUTPUT_RUNNING : + case OUTPUT_PAUSE_FRAMES : + case OUTPUT_SKIP_FRAMES: + case OUTPUT_START_AT: +#ifndef USE_BT_RING_BUFFER + case OUTPUT_BUFFER: +#endif + // Buffer is ready, local buffer has some data, start playback! + LOG_INFO("Buffering complete, out state is %s, a2dp media ready and connected. Starting playback! ", get_output_state_desc(out_state)); + s_media_state = APP_AV_MEDIA_STATE_STARTING; + esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_START); +#ifdef USE_BT_RING_BUFFER + break; - // 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); - } + case OUTPUT_BUFFER: + LOG_DEBUG("Buffering... BT Buffer: %d bytes. Start threshold: %u, ",bt_buffer_used, start_frames*BYTES_PER_FRAME); +#endif + break; + case OUTPUT_STOPPED: + case OUTPUT_OFF: + LOG_DEBUG("Output state is %s. Changing app status to ",get_output_state_desc(out_state)); + s_media_state = APP_AV_MEDIA_STATE_STOPPING; + esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_STOP); +#ifdef USE_BT_RING_BUFFER + output_bt_check_buffer(); +#endif + break; + default: + LOG_ERROR("Unknown output status while waiting for buffering to complete %d",out_state); + break; + } } else{ LOG_WARN("Received unknown event while in state APP_AV_MEDIA_STATE_BUFFERING"); @@ -686,7 +758,6 @@ static void bt_app_av_media_proc(uint16_t event, void *param) if (a2d->media_ctrl_stat.cmd == ESP_A2D_MEDIA_CTRL_START && a2d->media_ctrl_stat.status == ESP_A2D_MEDIA_CTRL_ACK_SUCCESS) { LOG_INFO("a2dp media started successfully."); - s_intv_cnt = 0; s_media_state = APP_AV_MEDIA_STATE_STARTED; } else { // not started succesfully, transfer to idle state @@ -702,25 +773,32 @@ static void bt_app_av_media_proc(uint16_t event, void *param) LOG_INFO("Output state is stopped. Stopping a2dp media ..."); s_media_state = APP_AV_MEDIA_STATE_STOPPING; esp_a2d_media_ctrl(ESP_A2D_MEDIA_CTRL_STOP); - s_intv_cnt = 0; +#ifdef USE_BT_RING_BUFFER + output_bt_check_buffer(); +#endif } else { static time_t lastTime=0; if (lastTime <= gettime_ms() ) { - lastTime = gettime_ms() + 5000; - //LOG_INFO( "count:%d, current sample rate: %d, bytes per frame: %d",count,output.current_sample_rate); - LOG_INFO( " **********+**********+***********+***********+ +**********+**********+****************+****************+****************+"); - LOG_INFO( " max | min | avg | current| | max | min | average | count | current |"); - LOG_INFO( " (ms) | (ms) | (ms)| (ms) | | (bytes) | (bytes) | (bytes) | | (bytes) |"); - LOG_INFO( " **********+**********+***********+***********+ +**********+**********+****************+****************+****************+"); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("output",o)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("available",bt)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("underrun",under)); - LOG_INFO(" **********+**********+***********+***********+ +**********+**********+****************+****************+****************+"); + lastTime = gettime_ms() + 15000; + LOG_DEBUG( " +==========+==========+================+=====+================+"); + LOG_DEBUG( " | max | min | average | avg | count |"); + LOG_DEBUG( " | (bytes) | (bytes) | (bytes) | pct | |"); + LOG_DEBUG( " +==========+==========+================+=====+================+"); + LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("available",bt)); + LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req)); + LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec)); + LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("underrun",under)); + LOG_DEBUG( " +==========+==========+================+=====+================+"); + LOG_DEBUG("\n"); + LOG_DEBUG(" ==========+==========+===========+===========+ "); + LOG_DEBUG(" max (us) | min (us) | avg(us) | count | "); + LOG_DEBUG(" ==========+==========+===========+===========+ "); + LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("BT Buf Lock",lock_bt_time)); + LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Out Buf Lock",lock_out_time)); + LOG_DEBUG(" ==========+==========+===========+===========+"); RESET_ALL_MIN_MAX; } @@ -771,9 +849,18 @@ static void bt_app_av_state_unconnected(uint16_t event, void *param) switch (event) { case ESP_A2D_CONNECTION_STATE_EVT: LOG_DEBUG_EVENT(ESP_A2D_CONNECTION_STATE_EVT); + // this could happen if connection was established + // right after we timed out. Pass the call down to the connecting + // handler. + esp_a2d_cb_param_t *a2d = (esp_a2d_cb_param_t *)(param); + if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED){ + bt_app_av_state_connecting(event, param); + } + break; case ESP_A2D_AUDIO_STATE_EVT: LOG_DEBUG_EVENT(ESP_A2D_AUDIO_STATE_EVT); + break; case ESP_A2D_AUDIO_CFG_EVT: LOG_DEBUG_EVENT(ESP_A2D_AUDIO_CFG_EVT); @@ -794,16 +881,17 @@ static void bt_app_av_state_unconnected(uint16_t event, void *param) case ESP_BLUEDROID_STATUS_ENABLED: LOG_SDEBUG("BlueDroid Status is ESP_BLUEDROID_STATUS_ENABLED."); break; - default: - break; + default: + break; } // if(out_state > OUTPUT_STOPPED){ // only attempt a connect when playback isn't stopped - if(esp_a2d_source_connect(s_peer_bda)!=ESP_ERR_INVALID_STATE) { + if(esp_a2d_source_connect(s_peer_bda)==ESP_OK) { s_a2d_state = APP_AV_STATE_CONNECTING; - //esp_bt_gap_set_scan_mode(ESP_BT_CONNECTABLE, ESP_BT_GENERAL_DISCOVERABLE); - //LOG_INFO("squeezelite playback resumed. connecting to A2DP peer: %s", s_peer_bdname); - LOG_INFO("connecting to A2DP peer: %s", s_peer_bdname); + for(uint8_t l=0;art_a2dp_connecting[l][0]!='\0';l++){ + LOG_INFO_NO_LF("%s",art_a2dp_connecting[l]); + } + LOG_INFO("********** A2DP CONNECTING TO %s", s_peer_bdname); A2DP_TIMER_INIT; } else { @@ -830,8 +918,12 @@ static void bt_app_av_state_connecting(uint16_t event, void *param) if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED) { s_a2d_state = APP_AV_STATE_CONNECTED; s_media_state = APP_AV_MEDIA_STATE_IDLE; - LOG_INFO("a2dp connected! Setting BT mode to non_connectable and non_discoverable. "); + for(uint8_t l=0;art_a2dp_connected[l][0]!='\0';l++){ + LOG_INFO_NO_LF("%s",art_a2dp_connected[l]); + } + LOG_DEBUG("Setting scan mode to ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE"); esp_bt_gap_set_scan_mode(ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE); + LOG_DEBUG("Done setting scan mode. App state is now CONNECTED and media state IDLE."); } else if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_DISCONNECTED) { s_a2d_state = APP_AV_STATE_UNCONNECTED; } @@ -888,7 +980,7 @@ static void bt_app_av_state_connected(uint16_t event, void *param) LOG_DEBUG_EVENT(ESP_A2D_AUDIO_CFG_EVT); break; case ESP_A2D_MEDIA_CTRL_ACK_EVT:{ - LOG_DEBUG_EVENT(ESP_A2D_MEDIA_CTRL_ACK_EVT); + LOG_SDEBUG_EVENT(ESP_A2D_MEDIA_CTRL_ACK_EVT); bt_app_av_media_proc(event, param); break; } diff --git a/main/esp_app_main.c b/main/esp_app_main.c index 61aca767..bf0f1cb4 100644 --- a/main/esp_app_main.c +++ b/main/esp_app_main.c @@ -30,6 +30,47 @@ #include "nvs_flash.h" #include "sys/socket.h" #include "string.h" +thread_cond_type wifi_connect_suspend_cond; +mutex_type wifi_connect_suspend_mutex; +char * art_wifi[]={ + "\n", + "o `O ooOoOOo OOooOoO ooOoOOo\n", + "O o O o O \n", + "o O o O o \n", + "O O O oOooO O \n", + "o o o o O o \n", + "O O O O o O \n", + "`o O o O' O o O \n", + " `OoO' `OoO' ooOOoOo O' ooOOoOo\n", + "\n", + "" +}; +char * art_wifi_connecting[]={ + " .oOOOo.", + ".O o o \n", + "o O \n", + "o oOo \n", + "o .oOo. 'OoOo. 'OoOo. .oOo. .oOo o O 'OoOo. .oOoO \n", + "O O o o O o O OooO' O O o o O o O \n", + "`o .o o O O o O o O o o O O o O o \n", + " `OoooO' `OoO' o O o O `OoO' `OoO' `oO o' o O `OoOo \n", + " O \n", + " OoO' \n", + "\n", + "" +}; +char * art_wifi_connected[]={ + " .oOOOo. o oO\n", + ".O o O OO\n", + "o O o oO\n", + "o oOo o Oo\n", + "o .oOo. 'OoOo. 'OoOo. .oOo. .oOo o .oOo. .oOoO oO\n", + "O O o o O o O OooO' O O OooO' o O \n", + "`o .o o O O o O o O o o O O o Oo\n", + " `OoooO' `OoO' o O o O `OoO' `OoO' `oO `OoO' `OoO'o oO\n", + "\n", + "" +}; /*Set the SSID and Password via "make menuconfig"*/ #define DEFAULT_SSID CONFIG_WIFI_SSID @@ -80,7 +121,13 @@ static void event_handler(void* arg, esp_event_base_t event_base, esp_wifi_connect(); } else if (event_base == IP_EVENT && event_id == IP_EVENT_STA_GOT_IP) { ip_event_got_ip_t* event = (ip_event_got_ip_t*) event_data; - ESP_LOGI(TAG, "got ip: %s", ip4addr_ntoa(&event->ip_info.ip)); + ESP_LOGI(TAG, "got ip: %s.", ip4addr_ntoa(&event->ip_info.ip)); + logprint("Signaling wifi connected. Locking.\n"); + mutex_lock(wifi_connect_suspend_mutex); + logprint("Signaling wifi connected. Broadcasting.\n"); + mutex_broadcast_cond(wifi_connect_suspend_cond); + logprint("Signaling wifi connected. Unlocking.\n"); + mutex_unlock(wifi_connect_suspend_mutex); } } @@ -88,6 +135,12 @@ static void event_handler(void* arg, esp_event_base_t event_base, /* Initialize Wi-Fi as sta and set scan method */ static void wifi_scan(void) { + for(uint8_t l=0;art_wifi[l][0]!='\0';l++){ + logprint("%s",art_wifi[l]); + } + for(uint8_t l=0;art_wifi_connecting[l][0]!='\0';l++){ + logprint("%s",art_wifi_connecting[l]); + } tcpip_adapter_init(); ESP_ERROR_CHECK(esp_event_loop_create_default()); @@ -143,18 +196,13 @@ void app_main() }; + // can't do strtok on FLASH strings argv = malloc(sizeof(_argv)); for (i = 0; i < sizeof(_argv)/sizeof(char*); i++) { argv[i] = strdup(_argv[i]); } - logprint("%s %s:%d Calling main with parameters: " , logtime(), __FUNCTION__, __LINE__); - - for (i = 0; i < sizeof(_argv)/sizeof(char*); i++) { - logprint("%s " , _argv[i]); - } - logprint("\n"); // Initialize NVS esp_err_t ret = nvs_flash_init(); @@ -163,8 +211,30 @@ void app_main() ret = nvs_flash_init(); } ESP_ERROR_CHECK( ret ); - + + mutex_create_p(wifi_connect_suspend_mutex); + mutex_cond_init(wifi_connect_suspend_cond); + + logprint("Starting WiFi.\n"); wifi_scan(); - + logprint("Waiting for WiFi to connect. Locking Mutex.\n"); + mutex_lock(wifi_connect_suspend_mutex); + logprint("Waiting for WiFi to connect. cond_wait.\n"); + pthread_cond_wait(&wifi_connect_suspend_cond,&wifi_connect_suspend_mutex); + logprint("Waiting for WiFi to connect. Unlocking Mutex.\n"); + mutex_unlock(wifi_connect_suspend_mutex); + for(uint8_t l=0;art_wifi[l][0]!='\0';l++){ + logprint("%s",art_wifi[l]); + } + for(uint8_t l=0;art_wifi_connected[l][0]!='\0';l++){ + logprint("%s",art_wifi_connected[l]); + } + logprint("%s %s:%d Calling main with parameters: " , logtime(), __FUNCTION__, __LINE__); + + for (i = 0; i < sizeof(_argv)/sizeof(char*); i++) { + logprint("%s " , _argv[i]); + } + logprint("\n"); + main(sizeof(_argv)/sizeof(char*), argv); } diff --git a/main/output_bt.c b/main/output_bt.c index 37da605c..5b391546 100644 --- a/main/output_bt.c +++ b/main/output_bt.c @@ -8,50 +8,57 @@ static bool running = true; extern struct outputstate output; extern struct buffer *outputbuf; extern struct buffer *streambuf; -size_t bt_buffer_size=0; - -static struct buffer bt_buf_structure; -struct buffer *btbuf=&bt_buf_structure; #define LOCK mutex_lock(outputbuf->mutex) #define UNLOCK mutex_unlock(outputbuf->mutex) + +#ifdef USE_BT_RING_BUFFER +size_t bt_buffer_size=0; +uint8_t bt_buf_used_threshold = 25; +uint16_t output_bt_thread_heartbeat_ms=1000; +thread_type thread_bt; #define LOCK_BT mutex_lock(btbuf->mutex) #define UNLOCK_BT mutex_unlock(btbuf->mutex) +thread_cond_type output_bt_suspend_cond; +mutex_type output_bt_suspend_mutex; +static struct buffer bt_buf_structure; +struct buffer *btbuf=&bt_buf_structure; +static void *output_thread_bt(); +extern void wait_for_frames(size_t frames, uint8_t pct); +#else +uint8_t * btout; +#endif #define FRAME_BLOCK MAX_SILENCE_FRAMES -#define BUFFERING_FRAME_BLOCK FRAME_BLOCK*2 - extern u8_t *silencebuf; void hal_bluetooth_init(log_level); -static void *output_thread_bt(); + static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t gainR, s32_t cross_gain_in, s32_t cross_gain_out, ISAMPLE_T **cross_ptr); -extern void wait_for_frames(size_t frames, uint8_t pct); - #define DECLARE_ALL_MIN_MAX \ - DECLARE_MIN_MAX(req, long,LONG); \ - DECLARE_MIN_MAX(rec, long,LONG); \ - DECLARE_MIN_MAX(o, long,LONG); \ - DECLARE_MIN_MAX(s, long,LONG); \ - DECLARE_MIN_MAX(d, long,LONG); \ - DECLARE_MIN_MAX(locbtbuff, long,LONG); \ - DECLARE_MIN_MAX(mutex1, long,LONG); \ - DECLARE_MIN_MAX(mutex2, long,LONG); \ - DECLARE_MIN_MAX(total, long,LONG); \ -DECLARE_MIN_MAX(buffering, long,LONG); + DECLARE_MIN_MAX(req);\ + DECLARE_MIN_MAX(rec);\ + DECLARE_MIN_MAX(o);\ + DECLARE_MIN_MAX(s);\ + DECLARE_MIN_MAX(locbtbuff);\ + DECLARE_MIN_MAX(under);\ + DECLARE_MIN_MAX_DURATION(mutex1);\ + DECLARE_MIN_MAX_DURATION(mutex2);\ + DECLARE_MIN_MAX_DURATION(buffering);\ + DECLARE_MIN_MAX_DURATION(sleep_time); #define RESET_ALL_MIN_MAX \ - RESET_MIN_MAX(d,LONG); \ - RESET_MIN_MAX(o,LONG); \ - RESET_MIN_MAX(s,LONG); \ - RESET_MIN_MAX(locbtbuff, LONG); \ - RESET_MIN_MAX(req,LONG); \ - RESET_MIN_MAX(rec,LONG); \ - RESET_MIN_MAX(mutex1,LONG); \ - RESET_MIN_MAX(mutex2,LONG); \ - RESET_MIN_MAX(total,LONG); \ - RESET_MIN_MAX(buffering,LONG); + RESET_MIN_MAX(o); \ + RESET_MIN_MAX(s); \ + RESET_MIN_MAX(locbtbuff); \ + RESET_MIN_MAX(req); \ + RESET_MIN_MAX(rec); \ + RESET_MIN_MAX(under); \ + RESET_MIN_MAX_DURATION(mutex1); \ + RESET_MIN_MAX_DURATION(mutex2); \ + RESET_MIN_MAX_DURATION(sleep_time); \ + RESET_MIN_MAX_DURATION(buffering); #if CONFIG_BTAUDIO @@ -64,7 +71,58 @@ void set_volume_bt(unsigned left, unsigned right) { } #endif -static thread_type thread_bt; + + +void output_bt_check_buffer() +{ +#ifdef USE_BT_RING_BUFFER + LOCK_BT; + uint8_t tot_buf_used_pct=100*_buf_used(btbuf)/btbuf->size; + UNLOCK_BT; + if(tot_buf_used_pctbuf) { LOG_ERROR("unable to malloc BT buffer"); exit(0); } - + mutex_create_p(output_bt_suspend_mutex); + mutex_cond_init(output_bt_suspend_cond); + PTHREAD_SET_NAME("output_bt"); #if LINUX || OSX || FREEBSD || POSIX pthread_attr_t attr; @@ -102,11 +157,18 @@ void output_init_bt(log_level level, char *device, unsigned output_buf_size, cha #ifdef PTHREAD_STACK_MIN pthread_attr_setstacksize(&attr, PTHREAD_STACK_MIN + OUTPUT_THREAD_STACK_SIZE); #endif + pthread_create(&thread_bt, &attr, output_thread_bt, NULL); - pthread_attr_destroy(&attr); #endif + pthread_attr_destroy(&attr); + #if WIN thread = CreateThread(NULL, OUTPUT_THREAD_STACK_SIZE, (LPTHREAD_START_ROUTINE)&output_thread_bt, NULL, 0, NULL); +#endif +#else + output.start_frames = FRAME_BLOCK; + output.write_cb = &_write_frames; + output.rate_delay = rate_delay; #endif LOG_INFO("Init completed."); @@ -115,111 +177,135 @@ void output_init_bt(log_level level, char *device, unsigned output_buf_size, cha /**************************************************************************************** * Main output thread */ +#ifdef USE_BT_RING_BUFFER static void *output_thread_bt() { + frames_t frames=0; - frames_t available_frames_space=0; - uint32_t timer_start=0, mutex_start=0, total_start=0; - static int count = 0; - + frames_t requested_frames=0; + uint32_t timer_start=0, mutex_start=0; + unsigned btbuf_used=0; + output_state state; DECLARE_ALL_MIN_MAX; - while (running) { frames=0; - available_frames_space=0; - + requested_frames=0; TIME_MEASUREMENT_START(timer_start); - TIME_MEASUREMENT_START(total_start); + + // Get output state TIME_MEASUREMENT_START(mutex_start); LOCK; + state=output.state; SET_MIN_MAX(TIME_MEASUREMENT_GET(mutex_start),mutex1); - if (output.state == OUTPUT_OFF) { + + if(state < OUTPUT_STOPPED ){ + // Flushing the buffer will automatically + // lock the mutex + LOG_SDEBUG("Flushing BT buffer"); + buf_flush(btbuf); + } + if (state == OUTPUT_OFF) { UNLOCK; LOG_SDEBUG("Output state is off."); - usleep(500000); + usleep(200000); continue; } + output.device_frames = 0; // todo: check if this is the right way do to this. + output.updated = gettime_ms(); + output.frames_played_dmp = output.frames_played; + TIME_MEASUREMENT_START(mutex_start); LOCK_BT; SET_MIN_MAX(TIME_MEASUREMENT_GET(mutex_start),mutex2); - available_frames_space = min(_buf_space(btbuf), _buf_cont_write(btbuf))/BYTES_PER_FRAME; - SET_MIN_MAX( available_frames_space,req); - SET_MIN_MAX(_buf_used(outputbuf)/BYTES_PER_FRAME,o); - SET_MIN_MAX(_buf_used(streambuf)/BYTES_PER_FRAME,s); - if(available_frames_space==0) + btbuf_used=_buf_used(btbuf); + SET_MIN_MAX_SIZED(btbuf_used,locbtbuff,btbuf->size); + + + // only output more frames if we need them + // so we can release the mutex as quickly as possible + requested_frames = min(_buf_space(btbuf), _buf_cont_write(btbuf))/BYTES_PER_FRAME; + SET_MIN_MAX( requested_frames*BYTES_PER_FRAME,req); + SET_MIN_MAX_SIZED(_buf_used(outputbuf),o,outputbuf->size); + SET_MIN_MAX_SIZED(_buf_used(streambuf),s,streambuf->size); + if(requested_frames>0) { - UNLOCK; - UNLOCK_BT; - usleep(10000); - continue; + frames = _output_frames( requested_frames ); // Keep the transfer buffer full + SET_MIN_MAX(frames*BYTES_PER_FRAME,rec); + if(requested_frames>frames){ + SET_MIN_MAX((requested_frames-frames)*BYTES_PER_FRAME,under); + } } - frames = _output_frames( available_frames_space ); // Keep the transfer buffer full - SET_MIN_MAX(_buf_used(btbuf),locbtbuff); + UNLOCK; UNLOCK_BT; - //LOG_SDEBUG("Current buffer free: %10d, cont read: %10d",_buf_space(btbuf),_buf_cont_read(btbuf)); SET_MIN_MAX( TIME_MEASUREMENT_GET(timer_start),buffering); - SET_MIN_MAX( available_frames_space,req); - SET_MIN_MAX(frames,rec); -// if(frames>0 ){ -// // let's hold processing a bit, while frames are being processed -// // we're waiting long enough to avoid hogging the CPU too much -// // while we're ramping up this transfer buffer -// wait_for_frames(frames,95); -// } - wait_for_frames(FRAME_BLOCK,100); + SET_MIN_MAX( requested_frames,req); + + // When playback has started, we want to + // hold the BT out thread + // so the BT data callback isn't constantly interrupted. + TIME_MEASUREMENT_START(timer_start); + if(state>OUTPUT_BUFFER){ + output_bt_suspend(); + } + SET_MIN_MAX(TIME_MEASUREMENT_GET(timer_start),sleep_time); /* * Statistics reporting */ -#define STATS_PERIOD_MS 10000 - count++; - TIMED_SECTION_START_MS(STATS_PERIOD_MS); - if(count>1){ - LOG_INFO( "count:%d, current sample rate: %d, avg cycle duration (ms): %d",count,output.current_sample_rate, STATS_PERIOD_MS/count); - LOG_INFO( " ----------+----------+-----------+-----------+ +----------+----------+----------------+----------------+----------------+"); - LOG_INFO( " max | min | avg | current| | max | min | average | count | current |"); - LOG_INFO( " (ms) | (ms) | (ms)| (ms) | | (bytes) | (bytes) | (bytes) | | (bytes) |"); - LOG_INFO( " ----------+----------+-----------+-----------+ +----------+----------+----------------+----------------+----------------+"); - LOG_INFO(LINE_MIN_MAX_FORMAT_STREAM, LINE_MIN_MAX_STREAM("stream",s)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("output",o)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("local bt buf",locbtbuff)); - LOG_INFO(" ----------+----------+-----------+-----------+ +----------+----------+----------------+----------------+"); - LOG_INFO(""); - LOG_INFO(" ----------+----------+-----------+-----------+-----------+ "); - LOG_INFO(" max (us) | min (us) | avg(us) | count |current(us)| "); - LOG_INFO(" ----------+----------+-----------+-----------+-----------+ "); - LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Buffering(us)",buffering)); - LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Output mux(us)",mutex1)); - LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("BT mux(us)",mutex2)); - LOG_INFO(" ----------+----------+-----------+-----------+-----------+"); + static time_t lastTime=0; + if (lastTime <= gettime_ms() ) + { +#define STATS_PERIOD_MS 15000 + lastTime = gettime_ms() + STATS_PERIOD_MS; + LOG_DEBUG(LINE_MIN_MAX_FORMAT_HEAD1); + LOG_DEBUG(LINE_MIN_MAX_FORMAT_HEAD2); + LOG_DEBUG(LINE_MIN_MAX_FORMAT_HEAD3); + LOG_DEBUG(LINE_MIN_MAX_FORMAT_HEAD4); + LOG_DEBUG(LINE_MIN_MAX_FORMAT_STREAM, LINE_MIN_MAX_STREAM("stream",s)); + LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("output",o)); + LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("local bt buf",locbtbuff)); + LOG_DEBUG(LINE_MIN_MAX_FORMAT_FOOTER ); + LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req)); + LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec)); + LOG_DEBUG(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("Underrun",under)); + LOG_DEBUG(LINE_MIN_MAX_FORMAT_FOOTER ); + LOG_DEBUG(""); + LOG_DEBUG(" ----------+----------+-----------+-----------+ "); + LOG_DEBUG(" max (us) | min (us) | avg(us) | count | "); + LOG_DEBUG(" ----------+----------+-----------+-----------+ "); + LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Buffering(us)",buffering)); + LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Output mux(us)",mutex1)); + LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("BT mux(us)",mutex2)); + LOG_DEBUG(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("sleep(us)",mutex2)); + LOG_DEBUG(" ----------+----------+-----------+-----------+"); RESET_ALL_MIN_MAX; - count=0; } - TIMED_SECTION_END; /* * End Statistics reporting */ + } - - - return 0; + return NULL; } +#endif void output_close_bt(void) { LOG_INFO("close output"); LOCK; running = false; UNLOCK; - +#ifdef USE_BT_RING_BUFFER + LOCK_BT; + buf_destroy(btbuf); + UNLOCK_BT; +#endif output_close_common(); } static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t gainR, s32_t cross_gain_in, s32_t cross_gain_out, ISAMPLE_T **cross_ptr) { - +#ifdef USE_BT_RING_BUFFER if (!silence ) { DEBUG_LOG_TIMED(200,"Not silence, Writing audio out."); // TODO need 16 bit fix @@ -235,6 +321,7 @@ static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t g #if BYTES_PER_FRAME == 4 memcpy(btbuf->writep, outputbuf->readp, out_frames * BYTES_PER_FRAME); + _buf_inc_writep(btbuf,out_frames * BYTES_PER_FRAME); #else { @@ -248,12 +335,46 @@ static int _write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t g } #endif - } else { - DEBUG_LOG_TIMED(200,"Silence flag true. Writing silence to audio out."); - + } else if(output.state >OUTPUT_BUFFER){ + // Don't fill our local buffer with silence frames. u8_t *buf = silencebuf; memcpy(btbuf->writep, buf, out_frames * BYTES_PER_FRAME); + _buf_inc_writep(btbuf,out_frames * BYTES_PER_FRAME); } - _buf_inc_writep(btbuf,out_frames * BYTES_PER_FRAME); +#else + assert(btout!=NULL); + if (!silence ) { + DEBUG_LOG_TIMED(200,"Not silence, Writing audio out."); + // TODO need 16 bit fix + + if (output.fade == FADE_ACTIVE && output.fade_dir == FADE_CROSS && *cross_ptr) { + _apply_cross(outputbuf, out_frames, cross_gain_in, cross_gain_out, cross_ptr); + } + + if (gainL != FIXED_ONE || gainR!= FIXED_ONE) { + _apply_gain(outputbuf, out_frames, gainL, gainR); + } + +#if BYTES_PER_FRAME == 4 + memcpy(btout, outputbuf->readp, out_frames * BYTES_PER_FRAME); +#else + { + frames_t count = out_frames; + s32_t *_iptr = (s32_t*) outputbuf->readp; + s16_t *_optr = (s16_t*) bt_optr; + while (count--) { + *_optr++ = *_iptr++ >> 16; + *_optr++ = *_iptr++ >> 16; + } + } +#endif + + } else { + + u8_t *buf = silencebuf; + memcpy(btout, buf, out_frames * BYTES_PER_FRAME); + } +#endif + return (int)out_frames; } diff --git a/main/output_dac.c b/main/output_dac.c index 927d64cc..2192580c 100644 --- a/main/output_dac.c +++ b/main/output_dac.c @@ -6,27 +6,25 @@ #define DECLARE_ALL_MIN_MAX \ - DECLARE_MIN_MAX(req, long,LONG); \ - DECLARE_MIN_MAX(rec, long,LONG); \ - DECLARE_MIN_MAX(over, long,LONG); \ - DECLARE_MIN_MAX(o, long,LONG); \ - DECLARE_MIN_MAX(s, long,LONG); \ - DECLARE_MIN_MAX(d, long,LONG); \ - DECLARE_MIN_MAX(loci2sbuf, long,LONG); \ - DECLARE_MIN_MAX(buffering, long,LONG);\ - DECLARE_MIN_MAX(i2s_time, long,LONG); \ - DECLARE_MIN_MAX(i2savailable, long,LONG); + DECLARE_MIN_MAX(req); \ + DECLARE_MIN_MAX(rec); \ + DECLARE_MIN_MAX(over); \ + DECLARE_MIN_MAX(o); \ + DECLARE_MIN_MAX(s); \ + DECLARE_MIN_MAX(loci2sbuf); \ + DECLARE_MIN_MAX(buffering); \ + DECLARE_MIN_MAX(i2s_time); \ + DECLARE_MIN_MAX(i2savailable); #define RESET_ALL_MIN_MAX \ - RESET_MIN_MAX(d,LONG); \ - RESET_MIN_MAX(o,LONG); \ - RESET_MIN_MAX(s,LONG); \ - RESET_MIN_MAX(loci2sbuf, LONG); \ - RESET_MIN_MAX(req,LONG); \ - RESET_MIN_MAX(rec,LONG); \ - RESET_MIN_MAX(over,LONG); \ - RESET_MIN_MAX(over,LONG); \ - RESET_MIN_MAX(i2savailable,LONG);\ - RESET_MIN_MAX(i2s_time,LONG); + RESET_MIN_MAX(o); \ + RESET_MIN_MAX(s); \ + RESET_MIN_MAX(loci2sbuf); \ + RESET_MIN_MAX(req); \ + RESET_MIN_MAX(rec); \ + RESET_MIN_MAX(over); \ + RESET_MIN_MAX(over); \ + RESET_MIN_MAX(i2savailable);\ + RESET_MIN_MAX(i2s_time); // Prevent compile errors if dac output is // included in the build and not actually activated in menuconfig @@ -74,7 +72,7 @@ static thread_type thread; static int _dac_write_frames(frames_t out_frames, bool silence, s32_t gainL, s32_t gainR, s32_t cross_gain_in, s32_t cross_gain_out, ISAMPLE_T **cross_ptr); -static void *output_thread(); +static void *output_thread_dac(); extern void wait_for_frames(size_t frames, uint8_t pct); /**************************************************************************************** @@ -160,8 +158,8 @@ void output_init_dac(log_level level, char *device, unsigned output_buf_size, ch LOG_ERROR("unable to malloc i2s buffer"); exit(0); } - LOG_SDEBUG("Current buffer free: %d",_buf_space(dacbuffer)); +PTHREAD_SET_NAME("output_dac"); #if LINUX || OSX || FREEBSD || POSIX pthread_attr_t attr; @@ -278,7 +276,7 @@ static void *output_thread() { isI2SStarted=false; i2s_stop(CONFIG_I2S_NUM); } - usleep(500000); + usleep(200000); continue; } LOG_SDEBUG("Current buffer free: %10d, cont read: %10d",_buf_space(dacbuffer),_buf_cont_read(dacbuffer)); @@ -343,35 +341,7 @@ static void *output_thread() { /* * Statistics reporting */ -#define STATS_PERIOD_MS 5000 - count++; - TIMED_SECTION_START_MS(STATS_PERIOD_MS); - LOG_INFO( "count:%d, current sample rate: %d, bytes per frame: %d, avg cycle duration (ms): %d",count,output.current_sample_rate, out_bytes_per_frame,STATS_PERIOD_MS/count); - LOG_INFO( " ----------+----------+-----------+ +----------+----------+----------------+"); - LOG_INFO( " max | min | current| | max | min | current |"); - LOG_INFO( " (ms) | (ms) | (ms)| | (bytes) | (bytes) | (bytes) |"); - LOG_INFO( " ----------+----------+-----------+ +----------+----------+----------------+"); - LOG_INFO(LINE_MIN_MAX_FORMAT_STREAM, LINE_MIN_MAX_STREAM("stream",s)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("output",o)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("i2swrite",i2savailable)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("local free",loci2sbuf)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("requested",req)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("received",rec)); - LOG_INFO(LINE_MIN_MAX_FORMAT,LINE_MIN_MAX("overflow",over)); - LOG_INFO(" ----------+----------+-----------+ +----------+----------+----------------+"); - LOG_INFO(""); - LOG_INFO(" max (us) | min (us) |current(us)| "); - LOG_INFO(" ----------+----------+-----------+ "); - LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("Buffering(us)",buffering)); - LOG_INFO(LINE_MIN_MAX_DURATION_FORMAT,LINE_MIN_MAX_DURATION("i2s tfr(us)",i2s_time)); - LOG_INFO(" ----------+----------+-----------+ "); - RESET_ALL_MIN_MAX; - count=0; - TIMED_SECTION_END; - /* - * End Statistics reporting - */ //wait_for_frames(BYTES_TO_FRAME(i2s_bytes_written)); /* @@ -406,9 +376,7 @@ static void *output_thread() { /* * End Statistics reporting */ - wait_for_frames(BYTES_TO_FRAME(i2s_bytes_written),75); - } - +// wait_for_frames(BYTES_TO_FRAME(i2s_bytes_written),75); return 0; } diff --git a/main/output_dac.c.tes b/main/output_dac.c.tes index 427d9267..2f2d8229 100644 --- a/main/output_dac.c.tes +++ b/main/output_dac.c.tes @@ -15,7 +15,6 @@ extern struct buffer *streambuf; #define FRAME_BLOCK MAX_SILENCE_FRAMES extern u8_t *silencebuf; -extern u8_t *buf; #define I2S_NUM (0) #define WAVE_FREQ_HZ (100) diff --git a/main/perf_trace.h b/main/perf_trace.h index 898cc82e..04e091bb 100644 --- a/main/perf_trace.h +++ b/main/perf_trace.h @@ -1,24 +1,48 @@ #pragma once -#define FRAMES_TO_MS(f) output.current_sample_rate>0?1000*f/output.current_sample_rate:LONG_MIN +#define PERF_MAX LONG_MAX +#define MIN_MAX_VAL(x) x==PERF_MAX?0:x +#define CURR_SAMPLE_RATE output.current_sample_rate>0?output.current_sample_rate:1 +#define FRAMES_TO_MS(f) (uint32_t)f*(uint32_t)1000/(uint32_t)(CURR_SAMPLE_RATE) #ifdef BYTES_TO_FRAME #define BYTES_TO_MS(b) FRAMES_TO_MS(BYTES_TO_FRAME(b)) #else #define BYTES_TO_MS(b) FRAMES_TO_MS(b/BYTES_PER_FRAME) #endif -#define LINE_MIN_MAX_FORMAT "%14s%10d|%10d|%11d|%11d|" " |%10d|%10d|%16d|%16d|%16d|" -#define LINE_MIN_MAX_DURATION_FORMAT "%14s%10d|%10d|%11d|%11d|%11d|" -#define LINE_MIN_MAX_FORMAT_STREAM "%14s%10s|%10s|%11s|%11s|" " |%10d|%10d|%16d|%16d|%16d|" #define SET_MIN_MAX(val,var) var=val; if(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 SET_MIN_MAX_SIZED(val,var,siz) var=val; if(varmax_##var) max_##var=var; count_##var++; avgtot_##var+= var;size_##var=siz +#define RESET_MIN_MAX(var) min_##var=PERF_MAX; max_##var=0; avgtot_##var=0;count_##var=0;var=0;size_##var=0 +#define RESET_MIN_MAX_DURATION(var) min_##var=PERF_MAX; max_##var=0; avgtot_##var=0;count_##var=0;var=0 +#define DECLARE_MIN_MAX(var) static uint32_t min_##var = PERF_MAX, max_##var = 0, size_##var = 0,avgtot_##var = 0, count_##var=0; uint32_t var=0 +#define DECLARE_MIN_MAX_DURATION(var) static uint32_t min_##var = PERF_MAX, max_##var = 0, avgtot_##var = 0, count_##var=0; uint32_t var=0 +#define LINE_MIN_MAX_AVG(var) (count_##var>0?avgtot_##var/count_##var:0) + +#define LINE_MIN_MAX_FORMAT_HEAD1 " +----------+----------+----------------+-----+----------------+" +#define LINE_MIN_MAX_FORMAT_HEAD2 " | max | min | average | | count |" +#define LINE_MIN_MAX_FORMAT_HEAD3 " | (bytes) | (bytes) | (bytes) | | |" +#define LINE_MIN_MAX_FORMAT_HEAD4 " +----------+----------+----------------+-----+----------------+" +#define LINE_MIN_MAX_FORMAT_FOOTER " +----------+----------+----------------+-----+----------------+" +#define LINE_MIN_MAX_FORMAT "%14s|%10u|%10u|%16u|%5u|%16u|" +#define LINE_MIN_MAX(name,var) name,\ + MIN_MAX_VAL(max_##var),\ + MIN_MAX_VAL(min_##var),\ + LINE_MIN_MAX_AVG(var),\ + size_##var!=0?100*LINE_MIN_MAX_AVG(var)/size_##var:0,\ + count_##var + +#define LINE_MIN_MAX_FORMAT_STREAM "%14s|%10u|%10u|%16u|%5u|%16u|" +#define LINE_MIN_MAX_STREAM(name,var) name,\ + MIN_MAX_VAL(max_##var),\ + MIN_MAX_VAL(min_##var),\ + LINE_MIN_MAX_AVG(var),\ + size_##var!=0?100*LINE_MIN_MAX_AVG(var)/size_##var:0,\ + count_##var +#define LINE_MIN_MAX_DURATION_FORMAT "%14s%10u|%10u|%11u|%11u|" +#define LINE_MIN_MAX_DURATION(name,var) name,MIN_MAX_VAL(max_##var),MIN_MAX_VAL(min_##var), LINE_MIN_MAX_AVG(var), count_##var + #define TIME_MEASUREMENT_START(x) x=esp_timer_get_time() -#define TIME_MEASUREMENT_GET(x) (esp_timer_get_time()-x)/1000 +#define TIME_MEASUREMENT_GET(x) (esp_timer_get_time()-x) #define TIMED_SECTION_START_MS_FORCE(x,force) if(hasTimeElapsed(x,force)) { #define TIMED_SECTION_START_MS(x) if(hasTimeElapsed(x,false)){ diff --git a/main/squeezelite.h b/main/squeezelite.h index 54495cda..459fe98a 100644 --- a/main/squeezelite.h +++ b/main/squeezelite.h @@ -46,6 +46,9 @@ #define POSIX 1 #include "embedded.h" #endif +#ifndef PTHREAD_SET_NAME +#define PTHREAD_SET_NAME(n) +#endif // build detection #if defined(linux) @@ -334,6 +337,10 @@ typedef int64_t s64_t; #define mutex_lock(m) pthread_mutex_lock(&m) #define mutex_unlock(m) pthread_mutex_unlock(&m) #define mutex_destroy(m) pthread_mutex_destroy(&m) +#define mutex_broadcast_cond(m) pthread_cond_broadcast(&m) +#define mutex_cond_wait(c,m) pthread_cond_wait(&c, &m) +#define mutex_cond_init(c) pthread_cond_init(&c, NULL) +#define thread_cond_type pthread_cond_t #define thread_type pthread_t #endif @@ -765,6 +772,7 @@ bool test_open(const char *device, unsigned rates[], bool userdef_rates); void output_init_bt(log_level level, char *device, unsigned output_buf_size, char *params, unsigned rates[], unsigned rate_delay, unsigned idle); void output_close_bt(void); void hal_bluetooth_init(log_level loglevel); +void output_bt_check_buffer(); #endif diff --git a/main/stream.c b/main/stream.c index ee9fe5f4..36c2f1b4 100644 --- a/main/stream.c +++ b/main/stream.c @@ -405,7 +405,7 @@ void stream_init(log_level level, unsigned stream_buf_size) { #if LINUX || FREEBSD touch_memory(streambuf->buf, streambuf->size); #endif - +PTHREAD_SET_NAME("stream"); #if LINUX || OSX || FREEBSD || POSIX pthread_attr_t attr; pthread_attr_init(&attr);