From: Mike Brady Date: Mon, 2 Apr 2018 15:42:46 +0000 (+0100) Subject: Modify latency detection to use the second word of a sync packet to decide whether... X-Git-Tag: 3.2RC1~7^2~17 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=8bf83c149f068c8e22dbbe497de269dcd8bd9e8f;p=thirdparty%2Fshairport-sync.git Modify latency detection to use the second word of a sync packet to decide whether to add an extra delay or not. Use all sync packets, not just one with the exception flag. Use 1024 buffers -- a bit profligate, but hey. --- diff --git a/common.c b/common.c index 33666e95..0a8eaa04 100644 --- a/common.c +++ b/common.c @@ -970,13 +970,20 @@ uint64_t ranarray64u() { return (ranarrayval()); } int64_t ranarray64i() { return (ranarrayval() >> 1); } -uint32_t nctohl(const uint8_t *p) { // read 4 characters from the p and do ntohl on them +uint32_t nctohl(const uint8_t *p) { // read 4 characters from *p and do ntohl on them // this is to avoid possible aliasing violations uint32_t holder; memcpy(&holder, p, sizeof(holder)); return ntohl(holder); } +uint16_t nctohs(const uint8_t *p) { // read 2 characters from *p and do ntohs on them + // this is to avoid possible aliasing violations + uint16_t holder; + memcpy(&holder, p, sizeof(holder)); + return ntohs(holder); +} + pthread_mutex_t barrier_mutex = PTHREAD_MUTEX_INITIALIZER; void memory_barrier() { diff --git a/common.h b/common.h index 49717c8b..ce8a6e2a 100644 --- a/common.h +++ b/common.h @@ -178,7 +178,9 @@ typedef struct { } shairport_cfg; -uint32_t nctohl(const uint8_t *p); // read 4 characters from the p and do ntohl on them +uint32_t nctohl(const uint8_t *p); // read 4 characters from *p and do ntohl on them +uint16_t nctohs(const uint8_t *p); // read 2 characters from *p and do ntohs on them + void memory_barrier(); // true if Shairport Sync is supposed to be sending output to the output device, false otherwise diff --git a/dacp.c b/dacp.c index 63bfdfe8..799f719c 100644 --- a/dacp.c +++ b/dacp.c @@ -223,7 +223,7 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { int ndata = recv(sockfd, buffer, sizeof(buffer), 0); // debug(1,"Received %d bytes: \"%s\".",ndata,buffer); if (ndata <= 0) { - debug(1, "Error receiving data."); + debug(2, "dacp_send_command -- error receiving response for command \"%s\".",command); free(response.body); response.body = NULL; response.malloced_size = 0; @@ -258,7 +258,7 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) { // debug(1,"Sent command\"%s\" with a response body of size %d.",command,response.size); // debug(1,"dacp_conversation_lock released."); } else { - debug(1, "Could not acquire a lock on the dacp transmit/receive section when attempting to " + debug(3, "Could not acquire a lock on the dacp transmit/receive section when attempting to " "send the command \"%s\". Possible timeout?", command); response.code = 494; // This client is already busy @@ -289,7 +289,7 @@ void relinquish_dacp_server_information(rtsp_conn_info *conn) { // index) hasn't already taken over the dacp service sps_pthread_mutex_timedlock( &dacp_server_information_lock, 500000, - "set_dacp_server_information couldn't get DACP server information lock in 0.5 second!.", 1); + "set_dacp_server_information couldn't get DACP server information lock in 0.5 second!.", 2); if (dacp_server.players_connection_thread_index == conn->connection_number) dacp_server.players_connection_thread_index = 0; pthread_mutex_unlock(&dacp_server_information_lock); @@ -303,7 +303,7 @@ void relinquish_dacp_server_information(rtsp_conn_info *conn) { void set_dacp_server_information(rtsp_conn_info *conn) { sps_pthread_mutex_timedlock( &dacp_server_information_lock, 500000, - "set_dacp_server_information couldn't get DACP server information lock in 0.5 second!.", 1); + "set_dacp_server_information couldn't get DACP server information lock in 0.5 second!.", 2); dacp_server.players_connection_thread_index = conn->connection_number; if (strcmp(conn->dacp_id, dacp_server.dacp_id) != 0) { strncpy(dacp_server.dacp_id, conn->dacp_id, sizeof(dacp_server.dacp_id)); @@ -342,7 +342,7 @@ void dacp_monitor_port_update_callback(char *dacp_id, uint16_t port) { sps_pthread_mutex_timedlock( &dacp_server_information_lock, 500000, "dacp_monitor_port_update_callback couldn't get DACP server information lock in 0.5 second!.", - 1); + 2); if (strcmp(dacp_id, dacp_server.dacp_id) == 0) { dacp_server.port = port; if (port == 0) @@ -355,7 +355,7 @@ void dacp_monitor_port_update_callback(char *dacp_id, uint16_t port) { metadata_hub_modify_epilog(ch); pthread_cond_signal(&dacp_server_information_cv); } else { - debug(1, "dacp port monitor reporting on and out-of-use remote."); + debug(1, "dacp port monitor reporting on an out-of-use remote."); } pthread_mutex_unlock(&dacp_server_information_lock); } @@ -369,7 +369,7 @@ void *dacp_monitor_thread_code(__attribute__((unused)) void *na) { int result; sps_pthread_mutex_timedlock( &dacp_server_information_lock, 500000, - "dacp_monitor_thread_code couldn't get DACP server information lock in 0.5 second!.", 1); + "dacp_monitor_thread_code couldn't get DACP server information lock in 0.5 second!.", 2); while (dacp_server.scan_enable == 0) { // debug(1, "Wait for a valid DACP port"); pthread_cond_wait(&dacp_server_information_cv, &dacp_server_information_lock); @@ -459,19 +459,19 @@ void *dacp_monitor_thread_code(__attribute__((unused)) void *na) { case 2: if (metadata_store.play_status != PS_STOPPED) { metadata_store.play_status = PS_STOPPED; - debug(1, "Play status is \"stopped\"."); + debug(2, "Play status is \"stopped\"."); } break; case 3: if (metadata_store.play_status != PS_PAUSED) { metadata_store.play_status = PS_PAUSED; - debug(1, "Play status is \"paused\"."); + debug(2, "Play status is \"paused\"."); } break; case 4: if (metadata_store.play_status != PS_PLAYING) { metadata_store.play_status = PS_PLAYING; - debug(1, "Play status changed to \"playing\"."); + debug(2, "Play status changed to \"playing\"."); } break; default: @@ -486,13 +486,13 @@ void *dacp_monitor_thread_code(__attribute__((unused)) void *na) { case 0: if (metadata_store.shuffle_status != SS_OFF) { metadata_store.shuffle_status = SS_OFF; - debug(1, "Shuffle status is \"off\"."); + debug(2, "Shuffle status is \"off\"."); } break; case 1: if (metadata_store.shuffle_status != SS_ON) { metadata_store.shuffle_status = SS_ON; - debug(1, "Shuffle status is \"on\"."); + debug(2, "Shuffle status is \"on\"."); } break; default: @@ -507,19 +507,19 @@ void *dacp_monitor_thread_code(__attribute__((unused)) void *na) { case 0: if (metadata_store.repeat_status != RS_OFF) { metadata_store.repeat_status = RS_OFF; - debug(1, "Repeat status is \"none\"."); + debug(2, "Repeat status is \"none\"."); } break; case 1: if (metadata_store.repeat_status != RS_ONE) { metadata_store.repeat_status = RS_ONE; - debug(1, "Repeat status is \"one\"."); + debug(2, "Repeat status is \"one\"."); } break; case 2: if (metadata_store.repeat_status != RS_ALL) { metadata_store.repeat_status = RS_ALL; - debug(1, "Repeat status is \"all\"."); + debug(2, "Repeat status is \"all\"."); } break; default: diff --git a/dbus-service.c b/dbus-service.c index a6476027..26834e58 100644 --- a/dbus-service.c +++ b/dbus-service.c @@ -503,7 +503,7 @@ gboolean notify_loop_status_callback(ShairportSyncAdvancedRemoteControl *skeleto char *th = (char *)shairport_sync_advanced_remote_control_get_loop_status(skeleton); // enum volume_control_profile_type previous_volume_control_profile = // config.volume_control_profile; - debug(1, "notify_loop_status_callback called with loop status of \"%s\".", th); + // debug(1, "notify_loop_status_callback called with loop status of \"%s\".", th); if (strcasecmp(th, "off") == 0) send_simple_dacp_command("setproperty?dacp.repeatstate=0"); else if (strcasecmp(th, "one") == 0) diff --git a/metadata_hub.c b/metadata_hub.c index b627d9f9..9bcf58d8 100644 --- a/metadata_hub.c +++ b/metadata_hub.c @@ -82,7 +82,7 @@ void metadata_hub_release_track_metadata(struct track_metadata_bundle *track_met release_char_string(&track_metadata->sort_as); free((char *)track_metadata); } else { - debug(1, "Releasing non-existent track metadata"); + debug(3, "Asked to release non-existent track metadata"); } } diff --git a/player.c b/player.c index 6e3f533d..2d2f0d0e 100644 --- a/player.c +++ b/player.c @@ -833,9 +833,11 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { // supposed to start playing this have_sent_prefiller_silence = 0; + // debug(1, "First packet timestamp is %" PRId64 ".", conn->first_packet_timestamp); + // say we have started playing here #ifdef CONFIG_METADATA - debug(1, "pffr"); + debug(2, "pffr"); send_ssnc_metadata( 'pffr', NULL, 0, 0); // "first frame received", but don't wait if the queue is locked @@ -1060,7 +1062,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { &conn->play_segment_reference_frame_remote_time, conn); conn->play_segment_reference_frame *= conn->output_sample_ratio; #ifdef CONFIG_METADATA - debug(1, "prsm"); + debug(2, "prsm"); send_ssnc_metadata('prsm', NULL, 0, 0); // "resume", but don't wait if the queue is locked #endif @@ -1386,9 +1388,9 @@ static void *player_thread_func(void *arg) { conn->fix_volume = 0x10000; if (conn->latency == 0) { - debug(3, "No latency has (yet) been specified. Setting 99,226 (2.25 seconds + 1 frame) frames " + debug(3, "No latency has (yet) been specified. Setting 88,200 (2 seconds) frames " "as a default."); - conn->latency = 99226; + conn->latency = 88200; } int rc = pthread_mutex_init(&conn->ab_mutex, NULL); @@ -2532,7 +2534,7 @@ void player_flush(int64_t timestamp, rtsp_conn_info *conn) { // only send a flush metadata message if the first packet has been seen -- it's a bogus message // otherwise if (conn->first_packet_timestamp) { - debug(1, "pfls"); + debug(2, "pfls"); send_ssnc_metadata('pfls', NULL, 0, 1); } #endif @@ -2547,7 +2549,7 @@ int player_play(rtsp_conn_info *conn) { BUFFER_FRAMES); command_start(); #ifdef CONFIG_METADATA - debug(1, "pbeg"); + debug(2, "pbeg"); send_ssnc_metadata('pbeg', NULL, 0, 1); #endif pthread_t *pt = malloc(sizeof(pthread_t)); @@ -2572,7 +2574,7 @@ void player_stop(rtsp_conn_info *conn) { pthread_kill(*conn->player_thread, SIGUSR1); pthread_join(*conn->player_thread, NULL); #ifdef CONFIG_METADATA - debug(1, "pend"); + debug(2, "pend"); send_ssnc_metadata('pend', NULL, 0, 1); #endif command_stop(); diff --git a/player.h b/player.h index a6deb7c8..f04eee1a 100644 --- a/player.h +++ b/player.h @@ -45,7 +45,7 @@ typedef struct audio_buffer_entry { // decoded audio packets // default buffer size // needs to be a power of 2 because of the way BUFIDX(seqno) works -#define BUFFER_FRAMES 512 +#define BUFFER_FRAMES 1024 typedef struct { int encrypted; @@ -141,6 +141,7 @@ typedef struct { int control_socket; // our local [server] control socket int timing_socket; // local timing socket + int64_t latency_delayed_timestamp; // this is for debugging only... int64_t reference_timestamp; uint64_t reference_timestamp_time; uint64_t remote_reference_timestamp_time; diff --git a/rtp.c b/rtp.c index 03002fa7..7a9f8234 100644 --- a/rtp.c +++ b/rtp.c @@ -25,9 +25,14 @@ * OTHER DEALINGS IN THE SOFTWARE. */ +#include "rtp.h" +#include "common.h" +#include "player.h" +#include "rtsp.h" #include #include #include +#include #include #include #include @@ -39,11 +44,6 @@ #include #include -#include "common.h" -#include "player.h" -#include "rtp.h" -#include "rtsp.h" - uint64_t local_to_remote_time_jitters; uint64_t local_to_remote_time_jitters_count; @@ -56,6 +56,7 @@ void rtp_initialise(rtsp_conn_info *conn) { int rc = pthread_mutex_init(&conn->reference_time_mutex, NULL); if (rc) debug(1, "Error initialising reference_time_mutex."); + } void rtp_terminate(rtsp_conn_info *conn) { @@ -209,17 +210,38 @@ void *rtp_control_receiver(void *arg) { ssize_t plen = nread; if (packet[1] == 0xd4) { // sync data - /* - char obf[4096]; - char *obfp = obf; - int obfc; - for (obfc=0;obfclocal_to_remote_time_difference) { // need a time packet to be interchanged first... remote_time_of_sync = (uint64_t)nctohl(&packet[8]) << 32; @@ -228,48 +250,83 @@ void *rtp_control_receiver(void *arg) { // debug(1,"Remote Sync Time: %0llx.",remote_time_of_sync); sync_rtp_timestamp = monotonic_timestamp(nctohl(&packet[16]), conn); + int64_t rtp_timestamp_less_latency = monotonic_timestamp(nctohl(&packet[4]), conn); // debug(1,"Sync timestamp is %u.",ntohl(*((uint32_t *)&packet[16]))); if (config.userSuppliedLatency) { if (config.userSuppliedLatency != conn->latency) { - debug(1, "Using the user-supplied latency: %lld.", config.userSuppliedLatency); + debug(1, "Using the user-supplied latency: %" PRId64 ".", config.userSuppliedLatency); } conn->latency = config.userSuppliedLatency; - } else if (packet[0] & - 0x10) { // only set latency if it's a packet just after a flush or resume - int64_t rtp_timestamp_less_latency = monotonic_timestamp(nctohl(&packet[4]), conn); - int64_t la = sync_rtp_timestamp - rtp_timestamp_less_latency + config.fixedLatencyOffset; + } else { + + // It seems that the second pair of bytes in the packet indicate whether a fixed + // delay of 11,025 frames should be added -- iTunes set this field to 7 and + // AirPlay sets it to 4. + + // The value of 11,025 (0.25 seconds) is a guess based on the "Audio-Latency" parameter + // returned by an AE. + + // Sigh, it would be nice to have a published protocol... + + uint16_t flags = nctohs(&packet[2]); + int64_t la = sync_rtp_timestamp - rtp_timestamp_less_latency; + if (flags == 7) + la += config.fixedLatencyOffset; + // debug(1,"Latency calculated from the sync packet is %" PRId64 " frames.",la); if ((conn->maximum_latency) && (conn->maximum_latency < la)) la = conn->maximum_latency; if ((conn->minimum_latency) && (conn->minimum_latency > la)) la = conn->minimum_latency; + + + const int max_frames = ((3 * BUFFER_FRAMES * 352)/4)-11025; + + if ((la < 0) || (la > max_frames)) { + warn("An out-of-range latency request of %" PRId64 + " frames was ignored. Must be %d frames or less (44,100 frames per second). Latency remains at %" PRId64 + " frames.", + la,max_frames,conn->latency); + } else { - if (la != conn->latency) { - conn->latency = la; - // debug(1, "New latency: %lld, sync latency: %lld, minimum latency: %lld, maximum " - // "latency: %lld, fixed offset: %lld.", - // la, sync_rtp_timestamp - rtp_timestamp_less_latency, conn->minimum_latency, - // conn->maximum_latency, config.fixedLatencyOffset); + if (la != conn->latency) { + conn->latency = la; + debug(2, "New latency detected: %" PRId64 ", sync latency: %" PRId64 + ", minimum latency: %" PRId64 ", maximum " + "latency: %" PRId64 ", fixed offset: %" PRId64 ".", + la, sync_rtp_timestamp - rtp_timestamp_less_latency, conn->minimum_latency, + conn->maximum_latency, config.fixedLatencyOffset); + } } } - // need to clarify this. - - if (packet[0] & 0x10) { - // if it's a packet right after a flush or resume - sync_rtp_timestamp += 352; // add frame_size -- can't see a reference to this anywhere, - // but it seems to get everything into sync. - // it's as if the first sync after a flush or resume is the timing of the next packet - // after the one whose RTP is given. Weird. - } - pthread_mutex_lock(&conn->reference_time_mutex); + + //this is for debugging + //uint64_t old_remote_reference_time = conn->remote_reference_timestamp_time; + //int64_t old_reference_timestamp = conn->reference_timestamp; + //int64_t old_latency_delayed_timestamp = conn->latency_delayed_timestamp; conn->remote_reference_timestamp_time = remote_time_of_sync; conn->reference_timestamp_time = remote_time_of_sync - conn->local_to_remote_time_difference; conn->reference_timestamp = sync_rtp_timestamp; + conn->latency_delayed_timestamp = rtp_timestamp_less_latency; pthread_mutex_unlock(&conn->reference_time_mutex); + + // this is for debugging + /* + uint64_t time_difference = remote_time_of_sync - old_remote_reference_time; + int64_t reference_frame_difference = sync_rtp_timestamp - old_reference_timestamp; + int64_t delayed_frame_difference = rtp_timestamp_less_latency - old_latency_delayed_timestamp; + + if (old_remote_reference_time) + debug(1,"Time difference: %" PRIu64 " reference and delayed frame differences: %" PRId64 " and %" PRId64 ", giving rates of %f and %f respectively.", + (time_difference*1000000)>>32,reference_frame_difference,delayed_frame_difference,(1.0*(reference_frame_difference*10000000))/((time_difference*10000000)>>32),(1.0*(delayed_frame_difference*10000000))/((time_difference*10000000)>>32)); + else + debug(1,"First sync received"); + */ + // debug(1,"New Reference timestamp and timestamp time..."); // get estimated remote time now // remote_time_now = local_time_now + local_to_remote_time_difference; @@ -734,7 +791,7 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, int cport, int tport, int *lsp inet_ntop(conn->connection_ip_family, self_addr, conn->self_ip_string, sizeof(conn->self_ip_string)); - debug(1, "Set up play connection from %s to self at %s on RTSP conversation thread %d.", + debug(2, "Set up play connection from %s to self at %s on RTSP conversation thread %d.", conn->client_ip_string, conn->self_ip_string, conn->connection_number); // set up a the record of the remote's control socket diff --git a/rtsp.c b/rtsp.c index ca6e48d4..a5d05ca4 100644 --- a/rtsp.c +++ b/rtsp.c @@ -1941,7 +1941,7 @@ static void *rtsp_conversation_thread_func(void *pconn) { playing_conn = NULL; pthread_mutex_unlock(&play_lock); } - debug(1, "RTSP conversation thread %d terminated.", conn->connection_number); + debug(2, "RTSP conversation thread %d terminated.", conn->connection_number); // please_shutdown = 0; conn->running = 0; return NULL;