nils/shairport-sync
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

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.

Browse Source
This commit is contained in:
Mike Brady
2018-04-02 16:42:46 +01:00
parent cb69c1dd2e
commit 8bf83c149f
9 changed files with 135 additions and 66 deletions
Download Patch File Download Diff File Expand all files Collapse all files
common.c
+8 -1
View File
@@ -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() {
common.h
+3 -1
View File
@@ -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
dacp.c
+15 -15
View File
@@ -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:
dbus-service.c
+1 -1
View File
@@ -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)
metadata_hub.c
+1 -1
View File
@@ -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");
}
}
player.c
+9 -7
View File
@@ -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();
player.h
+2 -1
View File
@@ -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;
rtp.c
+95 -38
View File
@@ -25,9 +25,14 @@
* OTHER DEALINGS IN THE SOFTWARE.
*/
#include "rtp.h"
#include "common.h"
#include "player.h"
#include "rtsp.h"
#include <arpa/inet.h>
#include <errno.h>
#include <fcntl.h>
#include <inttypes.h>
#include <math.h>
#include <memory.h>
#include <netdb.h>
@@ -39,11 +44,6 @@
#include <time.h>
#include <unistd.h>
#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;obfc<plen;obfc++) {
sprintf(obfp,"%02X",packet[obfc]);
obfp+=2;
};
*obfp=0;
debug(1,"Sync Packet Received: \"%s\"",obf);
*/
/*
// the following stanza is for debugging only -- normally commented out.
{
char obf[4096];
char *obfp = obf;
int obfc;
for (obfc = 0; obfc < plen; obfc++) {
sprintf(obfp, "%02X", packet[obfc]);
obfp += 2;
};
*obfp = 0;
// get raw timestamp information
// I think that a good way to understand these timestamps is that
// (1) the rtlt below is the timestamp of the frame that should be playing at the client-time specified in the packet if there was no delay
// and (2) that the rt below is the timestamp of the frame that should be playing at the client-time specified in the packet on this device taking account of the delay
// Thus, (3) the latency can be calculated by subtracting the second from the first.
// There must be more to it -- there something missing.
// In addition, it seems that if the value of the short represented by the second pair of bytes in the packe is 7
// then an extra time lag is expected to be added, presumably by the AirPort Express. Best guess is that this delay is 11,025 frames.
uint32_t rtlt = nctohl(&packet[4]); // raw timestamp less latency
uint32_t rt = nctohl(&packet[16]); // raw timestamp
uint32_t fl = nctohs(&packet[2]); //
// debug(1,"Sync Packet of %d bytes received: \"%s\", flags: %d, timestamps %u and %u, giving a latency of %d frames.",plen,obf,fl,rt,rtlt,rt-rtlt);
// debug(1,"Monotonic timestamps are: %" PRId64 " and %" PRId64 " respectively.",monotonic_timestamp(rt, conn),monotonic_timestamp(rtlt, conn));
}
*/
if (conn->local_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 != 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 < 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(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
rtsp.c
+1 -1
View File
@@ -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;