From: Mike Brady Date: Wed, 22 Aug 2018 12:02:42 +0000 (+0100) Subject: Fix display of drift -- the sign is correct now. All timing is relative to the local... X-Git-Tag: 3.3RC0~249^2~2 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=1ee806a53ac2c0d37bd803421fc8fedb941e47c8;p=thirdparty%2Fshairport-sync.git Fix display of drift -- the sign is correct now. All timing is relative to the local clock. Add a rough estimate of the correction necessary. Use the most recent 128 timing samples. --- diff --git a/audio_alsa.c b/audio_alsa.c index 0cfe4a72..5b4d608f 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -882,7 +882,13 @@ int delay(long *the_delay) { debug(1, "Error %d in delay(): \"%s\". Delay reported is %d frames.", reply, snd_strerror(reply), *the_delay); snd_pcm_recover(alsa_handle, reply, 1); - } + } else { + if (*the_delay==0) { + // there's nothing in the pipeline, so we can't measure frame rate. + frame_index = 0; // we'll be starting over... + measurement_data_is_valid = 0; + } + } } else { frame_index = 0; // we'll be starting over... measurement_data_is_valid = 0; @@ -985,7 +991,14 @@ static int play(void *buf, int samples) { debug(1, "Error %d in delay(): \"%s\". Delay reported is %d frames.", err2, snd_strerror(err2), fl); snd_pcm_recover(alsa_handle, err2, 1); + } else { + if (fl==0) { + // there's nothing in the pipeline, so we can't measure frame rate. + frame_index = 0; // we'll be starting over... + measurement_data_is_valid = 0; + } } + uint64_t tf = get_absolute_time_in_fp(); frames_played_at_measurement_time = frames_sent_for_playing - fl; if (frame_index == start_measurement_from_this_frame) { diff --git a/player.c b/player.c index 47758a9a..ce1056d8 100644 --- a/player.c +++ b/player.c @@ -1282,6 +1282,9 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { if (notified_buffer_empty == 0) { debug(3, "Buffers exhausted."); notified_buffer_empty = 1; + conn->initial_reference_time = 0; + conn->initial_reference_timestamp = 0; + conn->input_frame_rate_starting_point_is_valid = 0; } do_wait = 1; } @@ -1813,10 +1816,12 @@ void *player_thread_func(void *arg) { "min DAC queue size, " "min buffer occupancy, " "max buffer occupancy, " - "source frames per second, " - "average input frames per second, " + "source nominal frames per second, " + "source actual frames per second, " "output frames per second, " - "client:local clock drift in ppm"); + "source clock drift in ppm, " + "source clock drift sample count, " + "rough calculated correction in ppm"); } else { inform("sync error in milliseconds, " "total packets, " @@ -1827,7 +1832,10 @@ void *player_thread_func(void *arg) { "min DAC queue size, " "min buffer occupancy, " "max buffer occupancy, " - "input frames per second."); + "source nominal frames per second, " + "source actual frames per second, " + "source clock drift in ppm, " + "source clock drift sample count"); } } else { inform("sync error in milliseconds, " @@ -1838,7 +1846,10 @@ void *player_thread_func(void *arg) { "resend requests, " "min buffer occupancy, " "max buffer occupancy, " - "input frames per second."); + "source nominal frames per second, " + "source actual frames per second, " + "source clock drift in ppm, " + "source clock drift sample count"); } } @@ -2466,63 +2477,92 @@ void *player_thread_func(void *arg) { "%*.1f," /* net correction in ppm */ "%*.1f," /* corrections in ppm */ "%*d," /* total packets */ - "%*llu," /* missing packets */ - "%*llu," /* late packets */ - "%*llu," /* too late packets */ - "%*llu," /* resend requests */ - "%*lli," /* min DAC queue size */ - "%*d," /* min buffer occupancy */ - "%*d," /* max buffer occupancy */ - "%*.2f," /* remote frame rate */ - "%*.2f," /* actual (average) input frame rate */ - "%*.2f," /* output frame rate */ - "%*.2f," /* output frame rate */ - "%*d", /* sample count */ - 10, - 1000 * moving_average_sync_error / config.output_rate, 10, - moving_average_correction * 1000000 / (352 * conn->output_sample_ratio), + "%*" PRIu64 "," /* missing packets */ + "%*" PRIu64 "," /* late packets */ + "%*" PRIu64 "," /* too late packets */ + "%*" PRIu64 "," /* resend requests */ + "%*" PRId64 "," /* min DAC queue size */ + "%*" PRId32 "," /* min buffer occupancy */ + "%*" PRId32 "," /* max buffer occupancy */ + "%*.2f," /* source nominal frame rate */ + "%*.2f," /* source actual (average) frame rate */ + "%*.2f," /* output frame rate */ + "%*.2f," /* source clock drift */ + "%*d," /* source clock drift sample count */ + "%*.2f", /* rough calculated correction in ppm */ + 10, 1000 * moving_average_sync_error / config.output_rate, + 10, moving_average_correction * 1000000 / (352 * conn->output_sample_ratio), 10, moving_average_insertions_plus_deletions * 1000000 / (352 * conn->output_sample_ratio), - 12, play_number, 7, conn->missing_packets, 7, conn->late_packets, 7, - conn->too_late_packets, 7, conn->resend_requests, 7, - minimum_dac_queue_size, 5, minimum_buffer_occupancy, 5, - maximum_buffer_occupancy, 11, conn->remote_frame_rate, 11, - conn->input_frame_rate, 11, conn->frame_rate, 10, - (1.0 - conn->local_to_remote_time_gradient) * 1000000, 6, - conn->local_to_remote_time_gradient_sample_count); + 12, play_number, + 7, conn->missing_packets, + 7, conn->late_packets, + 7, conn->too_late_packets, + 7, conn->resend_requests, + 7, minimum_dac_queue_size, + 5, minimum_buffer_occupancy, + 5, maximum_buffer_occupancy, + 11, conn->remote_frame_rate, + 11, conn->input_frame_rate, + 11, conn->frame_rate, + 10, (conn->local_to_remote_time_gradient-1.0) * 1000000, + 6, conn->local_to_remote_time_gradient_sample_count, + 10, (conn->frame_rate > 0.0) ? ((conn->frame_rate - conn->remote_frame_rate * conn->output_sample_ratio * conn->local_to_remote_time_gradient)*1000000)/conn->frame_rate : 0.0); } else { inform("%*.2f," /* Sync error in milliseconds */ "%*d," /* total packets */ - "%*llu," /* missing packets */ - "%*llu," /* late packets */ - "%*llu," /* too late packets */ - "%*llu," /* resend requests */ - "%*lli," /* min DAC queue size */ - "%*d," /* min buffer occupancy */ - "%*d," /* max buffer occupancy */ - "%*.2f", /* input frame rate */ + "%*" PRIu64 "," /* missing packets */ + "%*" PRIu64 "," /* late packets */ + "%*" PRIu64 "," /* too late packets */ + "%*" PRIu64 "," /* resend requests */ + "%*" PRId64 "," /* min DAC queue size */ + "%*" PRId32 "," /* min buffer occupancy */ + "%*" PRId32 "," /* max buffer occupancy */ + "%*.2f," /* source nominal frame rate */ + "%*.2f," /* source actual (average) frame rate */ + "%*.2f," /* source clock drift */ + "%*d", /* source clock drift sample count */ 10, - 1000 * moving_average_sync_error / config.output_rate, 12, play_number, 7, - conn->missing_packets, 7, conn->late_packets, 7, conn->too_late_packets, 7, - conn->resend_requests, 7, minimum_dac_queue_size, 5, - minimum_buffer_occupancy, 5, maximum_buffer_occupancy, 11, - conn->input_frame_rate); + 1000 * moving_average_sync_error / config.output_rate, + 12, play_number, + 7, conn->missing_packets, + 7, conn->late_packets, + 7, conn->too_late_packets, + 7, conn->resend_requests, + 7, minimum_dac_queue_size, + 5, minimum_buffer_occupancy, + 5, maximum_buffer_occupancy, + 11, conn->remote_frame_rate, + 11, conn->input_frame_rate, + 10, (conn->local_to_remote_time_gradient-1.0) * 1000000, + 6, conn->local_to_remote_time_gradient_sample_count); } } else { inform("%*.2f," /* Sync error in milliseconds */ "%*d," /* total packets */ - "%*llu," /* missing packets */ - "%*llu," /* late packets */ - "%*llu," /* too late packets */ - "%*llu," /* resend requests */ - "%*d," /* min buffer occupancy */ - "%*d," /* max buffer occupancy */ - "%*.2f", /* input frame rate */ + "%*" PRIu64 "," /* missing packets */ + "%*" PRIu64 "," /* late packets */ + "%*" PRIu64 "," /* too late packets */ + "%*" PRIu64 "," /* resend requests */ + "%*" PRId32 "," /* min buffer occupancy */ + "%*" PRId32 "," /* max buffer occupancy */ + "%*.2f," /* source nominal frame rate */ + "%*.2f," /* source actual (average) frame rate */ + "%*.2f," /* source clock drift */ + "%*d", /* source clock drift sample count */ 10, - 1000 * moving_average_sync_error / config.output_rate, 12, play_number, 7, - conn->missing_packets, 7, conn->late_packets, 7, conn->too_late_packets, 7, - conn->resend_requests, 5, minimum_buffer_occupancy, 5, - maximum_buffer_occupancy, 11, conn->input_frame_rate); + 1000 * moving_average_sync_error / config.output_rate, + 12, play_number, + 7, conn->missing_packets, + 7, conn->late_packets, + 7, conn->too_late_packets, + 7, conn->resend_requests, + 5, minimum_buffer_occupancy, + 5, maximum_buffer_occupancy, + 11, conn->remote_frame_rate, + 11, conn->input_frame_rate, + 10, (conn->local_to_remote_time_gradient-1.0) * 1000000, + 6, conn->local_to_remote_time_gradient_sample_count); } } else { inform("No frames received in the last sampling interval."); diff --git a/player.h b/player.h index 078a96a0..3bc415e4 100644 --- a/player.h +++ b/player.h @@ -24,7 +24,7 @@ #include "alac.h" #include "audio.h" -#define time_ping_history 64 // at 1 per three seconds, approximately three minutes of records +#define time_ping_history 128 // at 1 per three seconds, approximately six minutes of records typedef struct time_ping_record { uint64_t local_to_remote_difference; diff --git a/rtp.c b/rtp.c index 5b5b3d3b..41d1747d 100644 --- a/rtp.c +++ b/rtp.c @@ -794,11 +794,10 @@ void *rtp_timing_receiver(void *arg) { } conn->local_to_remote_time_gradient_sample_count = sample_count; conn->local_to_remote_time_gradient = (1.0 * mtl) / mbl; - // debug(1,"Drift is %12.2f ppm, based on %d - // samples.",(1.0-conn->local_to_remote_time_gradient)*1000000,sample_count); } else { conn->local_to_remote_time_gradient = 1.0; } + // debug(1,"local to remote time gradient is %12.2f ppm, based on %d samples.",conn->local_to_remote_time_gradient*1000000,sample_count); } else { debug(2, "Time ping turnaround time: %lld us -- it looks like a timing ping was lost.", (return_time * 1000000) >> 32);