cleanup of initial audio synchronization

This commit is contained in:
fduncanh
2022-05-01 17:26:38 -04:00
parent bdb949c6e2
commit 1379079220
5 changed files with 129 additions and 72 deletions

View File

@@ -266,7 +266,7 @@ raop_buffer_enqueue(raop_buffer_t *raop_buffer, unsigned char *data, unsigned sh
}
void *
raop_buffer_dequeue(raop_buffer_t *raop_buffer, unsigned int *length, uint32_t *timestamp, int no_resend) {
raop_buffer_dequeue(raop_buffer_t *raop_buffer, unsigned int *length, uint32_t *timestamp, unsigned short *seqnum, int no_resend) {
assert(raop_buffer);
/* Calculate number of entries in the current buffer */
@@ -299,6 +299,7 @@ raop_buffer_dequeue(raop_buffer_t *raop_buffer, unsigned int *length, uint32_t *
/* Return entry payload buffer */
*timestamp = entry->timestamp;
*seqnum = entry->seqnum;
*length = entry->payload_size;
entry->payload_size = 0;
void* data = entry->payload_data;
@@ -312,7 +313,7 @@ void raop_buffer_handle_resends(raop_buffer_t *raop_buffer, raop_resend_cb_t res
if (seqnum_cmp(raop_buffer->first_seqnum, raop_buffer->last_seqnum) < 0) {
int seqnum, count;
logger_log(raop_buffer->logger, LOGGER_DEBUG, "raop_buffer_handle_resends first_seqnum=%u last seqnum=%u", raop_buffer->first_seqnum, raop_buffer->last_seqnum);
for (seqnum = raop_buffer->first_seqnum; seqnum_cmp(seqnum, raop_buffer->last_seqnum) < 0; seqnum++) {
raop_buffer_entry_t *entry = &raop_buffer->entries[seqnum % RAOP_BUFFER_LENGTH];
if (entry->filled) {

View File

@@ -26,7 +26,7 @@ raop_buffer_t *raop_buffer_init(logger_t *logger,
const unsigned char *aeskey,
const unsigned char *aesiv);
int raop_buffer_enqueue(raop_buffer_t *raop_buffer, unsigned char *data, unsigned short datalen, uint32_t timestamp, int use_seqnum);
void *raop_buffer_dequeue(raop_buffer_t *raop_buffer, unsigned int *length, uint32_t *timestamp, int no_resend);
void *raop_buffer_dequeue(raop_buffer_t *raop_buffer, unsigned int *length, uint32_t *timestamp, unsigned short *seqnum, int no_resend);
void raop_buffer_handle_resends(raop_buffer_t *raop_buffer, raop_resend_cb_t resend_cb, void *opaque);
void raop_buffer_flush(raop_buffer_t *raop_buffer, int next_seq);

View File

@@ -271,7 +271,7 @@ raop_ntp_thread(void *arg)
byteutils_put_ntp_timestamp(request, 24, send_time);
int send_len = sendto(raop_ntp->tsock, (char *)request, sizeof(request), 0,
(struct sockaddr *) &raop_ntp->remote_saddr, raop_ntp->remote_saddr_len);
logger_log(raop_ntp->logger, LOGGER_DEBUG, "raop_ntp send_len = %d, now = %llu", send_len, send_time);
logger_log(raop_ntp->logger, LOGGER_DEBUG, "\nraop_ntp send_len = %d, now = %llu", send_len, send_time);
if (send_len < 0) {
logger_log(raop_ntp->logger, LOGGER_ERR, "raop_ntp error sending request");
} else {
@@ -295,7 +295,7 @@ raop_ntp_thread(void *arg)
timeout_counter = 0;
char *str = utils_data_to_string(response, response_len, 16);
logger_log(raop_ntp->logger, LOGGER_DEBUG, "raop_ntp receive time type_t packetlen = %d\n%s", response_len, str);
logger_log(raop_ntp->logger, LOGGER_DEBUG, "raop_ntp receive time type_t=%d packetlen = %d\n%s", response[1] &~0x80, response_len, str);
free(str);
// Local time of the server when the NTP request packet leaves the server

View File

@@ -34,12 +34,15 @@
#define RAOP_RTP_SAMPLE_RATE (44100.0 / 1000000.0)
#define RAOP_RTP_SYNC_DATA_COUNT 8
#define SEC 1000000
#define DELAY 500000 //this is empirical, there is about a 0.5 sec delay in initial audio timing before a clock sync event
#define DELAY_AAC 500000 //this is empirical, there is about a 0.5 sec delay in initial audio timing before a clock sync event
#define DELAY_ALAC 2000000 //this is empirical, there is about a 2.0 sec delay in initial audio timing before a clock sync event
typedef struct raop_rtp_sync_data_s {
uint64_t ntp_time; // The local wall clock time at the time of rtp_time
uint32_t rtp_time; // The remote rtp clock time corresponding to ntp_time
uint64_t ntp_time; // The local wall clock time at the time of rtp_time
uint32_t rtp_time; // The remote rtp clock time corresponding to ntp_time
uint32_t rtp_epoch; // The epoch of the remote rtp clock (rtp epoch is about 27 hours)
} raop_rtp_sync_data_t;
struct raop_rtp_s {
@@ -50,6 +53,7 @@ struct raop_rtp_s {
raop_ntp_t *ntp;
double rtp_sync_scale;
int64_t rtp_sync_offset;
uint32_t rtp_sync_epoch;
raop_rtp_sync_data_t sync_data[RAOP_RTP_SYNC_DATA_COUNT];
int sync_data_index;
@@ -156,9 +160,11 @@ raop_rtp_init(logger_t *logger, raop_callbacks_t *callbacks, raop_ntp_t *ntp, co
raop_rtp->rtp_sync_offset = 0;
raop_rtp->rtp_sync_scale = RAOP_RTP_SAMPLE_RATE;
raop_rtp->sync_data_index = 0;
raop_rtp->rtp_sync_epoch = 0;
for (int i = 0; i < RAOP_RTP_SYNC_DATA_COUNT; ++i) {
raop_rtp->sync_data[i].ntp_time = 0;
raop_rtp->sync_data[i].rtp_time = 0;
raop_rtp->sync_data[i].rtp_epoch = 0;
}
memcpy(&raop_rtp->callbacks, callbacks, sizeof(raop_callbacks_t));
@@ -370,17 +376,32 @@ raop_rtp_process_events(raop_rtp_t *raop_rtp, void *cb_data)
return 0;
}
void raop_rtp_sync_clock(raop_rtp_t *raop_rtp, uint32_t rtp_time, uint64_t ntp_time) {
void raop_rtp_sync_clock(raop_rtp_t *raop_rtp, uint64_t ntp_time, int64_t ntp_start_time, uint32_t rtp_time, int shift) {
const double epoch_length = (double) 0x100000000ULL;
if (rtp_time < raop_rtp->sync_data[raop_rtp->sync_data_index].rtp_time) {
raop_rtp->rtp_sync_epoch++;
}
raop_rtp->sync_data_index = (raop_rtp->sync_data_index + 1) % RAOP_RTP_SYNC_DATA_COUNT;
raop_rtp->sync_data[raop_rtp->sync_data_index].rtp_time = rtp_time;
raop_rtp->sync_data[raop_rtp->sync_data_index].ntp_time = ntp_time;
raop_rtp->sync_data[raop_rtp->sync_data_index].rtp_epoch = raop_rtp->rtp_sync_epoch;
uint32_t valid_data_count = 0;
valid_data_count = 0;
int64_t total_offsets = 0;
double rtp_offset;
for (int i = 0; i < RAOP_RTP_SYNC_DATA_COUNT; ++i) {
if (raop_rtp->sync_data[i].ntp_time == 0) continue;
total_offsets += (int64_t) (((double) (raop_rtp->sync_data[i].rtp_time - 11025)) / raop_rtp->rtp_sync_scale) - raop_rtp->sync_data[i].ntp_time;
rtp_offset = (((double) raop_rtp->sync_data[i].rtp_time) + ((double) shift));
if (raop_rtp->sync_data[i].rtp_epoch) {
rtp_offset += raop_rtp->sync_data[i].rtp_epoch * epoch_length;
}
total_offsets += (int64_t) (rtp_offset / raop_rtp-> rtp_sync_scale);
if (raop_rtp->sync_data[i].ntp_time > ntp_start_time) {
total_offsets -= raop_rtp->sync_data[i].ntp_time - ntp_start_time;
} else {
total_offsets += ntp_start_time - raop_rtp->sync_data[i].ntp_time;
}
valid_data_count++;
}
int64_t avg_offset = total_offsets / valid_data_count;
@@ -390,10 +411,6 @@ void raop_rtp_sync_clock(raop_rtp_t *raop_rtp, uint32_t rtp_time, uint64_t ntp_t
logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp sync correction=%lld", correction);
}
uint64_t raop_rtp_convert_rtp_time(raop_rtp_t *raop_rtp, uint32_t rtp_time) {
return (uint64_t) (((double) rtp_time) / raop_rtp->rtp_sync_scale) - raop_rtp->rtp_sync_offset;
}
static THREAD_RETVAL
raop_rtp_thread_udp(void *arg)
{
@@ -402,10 +419,16 @@ raop_rtp_thread_udp(void *arg)
unsigned int packetlen;
struct sockaddr_storage saddr;
socklen_t saddrlen;
uint32_t rtp_start_time = 0;
uint32_t rtp_prev = 0;
uint64_t ntp_start_time = 0;
bool first_packet = true;
int64_t ntp_start_time = 0;
bool have_synced = false;
bool no_data = true;
/* the 44.1 kHZ rtp_time epoch is about 27 hours */
bool have_rtp_time = false;
int64_t rtp_time; /* will only change by small amounts to track rtp epoch changes */
uint64_t epoch_length = 0x01;
epoch_length = epoch_length << 32;
int64_t half_epoch = (int64_t) epoch_length/2;
uint32_t prev_rtp_timestamp = 0;
assert(raop_rtp);
while(1) {
fd_set rfds;
@@ -448,57 +471,66 @@ raop_rtp_thread_udp(void *arg)
memcpy(&raop_rtp->control_saddr, &saddr, saddrlen);
raop_rtp->control_saddr_len = saddrlen;
int type_c = packet[1] & ~0x80;
logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp type_c 0x%02x, packetlen = %d", type_c, packetlen);
logger_log(raop_rtp->logger, LOGGER_DEBUG, "\nraop_rtp type_c 0x%02x, packetlen = %d", type_c, packetlen);
if (type_c == 0x56) {
/* Handle resent data packet */
const int offset = 4;
uint32_t rtp_timestamp = byteutils_get_int_be(packet + offset, 4);
logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp audio resent: rtp=%u", rtp_timestamp);
logger_log(raop_rtp->logger, LOGGER_INFO, "raop_rtp audio resent: rtp=%u", rtp_timestamp);
int result = raop_buffer_enqueue(raop_rtp->buffer, packet + offset, packetlen - offset, rtp_timestamp, 1);
assert(result >= 0);
} else if (type_c == 0x54 && packetlen >= 20) {
// The unit for the rtp clock is 1 / sample rate = 1 / 44100
uint32_t sync_rtp = byteutils_get_int_be(packet, 4) - rtp_start_time;
/* packet[0] = 0x90 (first sync) or 0x80 (subsequent ones) *
* packet[1:3] = 0xd4, 0xd4 && ~0x80 = type 54 *
* packet[2:3] = 0x00 0x04 *
* packet[4:7] : sync_rtp big-endian uint32_t) *
* packet[8:15]: remote ntp timestamp (uint64 big-endian) *
* packet[16:20]: next_rtp big-endian uint32_t) *
* next_rtp = sync_rtp + 7497 = 441 * 17 (0.17 sec) for AAC-ELD *
* next_rtp = sync_rtp + 77175 = 441 * 175 (1.75 sec) for ALAC */
// The unit for the rtp clock is 1 / sample rate = 1 / 44100
uint32_t sync_rtp = byteutils_get_int_be(packet, 4);
have_synced = true;
uint64_t sync_ntp_raw = byteutils_get_long_be(packet, 8);
// uint32_t next_rtp = byteutils_get_int_be(packet, 16) - rtp_start_time;
// next_rtp = sync_rtp + 7497 = 441 * 17 (0.17 sec) for AAC-ELD
// next_rtp = sync_rtp + 77175 = 441 * 175 (1.75 sec) for ALAC
/* subtract 44100/4 from sync_rtp */
char *str = utils_data_to_string(packet, packetlen, 16);
logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp_sync_clock\n%s", str);
free(str);
//sync_rtp -= 11025; this shift is moved to raop_rtp_sync_clock
uint64_t sync_ntp_remote = raop_ntp_timestamp_to_micro_seconds(sync_ntp_raw, true);
uint64_t sync_ntp_local = raop_ntp_convert_remote_time(raop_rtp->ntp, sync_ntp_remote);
raop_rtp_sync_clock(raop_rtp, sync_rtp, sync_ntp_local - ntp_start_time);
logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp sync: ntp=%llu, local ntp: %llu, rtp=%u",
sync_ntp_remote, sync_ntp_local, sync_rtp);
int64_t shift;
switch (raop_rtp->ct) {
case 0x08: /*AAC-ELD */
shift = -11025; /* 44100/4 */
break;
default:
break;
}
raop_rtp_sync_clock(raop_rtp, sync_ntp_local, ntp_start_time, sync_rtp, shift);
char *str = utils_data_to_string(packet, packetlen, 20);
logger_log(raop_rtp->logger, LOGGER_DEBUG,
"raop_rtp sync: client ntp=%llu, local ntp: %llu, local ntp_start_time %lld, sync_rtp=%u\n%s",
sync_ntp_remote, sync_ntp_local, ntp_start_time, sync_rtp, str);
free(str);
} else {
logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp unknown packet");
}
}
/* rtp data packets: *
* packet[0] 0x80 (both AAC-ELD and ALAC) *
* packet[1] 0x60 = 96 *
* packet[2:3] (be short) seqnum *
* packet[4:7] (be int) rtp timestamp *
* packet[8:11] 0x00 0x00 0x00 0x00 *
* packet12:] encrypted audio payload */
/* rtp un-resent audio data packets: *
* packet[0] 0x80 (both AAC-ELD and ALAC) *
* packet[1] 0x60 = 96 *
* packet[2:3] seqnum (big-endian unsigned short) *
* packet[4:7] rtp timestamp (big-endian unsigned int) *
* packet[8:11] 0x00 0x00 0x00 0x00 *
* packet[12:packetlen - 1] encrypted audio payload */
/* consecutive AAC-ELD rtp timestamps differ by 480 *
* consecutive ALAC rtp timestamps differ by 352 *
* These are the respective spf (samples per frame) values *
* both have PCM uncompressed sampling rate = 441000 Hz */
/* consecutive AAC-ELD rtp timestamps differ by spf = 480 *
* consecutive ALAC rtp timestamps differ by spf = 352 *
* both have PCM uncompressed sampling rate = 441000 Hz */
/* clock time in microseconds advances at (rtp_timestamp * 1000000)/44100 between frames */
/* clock time in microseconds advances at (rtp_timestamp * 1000000)/44100 between frames */
/* every AAC-ELD packet is sent three times: 0 0 1 0 1 2 1 2 3 2 3 4 ..... *
* (after decoding AAC-ELD into PCM, the sound frame is three times bigger) *
* ALAC packets are sent once only 0 1 2 3 4 5 ... */
/* every AAC-ELD packet is sent three times: 0 0 1 0 1 2 1 2 3 2 3 4 ... *
* (after decoding AAC-ELD into PCM, the sound frame is three times bigger) *
* ALAC packets are sent once only 0 1 2 3 4 5 ... */
if (FD_ISSET(raop_rtp->dsock, &rfds)) {
//logger_log(raop_rtp->logger, LOGGER_INFO, "Would have data packet in queue");
@@ -513,16 +545,28 @@ raop_rtp_thread_udp(void *arg)
// Len = 16 appears if there is no time
if ( packetlen >= 12) {
int no_resend = (raop_rtp->control_rport == 0); /* true when control_rport is not set */
uint32_t rtp_timestamp = byteutils_get_int_be(packet, 4) - rtp_start_time;
uint32_t rtp_timestamp = byteutils_get_int_be(packet, 4);
if (packetlen == 16 && packet[12] == 0x00 && packet[13] == 0x68 && packet[14] == 0x34 && packet[15] == 0x00) {
/* skip packet */
} else {
if (first_packet) {
ntp_start_time = raop_ntp_get_local_time(raop_rtp->ntp) + DELAY; /* DELAY = 500000 (0.5 sec) is empirical choice */
logger_log(raop_rtp->logger, LOGGER_DEBUG, "first audio packet, using DELAY= %d", DELAY);
rtp_start_time = rtp_timestamp;
rtp_timestamp = 0;
first_packet = false;
if (no_data) {
no_data = false;
logger_log(raop_rtp->logger, LOGGER_DEBUG, "First audio packet received");
if (have_synced == false) {
/* until the first rpt sync occurs, we don't know the exact client ntp timestamp that matches the client rtp timesamp */
int64_t ntp_time = ((uint64_t) raop_ntp_get_local_time(raop_rtp->ntp)) - ntp_start_time;
switch (raop_rtp->ct) {
case 0x02:
ntp_time += DELAY_ALAC; /* DELAY = 2000000 (2.0 sec) is empirical choice for ALAC */
break;
case 0x08:
ntp_time += DELAY_AAC; /* DELAY = 500000 (0.5 sec) is empirical choice for AAC-ELD */
break;
default:
break;
}
raop_rtp->rtp_sync_offset = ((int64_t) (((double) rtp_timestamp) / raop_rtp->rtp_sync_scale)) - ntp_time;
}
}
int result = raop_buffer_enqueue(raop_rtp->buffer, packet, packetlen, rtp_timestamp, 1);
assert(result >= 0);
@@ -531,23 +575,33 @@ raop_rtp_thread_udp(void *arg)
void *payload = NULL;
unsigned int payload_size;
uint32_t timestamp;
while ((payload = raop_buffer_dequeue(raop_rtp->buffer, &payload_size, &timestamp, no_resend))) {
/* rpt_timestamp wraps around to zero after about 27 hours */
if (timestamp < rtp_prev) {
const uint64_t shift = 0x100000000UL;
ntp_start_time += (uint64_t) (((double) (shift))/raop_rtp->rtp_sync_scale);
}
rtp_prev = timestamp;
uint64_t ntp_timestamp = ntp_start_time + raop_rtp_convert_rtp_time(raop_rtp, timestamp);
aac_decode_struct aac_data;
unsigned short seqnum;
while ((payload = raop_buffer_dequeue(raop_rtp->buffer, &payload_size, &timestamp, &seqnum, no_resend))) {
if (have_rtp_time == false) {
rtp_time = (int64_t) timestamp;
have_rtp_time = true;
prev_rtp_timestamp = timestamp;
}
int64_t rtp_time_increment = (int64_t) (timestamp - prev_rtp_timestamp);
prev_rtp_timestamp = timestamp;
if (rtp_time_increment > half_epoch) {
rtp_time_increment -= (int64_t) epoch_length ;
} else if (rtp_time_increment < -half_epoch) {
rtp_time_increment += (int64_t) epoch_length;
}
rtp_time += rtp_time_increment; /* this is rtp_epoch * epoch_length + timestamp */
int64_t ntp_timestamp = ntp_start_time - raop_rtp->rtp_sync_offset;
ntp_timestamp += (int64_t) ((double) rtp_time) / raop_rtp->rtp_sync_scale;
aac_decode_struct aac_data;
aac_data.data_len = payload_size;
aac_data.data = payload;
aac_data.pts = ntp_timestamp;
aac_data.pts = (uint64_t) ntp_timestamp;
raop_rtp->callbacks.audio_process(raop_rtp->callbacks.cls, raop_rtp->ntp, &aac_data);
free(payload);
uint64_t ntp_now = raop_ntp_get_local_time(raop_rtp->ntp);
logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp audio: ntp = %llu, now = %llu, latency=%lld, rtp=%u",
ntp_timestamp, ntp_now, ((int64_t) ntp_now) - ((int64_t) ntp_timestamp), rtp_timestamp);
int64_t latency = ((int64_t) ntp_now) - ntp_timestamp;
logger_log(raop_rtp->logger, LOGGER_DEBUG, "raop_rtp audio: ntp = %8.6f, now = %8.6f latency= %8.6f, rtp_time=%lld seqnum = %u",
((double) ntp_timestamp ) / SEC, ((double) ntp_now) / SEC, ((double) latency) / SEC, rtp_time, seqnum);
}
/* Handle possible resend requests */

View File

@@ -32,6 +32,7 @@
#include "utils.h"
#include "plist/plist.h"
#define SEC 1000000
/* for MacOS, where SOL_TCP and TCP_KEEPIDLE are not defined */
#if !defined(SOL_TCP) && defined(IPPROTO_TCP)
#define SOL_TCP IPPROTO_TCP
@@ -342,8 +343,9 @@ raop_rtp_mirror_thread(void *arg)
uint64_t ntp_timestamp = raop_ntp_convert_remote_time(raop_rtp_mirror->ntp, ntp_timestamp_remote);
uint64_t ntp_now = raop_ntp_get_local_time(raop_rtp_mirror->ntp);
logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror video ntp = %llu, now = %llu, latency = %lld",
ntp_timestamp, ntp_now, ((int64_t) ntp_now) - ((int64_t) ntp_timestamp));
int64_t latency = ((int64_t) ntp_now) - ((int64_t) ntp_timestamp);
logger_log(raop_rtp_mirror->logger, LOGGER_DEBUG, "raop_rtp_mirror video ntp = %8.6f, now = %8.6f, latency = %8.6f",
((double) ntp_timestamp) / SEC, ((double) ntp_now) / SEC, ((double) latency) / SEC);
#ifdef DUMP_H264
fwrite(payload, payload_size, 1, file_source);