From: Mike Brady Date: Tue, 11 Dec 2018 10:56:36 +0000 (+0000) Subject: Tidy up some debug messages and warnings, remove old diagnostic codes and settings. X-Git-Tag: 3.3RC0~104 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=45ce9092142ffb2c73a6fa4a198fbc84323dd1b4;p=thirdparty%2Fshairport-sync.git Tidy up some debug messages and warnings, remove old diagnostic codes and settings. --- diff --git a/audio_alsa.c b/audio_alsa.c index 71a4e7ee..761e06d9 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -75,9 +75,9 @@ audio_output audio_alsa = { static pthread_mutex_t alsa_mutex = PTHREAD_MUTEX_INITIALIZER; // for tracking how long the output device has stalled -uint64_t stall_monitor_start_time; // zero if not initialised / not started / zeroed by flush -long stall_monitor_frame_count; // set to delay at start of time, incremented by any writes -int stall_monitor_error_notified; +uint64_t stall_monitor_start_time; // zero if not initialised / not started / zeroed by flush +long stall_monitor_frame_count; // set to delay at start of time, incremented by any writes +uint64_t stall_monitor_error_threshold; // if the time is longer than this, it's an error static snd_output_t *output = NULL; static unsigned int desired_sample_rate; @@ -221,9 +221,7 @@ static int init(int argc, char **argv) { config.audio_backend_latency_offset = 0; config.audio_backend_buffer_desired_length = 0.15; - config.alsa_maximum_write_time = 0.016; // 16 milliseconds -- if it takes longer, we need to know - config.alsa_maximum_interface_response_time = - 0.001; // one millisecond -- if it takes longer, we need to know + config.alsa_maximum_stall_time = 0.200; // 200 milliseconds -- if it takes longer, it's a problem // get settings from settings file first, allow them to be overridden by // command line options @@ -382,25 +380,14 @@ static int init(int argc, char **argv) { } } - /* Get the optional alsa_maximum_interface_response_time setting. */ - if (config_lookup_float(config.cfg, "alsa.maximum_interface_response_time", &dvalue)) { - if (dvalue < 0.0) { - warn("Invalid alsa maximum interface response time setting \"%f\". It " - "must be greater than 0. Default is \"%f\". No setting is made.", - dvalue, config.alsa_maximum_interface_response_time); - } else { - config.alsa_maximum_interface_response_time = dvalue; - } - } - - /* Get the optional alsa_maximum_write_time setting. */ - if (config_lookup_float(config.cfg, "alsa.maximum_write_time", &dvalue)) { + /* Get the optional alsa_maximum_stall_time setting. */ + if (config_lookup_float(config.cfg, "alsa.maximum_stall_time", &dvalue)) { if (dvalue < 0.0) { warn("Invalid alsa maximum write time setting \"%f\". It " "must be greater than 0. Default is \"%f\". No setting is made.", - dvalue, config.alsa_maximum_write_time); + dvalue, config.alsa_maximum_stall_time); } else { - config.alsa_maximum_write_time = dvalue; + config.alsa_maximum_stall_time = dvalue; } } } @@ -943,7 +930,10 @@ static void start(int i_sample_rate, int i_sample_format) { stall_monitor_start_time = 0; stall_monitor_frame_count = 0; - stall_monitor_error_notified = 0; + + stall_monitor_error_threshold = + (uint64_t)1000000 * config.alsa_maximum_stall_time; // stall time max to microseconds; + stall_monitor_error_threshold = (stall_monitor_error_threshold << 32) / 1000000; // now in fp form } // assuming pthread cancellation is disabled @@ -984,7 +974,6 @@ int my_snd_pcm_delay(snd_pcm_t *pcm, snd_pcm_sframes_t *delayp) { } int delay(long *the_delay) { - uint64_t overall_time_before = get_absolute_time_in_fp(); *the_delay = 0; // snd_pcm_sframes_t is a signed long -- hence the return of a "long" int reply = 0; @@ -998,10 +987,8 @@ int delay(long *the_delay) { int derr; snd_pcm_state_t dac_state = snd_pcm_state(alsa_handle); if (dac_state == SND_PCM_STATE_RUNNING) { - *the_delay = 0; // just to see what happens - uint64_t time_before = get_absolute_time_in_fp(); + reply = snd_pcm_delay(alsa_handle, the_delay); - uint64_t response_time = get_absolute_time_in_fp() - time_before; if (reply != 0) { debug(1, "Error %d in delay(): \"%s\". Delay reported is %d frames.", reply, @@ -1020,15 +1007,6 @@ int delay(long *the_delay) { measurement_data_is_valid = 0; } } - uint64_t maximum_permitted_response_time = - (uint64_t)(config.alsa_maximum_interface_response_time * 1000000); // microseconds - maximum_permitted_response_time = (maximum_permitted_response_time << 32) / 1000000; - if (response_time > maximum_permitted_response_time) { - debug(3, "Maximum response time of %8.2f us exceeded reading delay. Response time was " - "%12.2f us.", - (1000000.0 * maximum_permitted_response_time) / (uint64_t)0x100000000, - (1000000.0 * response_time) / (uint64_t)0x100000000); - } } else { reply = -EIO; // shomething is wrong frame_index = 0; // we'll be starting over... @@ -1060,23 +1038,12 @@ int delay(long *the_delay) { // reply = -EIO; // pretend something bad has happened pthread_setcancelstate(oldState, NULL); } - debug(3, "Total playing time to get delay of %d frames: %8.2f us.", *the_delay, - (1000000.0 * (get_absolute_time_in_fp() - overall_time_before) / (uint64_t)0x100000000)); - if ((reply == 0) && (*the_delay != 0)) { uint64_t stall_monitor_time_now = get_absolute_time_in_fp(); if ((stall_monitor_start_time != 0) && (stall_monitor_frame_count == *the_delay)) { // hasn't outputted anything since the last call to delay() - int64_t time_stalled = stall_monitor_time_now - stall_monitor_start_time; - int64_t stall_monitor_error_threshold = 200000; // microseconds; - stall_monitor_error_threshold = - (stall_monitor_error_threshold << 32) / 1000000; // now in fp form + uint64_t time_stalled = stall_monitor_time_now - stall_monitor_start_time; if (time_stalled > stall_monitor_error_threshold) { - if (stall_monitor_error_notified == 0) { - debug(1, "alsa output device stalled -- no output in %8.2f us.", - (1000000.0 * stall_monitor_error_threshold) / (uint64_t)0x100000000); - stall_monitor_error_notified = 1; - } reply = sps_extra_errno_output_stalled; } } else { @@ -1106,7 +1073,6 @@ int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { } static int play(void *buf, int samples) { - uint64_t overall_time_before = get_absolute_time_in_fp(); // debug(3,"audio_alsa play called."); int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable @@ -1114,10 +1080,7 @@ static int play(void *buf, int samples) { if (alsa_handle == NULL) { pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); - overall_time_before = get_absolute_time_in_fp(); ret = actual_open_alsa_device(); - debug(3, "Opening time: %8.2f us.", - (1000000.0 * (get_absolute_time_in_fp() - overall_time_before) / (uint64_t)0x100000000)); if (ret == 0) { if (audio_alsa.volume) do_volume(set_volume); @@ -1151,12 +1114,8 @@ static int play(void *buf, int samples) { if ((samples != 0) && (buf != NULL)) { // debug(3, "write %d frames.", samples); - uint64_t maximum_permitted_writing_time = (config.alsa_maximum_write_time * 1000000000); - maximum_permitted_writing_time = (maximum_permitted_writing_time << 32) / 1000000000; - - overall_time_before = get_absolute_time_in_fp(); err = alsa_pcm_write(alsa_handle, buf, samples); - uint64_t writing_time = get_absolute_time_in_fp() - overall_time_before; + stall_monitor_frame_count += samples; if (err < 0) { @@ -1171,13 +1130,6 @@ static int play(void *buf, int samples) { err, samples, snd_strerror(err)); } - if (writing_time > maximum_permitted_writing_time) { - debug(3, "Taking too long to write %d samples. Playing time: %8.2f us, writing time: " - "%8.2f us.", - samples, (1000000.0 * maximum_permitted_writing_time) / (uint64_t)0x100000000, - (1000000.0 * writing_time) / (uint64_t)0x100000000); - } - if (frame_index == 0) { frames_sent_for_playing = samples; } else { @@ -1234,14 +1186,10 @@ static int play(void *buf, int samples) { pthread_cleanup_pop(0); // release the mutex } pthread_setcancelstate(oldState, NULL); - debug(3, "Total playing time to write %d samples: %8.2f us.", samples, - (1000000.0 * (get_absolute_time_in_fp() - overall_time_before) / (uint64_t)0x100000000)); - return ret; } static void flush(void) { - uint64_t overall_time_before = get_absolute_time_in_fp(); // debug(2,"audio_alsa flush called."); int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable @@ -1267,8 +1215,6 @@ static void flush(void) { debug_mutex_unlock(&alsa_mutex, 3); pthread_cleanup_pop(0); // release the mutex pthread_setcancelstate(oldState, NULL); - debug(3, "Total playing time to flush: %8.2f us.", - (1000000.0 * (get_absolute_time_in_fp() - overall_time_before) / (uint64_t)0x100000000)); } static void stop(void) { diff --git a/common.h b/common.h index 9e2d88f3..3ac2f1a0 100644 --- a/common.h +++ b/common.h @@ -187,8 +187,7 @@ typedef struct { float loudness_reference_volume_db; int alsa_use_hardware_mute; - double alsa_maximum_interface_response_time; - double alsa_maximum_write_time; + double alsa_maximum_stall_time; #if defined(CONFIG_DBUS_INTERFACE) enum dbus_session_type dbus_service_bus_type; diff --git a/player.c b/player.c index ec7d2adc..42985019 100644 --- a/player.c +++ b/player.c @@ -1079,16 +1079,9 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { (conn->unfixable_error_reported == 0)) { conn->unfixable_error_reported = 1; if (config.cmd_unfixable) { - warn("Connection %d: An unfixable error has been detected -- output device " - "is stalled. Executing the " - "\"run_this_if_an_unfixable_error_is_detected\" command.", - conn->connection_number); command_execute(config.cmd_unfixable, "output_device_stalled"); } else { - warn("Connection %d: An unfixable error has been detected -- output device " - "is stalled. \"No " - "run_this_if_an_unfixable_error_is_detected\" command provided -- " - "nothing done.", + warn("An unfixable error, \"output_device_stalled\", has been detected.", conn->connection_number); } } diff --git a/rtsp.c b/rtsp.c index 04369ee1..30505008 100644 --- a/rtsp.c +++ b/rtsp.c @@ -293,15 +293,10 @@ void *player_watchdog_thread_code(void *arg) { } else if (conn->watchdog_barks == 3) { if ((config.cmd_unfixable) && (conn->unfixable_error_reported == 0)) { conn->unfixable_error_reported = 1; - warn("Connection %d: An unfixable error has been detected -- can't stop a play " - "session. Executing the " - "\"run_this_if_an_unfixable_error_is_detected\" command.", - conn->connection_number); command_execute(config.cmd_unfixable, "unable_to_cancel_play_session"); } else { - warn("Connection %d: An unfixable error has been detected -- can't stop a play " - "session. \"No " - "run_this_if_an_unfixable_error_is_detected\" command provided -- nothing done.", + warn("Connection %d: An unfixable error, code \"unable_to_cancel_play_session\" has " + "been detected.", conn->connection_number); } }