From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Mon, 24 Jan 2022 09:17:07 +0000 (+0100) Subject: Add some sanity checking of latency-affecting settings. X-Git-Tag: 4.1-rc1~24^2~293 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=deb11654ab4ef4144fec2fb322968792f970ff8c;p=thirdparty%2Fshairport-sync.git Add some sanity checking of latency-affecting settings. --- diff --git a/player.c b/player.c index 59ff4ccc..dadfc48b 100644 --- a/player.c +++ b/player.c @@ -1743,6 +1743,8 @@ void *player_thread_func(void *arg) { int previous_frames_played_valid = 0; // pthread_cleanup_push(player_thread_initial_cleanup_handler, arg); + conn->latency_warning_issued = + 0; // be permitted to generate a warning each time a play is attempted conn->packet_count = 0; conn->packet_count_since_flush = 0; conn->previous_random_number = 0; diff --git a/player.h b/player.h index 526c99f2..453c5f49 100644 --- a/player.h +++ b/player.h @@ -145,10 +145,11 @@ typedef struct flush_request_t { #endif typedef struct { - int connection_number; // for debug ID purposes, nothing else... - int resend_interval; // this is really just for debugging - char *UserAgent; // free this on teardown - int AirPlayVersion; // zero if not an AirPlay session. Used to help calculate latency + int connection_number; // for debug ID purposes, nothing else... + int resend_interval; // this is really just for debugging + char *UserAgent; // free this on teardown + int AirPlayVersion; // zero if not an AirPlay session. Used to help calculate latency + int latency_warning_issued; uint32_t latency; // the actual latency used for this play session uint32_t minimum_latency; // set if an a=min-latency: line appears in the ANNOUNCE message; zero // otherwise diff --git a/rtp.c b/rtp.c index 07942ae9..c38ea966 100644 --- a/rtp.c +++ b/rtp.c @@ -1668,95 +1668,118 @@ void *rtp_ap2_control_receiver(void *arg) { debug(1, "Discarding early timing packet."); } - if ((nread > 0) && (time_since_start > 10000000)) { - packet_number++; - - if (packet_number == 1) { - if ((packet[0] & 0x10) != 0) { - debug(2, "First packet is a sentinel packet."); - } else { - debug(1, "First packet is a not a sentinel packet!"); - } - } - // debug(1,"rtp_ap2_control_receiver coded: %u, %u", packet[0], packet[1]); + if (nread > 0) { + if ((time_since_start < 10000000) && ((packet[0] & 0x10) == 0)) { + debug(1, + "Dropping what looks like a (non-sentinel) packet left over from a previous session " + "at %f ms.", + 0.000001 * time_since_start); + } else { + packet_number++; - if ((config.diagnostic_drop_packet_fraction == 0.0) || - (drand48() > config.diagnostic_drop_packet_fraction)) { - // store the from_sock_addr if we haven't already done so - // v remember to zero this when you're finished! - if (conn->ap2_remote_control_socket_addr_length == 0) { - memcpy(&conn->ap2_remote_control_socket_addr, &from_sock_addr, from_sock_addr_length); - conn->ap2_remote_control_socket_addr_length = from_sock_addr_length; + if (packet_number == 1) { + if ((packet[0] & 0x10) != 0) { + debug(2, "First packet is a sentinel packet."); + } else { + debug(1, "First packet is a not a sentinel packet!"); + } } - switch (packet[1]) { - case 215: // code 215, effectively an anchoring announcement - { - // struct timespec tnr; - // clock_gettime(CLOCK_REALTIME, &tnr); - // uint64_t local_realtime_now = timespec_to_ns(&tnr); - - /* - char obf[4096]; - char *obfp = obf; - int obfc; - for (obfc=0;obfcinput_rate); - // the actual latency is the notified latency plus the fixed latency + the added latency - - if (added_latency < (-(notified_latency + 11035))) - debug(1, "the audio_backend_latency_offset is causing a negative latency!"); + // debug(1,"rtp_ap2_control_receiver coded: %u, %u", packet[0], packet[1]); + + if ((config.diagnostic_drop_packet_fraction == 0.0) || + (drand48() > config.diagnostic_drop_packet_fraction)) { + // store the from_sock_addr if we haven't already done so + // v remember to zero this when you're finished! + if (conn->ap2_remote_control_socket_addr_length == 0) { + memcpy(&conn->ap2_remote_control_socket_addr, &from_sock_addr, from_sock_addr_length); + conn->ap2_remote_control_socket_addr_length = from_sock_addr_length; + } + switch (packet[1]) { + case 215: // code 215, effectively an anchoring announcement + { + // struct timespec tnr; + // clock_gettime(CLOCK_REALTIME, &tnr); + // uint64_t local_realtime_now = timespec_to_ns(&tnr); + + /* + char obf[4096]; + char *obfp = obf; + int obfc; + for (obfc=0;obfcinput_rate); + // the actual latency is the notified latency plus the fixed latency + the added latency + + int32_t net_latency = + notified_latency + 11035 + + added_latency; // this is the latency between incoming frames and the DAC + net_latency = net_latency - + (int32_t)(config.audio_backend_buffer_desired_length * conn->input_rate); + // debug(1, "Net latency is %d frames.", net_latency); + + if (net_latency <= 0) { + if (conn->latency_warning_issued == 0) { + warn("The stream latency (%f seconds) it too short to accommodate an offset of %f seconds and a backend buffer of %f seconds.", ((notified_latency + 11035) * 1.0)/conn->input_rate, config.audio_backend_latency_offset, config.audio_backend_buffer_desired_length); + warn("(FYI the stream latency needed would be %f seconds.)", config.audio_backend_buffer_desired_length - config.audio_backend_latency_offset); + conn->latency_warning_issued = 1; + } + conn->latency = notified_latency + 11035; + } else { + conn->latency = notified_latency + 11035 + added_latency; + } - /* - debug_mutex_lock(&conn->reference_time_mutex, 1000, 0); - conn->remote_reference_timestamp_time = remote_packet_time_ns; - conn->reference_timestamp = - frame_1 - 11035 - added_latency; // add the latency in to the anchortime - debug_mutex_unlock(&conn->reference_time_mutex, 0); - */ - // this is now only used for calculating when to ask for resends - conn->latency = notified_latency + 11035 + added_latency; - // debug(1,"conn->latency is %d.", conn->latency); - set_ptp_anchor_info(conn, clock_id, frame_1 - 11035 - added_latency, - remote_packet_time_ns); - - } break; - case 0xd6: - // six bytes in is the sequence number at the start of the encrypted audio packet - // returns the sequence number but we're not really interested - decipher_player_put_packet(packet + 6, nread - 6, conn); - break; - default: { - char *packet_in_hex_cstring = - debug_malloc_hex_cstring(packet, nread); // remember to free this afterwards - debug(1, + /* + debug_mutex_lock(&conn->reference_time_mutex, 1000, 0); + conn->remote_reference_timestamp_time = remote_packet_time_ns; + conn->reference_timestamp = + frame_1 - 11035 - added_latency; // add the latency in to the anchortime + debug_mutex_unlock(&conn->reference_time_mutex, 0); + */ + // this is now only used for calculating when to ask for resends + // debug(1, "conn->latency is %d.", conn->latency); + set_ptp_anchor_info(conn, clock_id, frame_1 - 11035 - added_latency, + remote_packet_time_ns); + + } break; + case 0xd6: + // six bytes in is the sequence number at the start of the encrypted audio packet + // returns the sequence number but we're not really interested + decipher_player_put_packet(packet + 6, nread - 6, conn); + break; + default: { + char *packet_in_hex_cstring = + debug_malloc_hex_cstring(packet, nread); // remember to free this afterwards + debug( + 1, "AP2 Control Receiver Packet of first byte 0x%02X, type 0x%02X length %d received: " "\"%s\".", packet[0], packet[1], nread, packet_in_hex_cstring); - free(packet_in_hex_cstring); - } break; + free(packet_in_hex_cstring); + } break; + } + } else { + debug(1, "AP2 Control Receiver -- dropping a packet."); } - } else { - debug(1, "AP2 Control Receiver -- dropping a packet."); } } else if (nread == 0) { debug(1, "AP2 Control Receiver -- connection closed.");