From 50700b46a58cb08a527763905746175891d05dc1 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 8 Dec 2018 12:58:01 +0000 Subject: [PATCH 1/3] Add timing to writing to the DAC --- audio_alsa.c | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/audio_alsa.c b/audio_alsa.c index 5705380e..ca869f1b 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -1067,7 +1067,12 @@ static int play(void *buf, int samples) { debug(1, "empty buffer being passed to pcm_writei -- skipping it"); if ((samples != 0) && (buf != NULL)) { debug(3, "write %d frames.", samples); + uint64_t nominal_playing_time = samples; + nominal_playing_time = (nominal_playing_time << 32) / desired_sample_rate; + uint64_t time_before = get_absolute_time_in_fp(); err = alsa_pcm_write(alsa_handle, buf, samples); + uint64_t writing_time = get_absolute_time_in_fp() - time_before; + if (err < 0) { frame_index = 0; measurement_data_is_valid = 0; @@ -1079,6 +1084,11 @@ static int play(void *buf, int samples) { "play(): \"%s\".", err, samples, snd_strerror(err)); } + + if (writing_time > nominal_playing_time) { + debug(1,"Taking too long to write %d samples. Playing time: %8.2f us, writing time: %8.2f us.", samples,(1000000.0 * nominal_playing_time)/(uint64_t)0x100000000, (1000000.0 * writing_time)/(uint64_t)0x100000000); + } + if (frame_index == 0) { frames_sent_for_playing = samples; } else { From e5452e51725fbc28d6dbe4b112ddf94eb4c4f223 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 8 Dec 2018 14:12:33 +0000 Subject: [PATCH 2/3] Make the idle timeout on the RTSP link the same as the overall timeout -- 30 seconds is a bit short. Add checks to the alsa interface timing -- 15 ms to write a packet of frames, 1 ms to ask for the delay. --- audio_alsa.c | 62 ++++++++++++++++++++++++++++++++++++++++++++-------- common.h | 4 ++++ rtp.c | 4 ++-- rtsp.c | 19 ++++++++-------- 4 files changed, 69 insertions(+), 20 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index ca869f1b..acc4693e 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -216,6 +216,10 @@ 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 + // get settings from settings file first, allow them to be overridden by // command line options @@ -223,6 +227,7 @@ static int init(int argc, char **argv) { parse_general_audio_options(); if (config.cfg != NULL) { + double dvalue; /* Get the Output Device Name. */ if (config_lookup_string(config.cfg, "alsa.output_device", &str)) { @@ -371,6 +376,28 @@ static int init(int argc, char **argv) { buffer_size_requested = value; } } + + /* 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)) { + 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); + } else { + config.alsa_maximum_write_time = dvalue; + } + } } optind = 1; // optind=0 is equivalent to optind=1 plus special behaviour @@ -956,12 +983,15 @@ int delay(long *the_delay) { } else { int oldState; pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable - pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1); + pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0); 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, snd_strerror(reply), *the_delay); @@ -979,6 +1009,15 @@ 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... @@ -1066,13 +1105,15 @@ static int play(void *buf, int samples) { if (samples == 0) debug(1, "empty buffer being passed to pcm_writei -- skipping it"); if ((samples != 0) && (buf != NULL)) { - debug(3, "write %d frames.", samples); - uint64_t nominal_playing_time = samples; - nominal_playing_time = (nominal_playing_time << 32) / desired_sample_rate; + // 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; + uint64_t time_before = get_absolute_time_in_fp(); err = alsa_pcm_write(alsa_handle, buf, samples); uint64_t writing_time = get_absolute_time_in_fp() - time_before; - + if (err < 0) { frame_index = 0; measurement_data_is_valid = 0; @@ -1084,11 +1125,14 @@ static int play(void *buf, int samples) { "play(): \"%s\".", err, samples, snd_strerror(err)); } - - if (writing_time > nominal_playing_time) { - debug(1,"Taking too long to write %d samples. Playing time: %8.2f us, writing time: %8.2f us.", samples,(1000000.0 * nominal_playing_time)/(uint64_t)0x100000000, (1000000.0 * writing_time)/(uint64_t)0x100000000); + + 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 { diff --git a/common.h b/common.h index a9f4ab7d..abf19e71 100644 --- a/common.h +++ b/common.h @@ -184,6 +184,10 @@ typedef struct { int loudness; float loudness_reference_volume_db; int alsa_use_hardware_mute; + + double alsa_maximum_interface_response_time; + double alsa_maximum_write_time; + #if defined(CONFIG_DBUS_INTERFACE) enum dbus_session_type dbus_service_bus_type; #endif diff --git a/rtp.c b/rtp.c index ac1a43b6..07f19169 100644 --- a/rtp.c +++ b/rtp.c @@ -377,7 +377,7 @@ void *rtp_control_receiver(void *arg) { } } - debug_mutex_lock(&conn->reference_time_mutex, 1000, 1); + debug_mutex_lock(&conn->reference_time_mutex, 1000, 0); if (conn->packet_stream_established) { if (conn->initial_reference_time == 0) { @@ -414,7 +414,7 @@ void *rtp_control_receiver(void *arg) { // remote_time_of_sync - local_to_remote_time_difference_now(conn); conn->reference_timestamp = sync_rtp_timestamp; conn->latency_delayed_timestamp = rtp_timestamp_less_latency; - debug_mutex_unlock(&conn->reference_time_mutex, 3); + debug_mutex_unlock(&conn->reference_time_mutex, 0); conn->reference_to_previous_time_difference = remote_time_of_sync - old_remote_reference_time; diff --git a/rtsp.c b/rtsp.c index 158b3263..7921f70b 100644 --- a/rtsp.c +++ b/rtsp.c @@ -273,7 +273,7 @@ void *player_watchdog_thread_code(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; do { usleep(2000000); // check every two seconds - debug(3, "Connection %d: Check the thread is doing something...", conn->connection_number); + // debug(3, "Connection %d: Check the thread is doing something...", conn->connection_number); if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { debug_mutex_lock(&conn->watchdog_mutex, 1000, 0); uint64_t last_watchdog_bark_time = conn->watchdog_bark_time; @@ -482,9 +482,9 @@ static void debug_print_msg_content(int level, rtsp_message *msg) { void msg_free(rtsp_message *msg) { if (msg) { - debug_mutex_lock(&reference_counter_lock, 1000, 3); + debug_mutex_lock(&reference_counter_lock, 1000, 0); msg->referenceCount--; - debug_mutex_unlock(&reference_counter_lock, 3); + debug_mutex_unlock(&reference_counter_lock, 0); if (msg->referenceCount == 0) { unsigned int i; for (i = 0; i < msg->nheaders; i++) { @@ -2151,7 +2151,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) { } void msg_cleanup_function(void *arg) { - debug(3, "msg_cleanup_function called."); + // debug(3, "msg_cleanup_function called."); msg_free((rtsp_message *)arg); } @@ -2409,11 +2409,12 @@ void rtsp_listen_loop(void) { if (setsockopt(fd, SOL_SOCKET, SO_SNDTIMEO, (const char *)&tv, sizeof tv) == -1) debug(1, "Error %d setting send timeout for rtsp writeback.", errno); - tv.tv_sec = 30; // 30 seconds read timeout - tv.tv_usec = 0; - if (setsockopt(fd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1) - debug(1, "Error %d setting send timeout for rtsp writeback.", errno); - + if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { + tv.tv_sec = config.timeout; // 120 seconds read timeout by default. + tv.tv_usec = 0; + if (setsockopt(fd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1) + debug(1, "Error %d setting read timeout for rtsp connection.", errno); + } #ifdef IPV6_V6ONLY // some systems don't support v4 access on v6 sockets, but some do. // since we need to account for two sockets we might as well From 697d654b4144da78eef40341103471f78a936a58 Mon Sep 17 00:00:00 2001 From: Mike Brady Date: Sat, 8 Dec 2018 14:13:04 +0000 Subject: [PATCH 3/3] Make the idle timeout on the RTSP link the same as the overall timeout -- 30 seconds is a bit short. Add checks to the alsa interface timing -- 15 ms to write a packet of frames, 1 ms to ask for the delay. --- configure.ac | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/configure.ac b/configure.ac index 8f3248ab..7d209028 100644 --- a/configure.ac +++ b/configure.ac @@ -2,7 +2,7 @@ # Process this file with autoconf to produce a configure script. AC_PREREQ([2.50]) -AC_INIT([shairport-sync], [3.3d34], [mikebrady@eircom.net]) +AC_INIT([shairport-sync], [3.3d35], [mikebrady@eircom.net]) AM_INIT_AUTOMAKE AC_CONFIG_SRCDIR([shairport.c]) AC_CONFIG_HEADERS([config.h])