From: Mike Brady Date: Thu, 10 Oct 2019 08:23:20 +0000 (+0100) Subject: Add missing frame status field, fix a bug with the first missing frame variable,... X-Git-Tag: 3.3.3~2^2~15 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=686fc2a5c1952588b0fee04be361201696a476ba;p=thirdparty%2Fshairport-sync.git Add missing frame status field, fix a bug with the first missing frame variable, expose the settings for resending, remove some commented out code. --- diff --git a/common.c b/common.c index 2cadc203..ff643ef3 100644 --- a/common.c +++ b/common.c @@ -1299,6 +1299,7 @@ int _debug_mutex_unlock(pthread_mutex_t *mutex, const char *mutexname, const cha void malloc_cleanup(void *arg) { // debug(1, "malloc cleanup called."); free(arg); + arg = NULL; } void pthread_cleanup_debug_mutex_unlock(void *arg) { pthread_mutex_unlock((pthread_mutex_t *)arg); } diff --git a/common.h b/common.h index f05f107e..b50d4844 100644 --- a/common.h +++ b/common.h @@ -100,9 +100,9 @@ enum sps_format_t { const char *sps_format_description_string(enum sps_format_t format); typedef struct { - double resend_wait_before_check; // wait this long before asking for a missing packet to be resent - double resend_wait_between_checks; // wait this long between making requests - double resend_last_check_before_use; // if the packet is missing this close to the time of use, give up + double resend_control_first_check_time; // wait this long before asking for a missing packet to be resent + double resend_control_check_interval_time; // wait this long between making requests + double resend_control_last_check_time; // if the packet is missing this close to the time of use, give up pthread_mutex_t lock; config_t *cfg; int endianness; diff --git a/player.c b/player.c index 31098598..e98331f4 100644 --- a/player.c +++ b/player.c @@ -139,7 +139,7 @@ static void ab_resync(rtsp_conn_info *conn) { int position_in_modulo_uint16_t_buffer(uint16_t x, uint16_t start, uint16_t end, uint16_t *pos) { int response = 0; // not in the buffer if (start <= end) { - if (x < start) { + if (x < start) { // this means that it's up around the wrap if (pos) *pos = UINT16_MAX - start + 1 + x; } else { @@ -483,7 +483,6 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in conn->packet_count_since_flush++; conn->time_of_last_audio_packet = time_now; if (conn->connection_state_to_output) { // if we are supposed to be processing these packets - if ((conn->flush_rtp_timestamp != 0) && (actual_timestamp != conn->flush_rtp_timestamp) && (modulo_32_offset(actual_timestamp, conn->flush_rtp_timestamp) < conn->input_rate * 10)) { // if it's less than 10 seconds @@ -494,19 +493,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in conn->initial_reference_time = 0; conn->initial_reference_timestamp = 0; } else { - /* - if ((conn->flush_rtp_timestamp != 0) && - (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) > conn->input_rate / 5) - && - (modulo_32_offset(conn->flush_rtp_timestamp, actual_timestamp) < conn->input_rate)) { - // between 0.2 and 1 second - debug(2, "Dropping flush request in player_put_packet"); - conn->flush_rtp_timestamp = 0; - } - */ - abuf_t *abuf = 0; - if (!conn->ab_synced) { // if this is the first packet... debug(3, "syncing to seqno %u.", seqno); @@ -514,21 +501,6 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in conn->ab_read = seqno; conn->ab_synced = 1; } - - // here, we should check for missing frames - int resend_interval = (((250 * 44100) / 352) / 1000); // approximately 250 ms intervals - const int number_of_resend_attempts = 8; - int latency_based_resend_interval = - (conn->latency) / (number_of_resend_attempts * conn->max_frames_per_packet); - if (latency_based_resend_interval > resend_interval) - resend_interval = latency_based_resend_interval; - - if (conn->resend_interval != resend_interval) { - debug(2, "Resend interval for latency of %u frames is %d frames.", conn->latency, - resend_interval); - conn->resend_interval = resend_interval; - } - if (conn->ab_write == seqno) { // if this is the expected packet (which could be the first packet...) if (conn->input_frame_rate_starting_point_is_valid == 0) { @@ -538,17 +510,11 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in conn->input_frame_rate_starting_point_is_valid = 1; // valid now } } - conn->frames_inward_measurement_time = time_now; conn->frames_inward_frames_received_at_measurement_time = actual_timestamp; - abuf = conn->audio_buffer + BUFIDX(seqno); conn->ab_write = SUCCESSOR(seqno); // move the write pointer to the next free space } else if (seq_order(conn->ab_write, seqno, conn->ab_read)) { // newer than expected - // if (ORDINATE(seqno)>(BUFFER_FRAMES*7)/8) - // debug(1,"An interval of %u frames has opened, with ab_read: %u, ab_write: %u and - // seqno: - // %u.",seq_diff(ab_read,seqno),ab_read,ab_write,seqno); int32_t gap = seq_diff(conn->ab_write, seqno, conn->ab_read); if (gap <= 0) debug(1, "Unexpected gap size: %d.", gap); @@ -558,6 +524,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in abuf->ready = 0; // to be sure, to be sure abuf->resend_request_number = 0; abuf->initialisation_time = time_now; // this represents when the packet was noticed to be missing + abuf->status = 1 << 0; // signifying missing abuf->resend_time = 0; abuf->given_timestamp = 0; abuf->sequence_number = 0; @@ -567,24 +534,12 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in // rtp_request_resend(ab_write, gap); // resend_requests++; conn->ab_write = SUCCESSOR(seqno); - } else if (seq_order(conn->ab_read, seqno, conn->ab_read)) { // late but not yet played + } else if (seq_order(conn->ab_read, seqno, conn->ab_read)) { // older than expected but not too late conn->late_packets++; abuf = conn->audio_buffer + BUFIDX(seqno); - /* - if (abuf->ready) - debug(1,"Late apparently duplicate packet received that is %d packets - late.",seq_diff(seqno, conn->ab_write, conn->ab_read)); - else - debug(1,"Late packet received that is %d packets late.",seq_diff(seqno, - conn->ab_write, conn->ab_read)); - */ } else { // too late. - - // debug(1,"Too late packet received that is %d packets late.",seq_diff(seqno, - // conn->ab_write, conn->ab_read)); conn->too_late_packets++; } - // pthread_mutex_unlock(&ab_mutex); if (abuf) { int datalen = conn->max_frames_per_packet; @@ -592,28 +547,29 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in abuf->resend_time = 0; if (audio_packet_decode(abuf->data, &datalen, data, len, conn) == 0) { abuf->ready = 1; + abuf->status = 0; // signifying that it was received abuf->length = datalen; abuf->given_timestamp = actual_timestamp; abuf->sequence_number = seqno; } else { debug(1, "Bad audio packet detected and discarded."); abuf->ready = 0; + abuf->status = 1 << 1; // bad packet, discarded abuf->resend_request_number = 0; abuf->given_timestamp = 0; abuf->sequence_number = 0; } } - // pthread_mutex_lock(&ab_mutex); int rc = pthread_cond_signal(&conn->flowcontrol); if (rc) debug(1, "Error signalling flowcontrol."); // resend checks { - uint64_t minimum_wait_time = (uint64_t)(config.resend_wait_before_check * (uint64_t)0x100000000); - uint64_t resend_repeat_interval = (uint64_t)(config.resend_wait_between_checks * (uint64_t)0x100000000); - uint64_t minimum_remaining_time = (uint64_t)((config.resend_last_check_before_use + config.audio_backend_buffer_desired_length)* (uint64_t)0x100000000); + uint64_t minimum_wait_time = (uint64_t)(config.resend_control_first_check_time * (uint64_t)0x100000000); + uint64_t resend_repeat_interval = (uint64_t)(config.resend_control_check_interval_time * (uint64_t)0x100000000); + uint64_t minimum_remaining_time = (uint64_t)((config.resend_control_last_check_time + config.audio_backend_buffer_desired_length)* (uint64_t)0x100000000); uint64_t latency_time = (uint64_t)(conn->latency * (uint64_t)0x100000000); latency_time = latency_time / (uint64_t)conn->input_rate; @@ -624,19 +580,36 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in } else { x = conn->ab_read; } - + + first_possibly_missing_frame = -1; // has not been set + int missing_frame_run_count = 0; int start_of_missing_frame_run = -1; int number_of_missing_frames = 0; - debug(3,"check start"); while (x != conn->ab_write) { abuf_t *check_buf = conn->audio_buffer + BUFIDX(x); if (!check_buf->ready) { + if (first_possibly_missing_frame < 0) + first_possibly_missing_frame = x; number_of_missing_frames++; // debug(1, "frame %u's initialisation_time is 0x%" PRIx64 ", latency_time is 0x%" PRIx64 ", time_now is 0x%" PRIx64 ", minimum_remaining_time is 0x%" PRIx64 ".", x, check_buf->initialisation_time, latency_time, time_now, minimum_remaining_time); int too_late = ((check_buf->initialisation_time < (time_now - latency_time)) || ((check_buf->initialisation_time - (time_now - latency_time)) < minimum_remaining_time)); int too_early = ((time_now - check_buf->initialisation_time) < minimum_wait_time); int too_soon_after_last_request = ((check_buf->resend_time != 0) && ((time_now - check_buf->resend_time) < resend_repeat_interval)); // time_now can never be less than the time_tag + + if (too_late) + check_buf->status |= 1<<2; // too late + else + check_buf->status &= 0xFF-(1<<2); // not too late + if (too_early) + check_buf->status |= 1<<3; // too early + else + check_buf->status &= 0xFF-(1<<3); // not too early + if (too_soon_after_last_request) + check_buf->status |= 1<<4; // too soon after last request + else + check_buf->status &= 0xFF-(1<<4); // not too soon after last request + if ((!too_soon_after_last_request) && (!too_late) && (!too_early)){ if (start_of_missing_frame_run == -1) { start_of_missing_frame_run = x; @@ -646,7 +619,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in } check_buf->resend_time = time_now; // setting the time to now because we are definitely going to take action check_buf->resend_request_number++; - debug(2,"Frame %d is missing with ab_read of %d.", x, conn->ab_read); + debug(3,"Frame %d is missing with ab_read of %u and ab_write of %u.", x, conn->ab_read, conn->ab_write); } // if (too_late) { // debug(1,"too late to get missing frame %u.", x); @@ -1992,8 +1965,8 @@ void *player_thread_func(void *arg) { // debug(3, "Play frame %d.", play_number); conn->play_number_after_flush++; if (inframe->given_timestamp == 0) { - debug(2, "Player has supplied a silent frame, (possibly frame %u) for play number %d, after %d resend requests.", - SUCCESSOR(conn->last_seqno_read), play_number, inframe->resend_request_number); + debug(1, "Player has supplied a silent frame, (possibly frame %u) for play number %d, status 0x%X after %u resend requests.", + SUCCESSOR(conn->last_seqno_read), play_number, inframe->status, inframe->resend_request_number); conn->last_seqno_read = (SUCCESSOR(conn->last_seqno_read) & 0xffff); // manage the packet out of sequence minder diff --git a/player.h b/player.h index 0d89da44..9246f448 100644 --- a/player.h +++ b/player.h @@ -38,13 +38,14 @@ typedef struct time_ping_record { typedef uint16_t seq_t; typedef struct audio_buffer_entry { // decoded audio packets - int ready; + uint8_t ready; + uint8_t status; // flags + uint16_t resend_request_number; + signed short *data; + seq_t sequence_number; uint64_t initialisation_time; // the time the packet was added or the time it was noticed the packet was missing uint64_t resend_time; // time of last resend request or zero - int resend_request_number; - seq_t sequence_number; uint32_t given_timestamp; // for debugging and checking - signed short *data; int length; // the length of the decoded data } abuf_t; diff --git a/rtp.c b/rtp.c index 2e1e7f9f..6a90a5cd 100644 --- a/rtp.c +++ b/rtp.c @@ -1218,7 +1218,8 @@ void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { } #endif uint64_t time_of_sending_fp = get_absolute_time_in_fp(); - uint64_t resend_error_backoff_time = (uint64_t)1 << (32 - 4); // one sixteenth of a second + uint64_t resend_error_backoff_time = (uint64_t)1000000 * 0.3; // 0.3 seconds + resend_error_backoff_time = (resend_error_backoff_time << 32) / 1000000; if ((conn->rtp_time_of_last_resend_request_error_fp == 0) || ((time_of_sending_fp - conn->rtp_time_of_last_resend_request_error_fp) > resend_error_backoff_time)) { @@ -1238,8 +1239,7 @@ void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { (struct sockaddr *)&conn->rtp_client_control_socket, msgsize) == -1) { char em[1024]; strerror_r(errno, em, sizeof(em)); - debug(1, "Error %d using sendto to an audio socket: \"%s\". Backing off for 1/16th of a " - "second.", + debug(2, "Error %d using sendto to request a resend: \"%s\".", errno, em); conn->rtp_time_of_last_resend_request_error_fp = time_of_sending_fp; } else { @@ -1249,12 +1249,12 @@ void rtp_request_resend(seq_t first, uint32_t count, rtsp_conn_info *conn) { } else { debug( 3, - "Dropping resend request packet to simulate a bad network. Backing off for 1/16th of a " + "Dropping resend request packet to simulate a bad network. Backing off for 0.3 " "second."); conn->rtp_time_of_last_resend_request_error_fp = time_of_sending_fp; } } else { - debug(3, "Backing off sending resend requests due to a previous send-to error"); + debug(1, "Suppressing a resend request due to a resend sendto error in the last 0.3 seconds."); } } else { // if (!request_sent) { diff --git a/rtsp.c b/rtsp.c index 1b198c69..ded7035f 100644 --- a/rtsp.c +++ b/rtsp.c @@ -591,15 +591,6 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes int msg_size = -1; while (msg_size < 0) { - /* -fd_set readfds; -FD_ZERO(&readfds); -FD_SET(conn->fd, &readfds); -do { - memory_barrier(); -} while (conn->stop == 0 && - pselect(conn->fd + 1, &readfds, NULL, NULL, NULL, &pselect_sigset) <= 0); -*/ if (conn->stop != 0) { debug(3, "RTSP conversation thread %d shutdown requested.", conn->connection_number); reply = rtsp_read_request_response_immediate_shutdown_requested; @@ -684,16 +675,6 @@ do { } } - /* - fd_set readfds; - FD_ZERO(&readfds); - FD_SET(conn->fd, &readfds); - do { - memory_barrier(); - } while (conn->stop == 0 && - pselect(conn->fd + 1, &readfds, NULL, NULL, NULL, &pselect_sigset) <= 0); - */ - if (conn->stop != 0) { debug(1, "RTSP shutdown requested."); reply = rtsp_read_request_response_immediate_shutdown_requested; @@ -711,8 +692,17 @@ do { if (nread < 0) { if (errno == EINTR) continue; - perror("read failure"); - reply = rtsp_read_request_response_error; + if (errno == EAGAIN) { + debug(1, "Getting Error 11 -- EAGAIN from a blocking read!"); + continue; + } + if (errno != ECONNRESET) { + char errorstring[1024]; + strerror_r(errno, (char *)errorstring, sizeof(errorstring)); + debug(1, "Connection %d: rtsp_read_request_response_read_error %d: \"%s\".", + conn->connection_number, errno, (char *)errorstring); + } + reply = rtsp_read_request_response_read_error; goto shutdown; } inbuf += nread; diff --git a/scripts/shairport-sync.conf b/scripts/shairport-sync.conf index 6bca6d0e..54e22e87 100644 --- a/scripts/shairport-sync.conf +++ b/scripts/shairport-sync.conf @@ -51,6 +51,10 @@ general = // as "org.gnome.ShairportSync" on the whichever bus you specify here: "system" (default) or "session". // mpris_service_bus = "system"; // The Shairport Sync mpris interface, if selected at compilation, will appear // as "org.gnome.ShairportSync" on the whichever bus you specify here: "system" (default) or "session". +// resend_control_first_check_time = 0.10; // Use this optional advanced setting to set the wait time in seconds before deciding a packet is missing. +// resend_control_check_interval_time = 0.25; // Use this optional advanced setting to set the time in seconds between requests for a missing packet. +// resend_control_last_check_time = 0.10; // Use this optional advanced setting to set the latest time, in seconds, by which the last check should be done before the estimated time of a missing packet's transfer to the output buffer. +// }; // Advanced parameters for controlling how Shairport Sync stays active and how it runs a session diff --git a/shairport.c b/shairport.c index 2ed31deb..84c3e1f5 100644 --- a/shairport.c +++ b/shairport.c @@ -402,9 +402,9 @@ int parse_options(int argc, char **argv) { // i.e. when reducing volume, reduce the sw first before reducing the software. // this is because some hw mixers mute at the bottom of their range, and they don't always advertise // this fact - config.resend_wait_before_check = 0.10; // wait this many seconds before requesting the resending of a missing packet - config.resend_wait_between_checks = 0.25; // wait this many seconds before again requesting the resending of a missing packet - config.resend_last_check_before_use = 0.10; // give up if the packet is still missing this close to when it's needed + config.resend_control_first_check_time = 0.10; // wait this many seconds before requesting the resending of a missing packet + config.resend_control_check_interval_time = 0.25; // wait this many seconds before again requesting the resending of a missing packet + config.resend_control_last_check_time = 0.10; // give up if the packet is still missing this close to when it's needed #ifdef CONFIG_METADATA_HUB config.cover_art_cache_dir = "/tmp/shairport-sync/.cache/coverart"; @@ -766,6 +766,44 @@ int parse_options(int argc, char **argv) { } else die("Invalid alac_decoder option choice \"%s\". It should be \"hammerton\" or \"apple\""); } + + + /* Get the resend control settings. */ + if (config_lookup_float(config.cfg, "general.resend_control_first_check_time", + &dvalue)) { + if ((dvalue >= 0.0) && (dvalue <= 3.0)) + config.resend_control_first_check_time = dvalue; + else + warn("Invalid general resend_control_first_check_time setting \"%d\". It should " + "be " + "between 0.0 and 3.0, " + "inclusive. The setting remains at %f seconds.", + dvalue, config.resend_control_first_check_time); + } + + if (config_lookup_float(config.cfg, "general.resend_control_check_interval_time", + &dvalue)) { + if ((dvalue >= 0.0) && (dvalue <= 3.0)) + config.resend_control_check_interval_time = dvalue; + else + warn("Invalid general resend_control_check_interval_time setting \"%d\". It should " + "be " + "between 0.0 and 3.0, " + "inclusive. The setting remains at %f seconds.", + dvalue, config.resend_control_check_interval_time); + } + + if (config_lookup_float(config.cfg, "general.resend_control_last_check_time", + &dvalue)) { + if ((dvalue >= 0.0) && (dvalue <= 3.0)) + config.resend_control_last_check_time = dvalue; + else + warn("Invalid general resend_control_last_check_time setting \"%d\". It should " + "be " + "between 0.0 and 3.0, " + "inclusive. The setting remains at %f seconds.", + dvalue, config.resend_control_last_check_time); + } /* Get the default latency. Deprecated! */ if (config_lookup_int(config.cfg, "latencies.default", &value))