From 6d7e0aa2a6ee411a14cca20490bd5a3472e8b923 Mon Sep 17 00:00:00 2001 From: BewickPlace Date: Sat, 15 Mar 2014 14:56:09 +0000 Subject: [PATCH 1/8] Add timestamp to debug and warning messages --- common.c | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/common.c b/common.c index 0bfbef100..437b1c1b9 100644 --- a/common.c +++ b/common.c @@ -35,6 +35,7 @@ #include #include "common.h" #include "daemon.h" +#include shairport_cfg config; @@ -57,7 +58,10 @@ void die(char *format, ...) { } void warn(char *format, ...) { - fprintf(stderr, "WARNING: "); + time_t rawtime; + + time( &rawtime); + fprintf(stderr, "%s WARNING: ", strtok(ctime(&rawtime),"\n")); va_list args; va_start(args, format); vfprintf(stderr, format, args); @@ -66,8 +70,12 @@ void warn(char *format, ...) { } void debug(int level, char *format, ...) { + time_t rawtime; if (level > debuglev) return; + + time( &rawtime); + fprintf(stderr, "%s DEBUG: ", strtok(ctime(&rawtime),"\n")); va_list args; va_start(args, format); vfprintf(stderr, format, args); From 97a806d850041e032a339d7bb8248a57571e460b Mon Sep 17 00:00:00 2001 From: BewickPlace Date: Sat, 15 Mar 2014 15:17:17 +0000 Subject: [PATCH 2/8] Use WiringPi to control GPIO pin 11 to signal playing/stopped (for Amp sleep control) --- configure | 2 +- rtsp.c | 7 +++++++ 2 files changed, 8 insertions(+), 1 deletion(-) diff --git a/configure b/configure index 2ed3df229..45cf03a8a 100755 --- a/configure +++ b/configure @@ -6,7 +6,7 @@ rm -f config.mk config.h echo "// automatically generated file" > config.h -LDFLAGS="${LDFLAGS} -lm -lpthread" +LDFLAGS="${LDFLAGS} -lm -lpthread -lwiringPi" export_config() { diff --git a/rtsp.c b/rtsp.c index 938862d4b..ce4bf73ba 100644 --- a/rtsp.c +++ b/rtsp.c @@ -45,6 +45,7 @@ #include "player.h" #include "rtp.h" #include "mdns.h" +#include "wiringPi.h" #ifdef AF_INET6 #define INETx_ADDRSTRLEN INET6_ADDRSTRLEN @@ -372,6 +373,7 @@ static void handle_teardown(rtsp_conn_info *conn, rtsp_message *req, rtsp_message *resp) { if (!rtsp_playing()) return; + digitalWrite(11, 1); /* On TearDown: Turn Ampliefier OFF - enable sleep */ resp->respcode = 200; msg_add_header(resp, "Connection", "close"); please_shutdown = 1; @@ -409,6 +411,7 @@ static void handle_setup(rtsp_conn_info *conn, int sport = rtp_setup(&conn->remote, cport, tport); if (!sport) return; + digitalWrite(11, 0); /* On Set-up: Turn Amplifier ON - disable sleep */ player_play(&conn->stream); @@ -816,6 +819,10 @@ void rtsp_listen_loop(void) { maxfd = sockfd[i]; } + wiringPiSetupPhys(); /* Listen Loop: Initilise the GPIO access - use physical pin numbers */ + pinMode(11, OUTPUT); /* let's use Pin 11 */ + digitalWrite(11, 1); /* turn Amplifier Sleep mode ON */ + mdns_register(); printf("Listening for connections.\n"); From 6373b04c0cf8bb2c9dd7646a59b516ce8be7e379 Mon Sep 17 00:00:00 2001 From: BewickPlace Date: Sat, 15 Mar 2014 16:20:44 +0000 Subject: [PATCH 3/8] Adjust Desired_fill calculation --- player.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/player.c b/player.c index bc569c338..1131af254 100644 --- a/player.c +++ b/player.c @@ -315,9 +315,10 @@ static void bf_est_update(short fill) { return; } else if (fill_count == 1000) { // this information could be used to help estimate our effective latency? + desired_fill = (2*config.buffer_start_fill) - desired_fill; debug(1, "established desired fill of %f frames, " "so output chain buffered about %f frames\n", desired_fill, - config.buffer_start_fill - desired_fill); + desired_fill - config.buffer_start_fill); fill_count++; } From 37f1ecaaa8f5e7d160838b55683ba1f4f91c1748 Mon Sep 17 00:00:00 2001 From: BewickPlace Date: Sat, 15 Mar 2014 17:50:30 +0000 Subject: [PATCH 4/8] Force resync and tidy behaviour on Underrun and Overrun --- player.c | 51 +++++++++++++++++++++++++++++++++++++++++---------- 1 file changed, 41 insertions(+), 10 deletions(-) diff --git a/player.c b/player.c index 1131af254..902927949 100644 --- a/player.c +++ b/player.c @@ -100,6 +100,17 @@ static void ab_resync(void) { ab_buffering = 1; } +// reset the audio frames in the range to NOT ready +static void ab_reset(seq_t from, seq_t to) { + abuf_t *abuf = 0; + + while (seq_diff(from, to)) { + abuf = audio_buffer + BUFIDX(from); + abuf->ready = 0; + from++; + } +} + // the sequence numbers will wrap pretty often. // this returns true if the second arg is after the first static inline int seq_order(seq_t a, seq_t b) { @@ -203,13 +214,31 @@ void player_put_packet(seq_t seqno, uint8_t *data, int len) { abuf = audio_buffer + BUFIDX(seqno); ab_write = seqno; } else if (seq_order(ab_write, seqno)) { // newer than expected - rtp_request_resend(ab_write+1, seqno-1); - abuf = audio_buffer + BUFIDX(seqno); - ab_write = seqno; + // Be careful with new packets that are in advance + // Those more than a buffer size in advance should cause a resync + // When buffering the valid threshold should be the buffer fill target itself + if (seq_diff(ab_read, seqno) > (ab_buffering ? config.buffer_start_fill : BUFFER_FRAMES)) { + warn("out of range re-sync %04X (%04X:%04%)", seqno, ab_read, ab_write); + ab_resync(); + ab_synced = 1; + ab_read = seqno; + ab_write = seqno; + abuf = audio_buffer + BUFIDX(seqno); + } else { + debug(1, "advance packet %04X (%04X:%04X)\n", seqno, ab_read, ab_write); + + rtp_request_resend(ab_write+1, seqno-1); + abuf = audio_buffer + BUFIDX(seqno); + ab_write = seqno; + } } else if (seq_order(ab_read, seqno)) { // late but not yet played abuf = audio_buffer + BUFIDX(seqno); + if (abuf->ready) { // discard this frame if frame previously received + abuf =0; + debug(1, "duplicate packet %04X (%04X:%04X)\n", seqno, ab_read, ab_write); + } } else { // too late. - debug(1, "late packet %04X (%04X:%04X)", seqno, ab_read, ab_write); + debug(1, "late packet %04X (%04X:%04X)\n", seqno, ab_read, ab_write); } buf_fill = seq_diff(ab_read, ab_write); pthread_mutex_unlock(&ab_mutex); @@ -221,9 +250,8 @@ void player_put_packet(seq_t seqno, uint8_t *data, int len) { pthread_mutex_lock(&ab_mutex); if (ab_buffering && buf_fill >= config.buffer_start_fill) { - debug(1, "buffering over. starting play\n"); + debug(1, "buffering over. starting play (%04X:%04X)\n", ab_read, ab_write); ab_buffering = 0; - bf_est_reset(buf_fill); } pthread_mutex_unlock(&ab_mutex); } @@ -354,14 +382,16 @@ static short *buffer_get_frame(void) { buf_fill = seq_diff(ab_read, ab_write); if (buf_fill < 1 || !ab_synced) { if (buf_fill < 1) - warn("underrun."); - ab_buffering = 1; + warn("underrun %i (%04X:%04X)", buf_fill, ab_read, ab_write); + ab_resync(); pthread_mutex_unlock(&ab_mutex); return 0; } if (buf_fill >= BUFFER_FRAMES) { // overrunning! uh-oh. restart at a sane distance - warn("overrun."); + warn("overrun %i (%04X:%04X)", buf_fill, ab_read, ab_write); + read = ab_read; ab_read = ab_write - config.buffer_start_fill; + ab_reset(read, ab_read); // reset any ready frames in those we've skipped } read = ab_read; ab_read++; @@ -382,7 +412,7 @@ static short *buffer_get_frame(void) { abuf_t *curframe = audio_buffer + BUFIDX(read); if (!curframe->ready) { - debug(1, "missing frame %04X.", read); + debug(1, "missing frame %04X\n", read); memset(curframe->data, 0, FRAME_BYTES(frame_size)); } curframe->ready = 0; @@ -515,6 +545,7 @@ int player_play(stream_cfg *stream) { #ifdef FANCY_RESAMPLING init_src(); #endif + bf_est_reset(config.buffer_start_fill); // initialise frame matching algorithm - only once per read thread (semaphore not required at this point) please_stop = 0; command_start(); From 1053c533c1facbd039d59cc84588ef5a392fee78 Mon Sep 17 00:00:00 2001 From: BewickPlace Date: Sat, 15 Mar 2014 22:34:53 +0000 Subject: [PATCH 5/8] Focus Resend/Last Chance Resend Algorithm --- player.c | 37 +++++++++++++++++++++++++++++-------- rtp.c | 2 +- 2 files changed, 30 insertions(+), 9 deletions(-) diff --git a/player.c b/player.c index 902927949..1b8b9f4e4 100644 --- a/player.c +++ b/player.c @@ -199,13 +199,28 @@ static void free_buffer(void) { free(audio_buffer[i].data); } + // Calculate the boundary threshold for resends dependant on buffer size + // FOCUS_BOUNDARY is the preferred threshold if this can be accomodated + // Above the boundary resends are handled as a result of advance packets + // Below the boundary resends are handled in Last-Chance algorithm +#define FOCUS_BOUNDARY 128 + +static int resend_focus(int fill){ + if ((fill > FOCUS_BOUNDARY) && + ((fill/2) < FOCUS_BOUNDARY)) { + return FOCUS_BOUNDARY; + } else { + return (fill/2); + } +} + void player_put_packet(seq_t seqno, uint8_t *data, int len) { abuf_t *abuf = 0; int16_t buf_fill; pthread_mutex_lock(&ab_mutex); if (!ab_synced) { - debug(2, "syncing to first seqno %04X\n", seqno); + debug(1, "syncing to first seqno %04X\n", seqno); ab_write = seqno-1; ab_read = seqno; ab_synced = 1; @@ -218,16 +233,21 @@ void player_put_packet(seq_t seqno, uint8_t *data, int len) { // Those more than a buffer size in advance should cause a resync // When buffering the valid threshold should be the buffer fill target itself if (seq_diff(ab_read, seqno) > (ab_buffering ? config.buffer_start_fill : BUFFER_FRAMES)) { - warn("out of range re-sync %04X (%04X:%04%)", seqno, ab_read, ab_write); + warn("out of range re-sync %04X (%04X:%04X)", seqno, ab_read, ab_write); ab_resync(); ab_synced = 1; ab_read = seqno; ab_write = seqno; abuf = audio_buffer + BUFIDX(seqno); } else { - debug(1, "advance packet %04X (%04X:%04X)\n", seqno, ab_read, ab_write); - - rtp_request_resend(ab_write+1, seqno-1); + // Accept advance packet, but only request resends + // if in upper portion of the frame buffer + if(seq_diff(ab_read, seqno) >= resend_focus(config.buffer_start_fill)) { + debug(1, "advance packet - request resend, %04X (%04X:%04X)\n", seqno, ab_read, ab_write); + rtp_request_resend(ab_write+1, seqno-1); + } else { + debug(1, "advance packet - no resend %04X (%04X:%04X)\n", seqno, ab_read, ab_write); + } abuf = audio_buffer + BUFIDX(seqno); ab_write = seqno; } @@ -398,14 +418,15 @@ static short *buffer_get_frame(void) { buf_fill = seq_diff(ab_read, ab_write); bf_est_update(buf_fill); - // check if t+16, t+32, t+64, t+128, ... (buffer_start_fill / 2) + // check if t+16, t+32, t+64, t+128, ... resend focus boundary // packets have arrived... last-chance resend if (!ab_buffering) { - for (i = 16; i < (config.buffer_start_fill / 2); i = (i * 2)) { + for (i = 16; i <= resend_focus(config.buffer_start_fill); i = (i * 2)) { next = ab_read + i; abuf = audio_buffer + BUFIDX(next); - if (!abuf->ready) { + if ((!abuf->ready) && (next <= (ab_write+1))){ rtp_request_resend(next, next); + debug(1, "last chance resend T+%i, %04X (%04X:%04X)\n", i, next, ab_read, ab_write); } } } diff --git a/rtp.c b/rtp.c index 51b846d5d..2d45476bc 100644 --- a/rtp.c +++ b/rtp.c @@ -179,7 +179,7 @@ void rtp_request_resend(seq_t first, seq_t last) { if (!running) die("rtp_request_resend called without active stream!"); - debug(1, "requesting resend on %d packets (%04X:%04X)\n", + debug(2, "requesting resend on %d packets (%04X:%04X)\n", seq_diff(first,last) + 1, first, last); char req[8]; // *not* a standard RTCP NACK From 3be162603bdb5d37c8f4312acaa3cd9d0bac86a3 Mon Sep 17 00:00:00 2001 From: BewickPlace Date: Tue, 18 Mar 2014 13:09:25 +0000 Subject: [PATCH 6/8] Refocus Last-Chance resend within received range --- player.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/player.c b/player.c index 1b8b9f4e4..91d16f56b 100644 --- a/player.c +++ b/player.c @@ -424,7 +424,7 @@ static short *buffer_get_frame(void) { for (i = 16; i <= resend_focus(config.buffer_start_fill); i = (i * 2)) { next = ab_read + i; abuf = audio_buffer + BUFIDX(next); - if ((!abuf->ready) && (next <= (ab_write+1))){ + if ((!abuf->ready) && (next <= ab_write)){ rtp_request_resend(next, next); debug(1, "last chance resend T+%i, %04X (%04X:%04X)\n", i, next, ab_read, ab_write); } From c286afa8632e4f17a6dc6ee771bfff3658cbd1b2 Mon Sep 17 00:00:00 2001 From: BewickPlace Date: Tue, 18 Mar 2014 21:49:31 +0000 Subject: [PATCH 7/8] Adjust Last Chance/Resend algorithm --- player.c | 20 ++++++++------------ 1 file changed, 8 insertions(+), 12 deletions(-) diff --git a/player.c b/player.c index 91d16f56b..88351ad72 100644 --- a/player.c +++ b/player.c @@ -201,8 +201,8 @@ static void free_buffer(void) { // Calculate the boundary threshold for resends dependant on buffer size // FOCUS_BOUNDARY is the preferred threshold if this can be accomodated - // Above the boundary resends are handled as a result of advance packets - // Below the boundary resends are handled in Last-Chance algorithm + // Resends are typically handled as a result of advance packets + // However below the boundary resends are also handled in Last-Chance algorithm #define FOCUS_BOUNDARY 128 static int resend_focus(int fill){ @@ -240,14 +240,10 @@ void player_put_packet(seq_t seqno, uint8_t *data, int len) { ab_write = seqno; abuf = audio_buffer + BUFIDX(seqno); } else { - // Accept advance packet, but only request resends - // if in upper portion of the frame buffer - if(seq_diff(ab_read, seqno) >= resend_focus(config.buffer_start_fill)) { - debug(1, "advance packet - request resend, %04X (%04X:%04X)\n", seqno, ab_read, ab_write); - rtp_request_resend(ab_write+1, seqno-1); - } else { - debug(1, "advance packet - no resend %04X (%04X:%04X)\n", seqno, ab_read, ab_write); - } + debug(1, "advance packet %04X (%04X:%04X)\n", seqno, ab_read, ab_write); + + rtp_request_resend(ab_write+1, seqno-1); + abuf = audio_buffer + BUFIDX(seqno); ab_write = seqno; } @@ -411,7 +407,7 @@ static short *buffer_get_frame(void) { warn("overrun %i (%04X:%04X)", buf_fill, ab_read, ab_write); read = ab_read; ab_read = ab_write - config.buffer_start_fill; - ab_reset(read, ab_read); // reset any ready frames in those we've skipped + ab_reset((ab_write + 1 - BUFFER_FRAMES), ab_read); // reset any ready frames in those we've skipped (avoiding wrap around) } read = ab_read; ab_read++; @@ -424,7 +420,7 @@ static short *buffer_get_frame(void) { for (i = 16; i <= resend_focus(config.buffer_start_fill); i = (i * 2)) { next = ab_read + i; abuf = audio_buffer + BUFIDX(next); - if ((!abuf->ready) && (next <= ab_write)){ + if ((!abuf->ready) && (next < ab_write)){ rtp_request_resend(next, next); debug(1, "last chance resend T+%i, %04X (%04X:%04X)\n", i, next, ab_read, ab_write); } From 97a7c4503f8fc5a8148226e24f29d2e70afefb9b Mon Sep 17 00:00:00 2001 From: BewickPlace Date: Tue, 18 Mar 2014 22:19:55 +0000 Subject: [PATCH 8/8] Allow Overrun but limit & resync if buffering --- player.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/player.c b/player.c index 88351ad72..cb8a121a3 100644 --- a/player.c +++ b/player.c @@ -230,9 +230,9 @@ void player_put_packet(seq_t seqno, uint8_t *data, int len) { ab_write = seqno; } else if (seq_order(ab_write, seqno)) { // newer than expected // Be careful with new packets that are in advance - // Those more than a buffer size in advance should cause a resync - // When buffering the valid threshold should be the buffer fill target itself - if (seq_diff(ab_read, seqno) > (ab_buffering ? config.buffer_start_fill : BUFFER_FRAMES)) { + // Those more than a buffer size in advance will cause an Overrun + // When buffering the valid threshold should be the buffer fill target itself which should re-sync + if (ab_buffering && (seq_diff(ab_read, seqno) > config.buffer_start_fill)) { warn("out of range re-sync %04X (%04X:%04X)", seqno, ab_read, ab_write); ab_resync(); ab_synced = 1;