From 136071a62180c5d5215678d6d00638240f1321bd Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Fri, 26 Nov 2021 15:17:27 +0000 Subject: [PATCH 1/5] change stats to report non-zero if output has just opened or if there has been any discontinuity in play from previous time. --- audio_alsa.c | 46 +++++++++++++++++----------------------------- 1 file changed, 17 insertions(+), 29 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index caaad899..0910b9e7 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -248,8 +248,12 @@ static snd_pcm_uframes_t period_size_requested, buffer_size_requested; static int set_period_size_request, set_buffer_size_request; static uint64_t frames_sent_for_playing; -static int output_error_occurred; // set to true if an underrun or similar has occurred since last - // requested + + // set to true if there has been a discontinuity between the last reported frames_sent_for_playing + // and the present reported frames_sent_for_playing + // Not that it will be set when the device is opened, as any previous figures for frames_sent_for_playing + // (which Shairport Sync might hold) would be invalid. +static int frames_sent_break_occurred; static void help(void) { printf(" -d output-device set the output device, default is \"default\".\n" @@ -1632,13 +1636,10 @@ int delay(long *the_delay) { int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) { // returns 0 if the device is in a valid state -- SND_PCM_STATE_RUNNING or // SND_PCM_STATE_PREPARED - // or SND_PCM_STATE_DRAINING - // and returns the actual delay if running or 0 if prepared in *the_delay - - // otherwise return an error code - // the error code could be a Unix errno code or a snderror code, or - // the sps_extra_code_output_stalled or the - // sps_extra_code_output_state_cannot_make_ready codes + // or SND_PCM_STATE_DRAINING. + // returns the actual delay if running or 0 if prepared in *the_delay + // returns the present value of frames_sent_for_playing + // otherwise return a non-zero value int ret = 0; *the_delay = 0; @@ -1657,8 +1658,10 @@ int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) ret = delay_and_status(&state, &my_delay, NULL); } if (ret == 0) - ret = output_error_occurred; // will be zero unless an error like an underrun occurred - output_error_occurred = 0; // reset it. + ret = frames_sent_break_occurred; // will be zero unless an error like an underrun occurred + else + ret = 1; // just indicate there was some kind of a break + frames_sent_break_occurred = 0; // reset it. if (frames_sent_to_dac != NULL) *frames_sent_to_dac = frames_sent_for_playing; debug_mutex_unlock(&alsa_mutex, 0); @@ -1668,22 +1671,6 @@ int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) *the_delay = hd; return ret; } - -int get_frames_sent_for_output(__attribute__((unused)) uint64_t *elapsed_time, - uint64_t *frames_sent_to_dac) { - int ret = 0; - pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0); - *frames_sent_to_dac = frames_sent_for_playing; - if (alsa_handle == NULL) - ret = ENODEV; - else - ret = output_error_occurred; // will be zero unless an error occurred - output_error_occurred = 0; // reset it. - debug_mutex_unlock(&alsa_mutex, 0); - pthread_cleanup_pop(0); - return ret; -} - /* int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { // elapsed_time is in nanoseconds @@ -1728,7 +1715,7 @@ int do_play(void *buf, int samples) { stall_monitor_frame_count += samples; frames_sent_for_playing += samples; } else { - output_error_occurred = -ret; // note than an output error has occurred + frames_sent_break_occurred = 1; // note than an output error has occurred if (ret == -EPIPE) { /* underrun */ // It could be that the DAC was in the SND_PCM_STATE_XRUN state before @@ -1802,7 +1789,8 @@ int do_open(int do_auto_setup) { // set accordingly // do_mute(0); // complete unmute } - output_error_occurred = 0; + frames_sent_break_occurred = 1; // there is a discontinuity with + // any previously-reported frame count frames_sent_for_playing = 0; alsa_backend_state = abm_connected; // only do this if it really opened it. } From b9d3abfa2421143788f2474aeaed7aeaca73e034 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Fri, 26 Nov 2021 15:18:27 +0000 Subject: [PATCH 2/5] Add some debug messages to help check the output rate calculations. --- player.c | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/player.c b/player.c index 824aa871..e568cc87 100644 --- a/player.c +++ b/player.c @@ -2332,27 +2332,25 @@ void *player_thread_func(void *arg) { conn->input_frame_rate = 0.0; } - int stats_status = -1; + int stats_status = 0; if ((config.output->delay) && (config.no_sync == 0) && (config.output->stats)) { uint64_t frames_sent_for_play; uint64_t measurement_time; uint64_t actual_delay; stats_status = config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); - // debug(1,"actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", - // frames_played: %" PRIu64 ".", actual_delay, frames_sent_for_play, - // frames_sent_for_play - actual_delay); + debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); uint64_t frames_played = frames_sent_for_play - actual_delay; // If the status is zero, it means that there were no output problems since the // last time the stats call was made. Thus, the frame rate should be valid. - if ((stats_status == 0) && (previous_frames_played_valid)) { + if ((stats_status == 0) && (previous_frames_played_valid != 0)) { uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; - uint64_t interval = measurement_time - previous_frames_played_time; - // debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRIu64 ".", - // frames_played_in_this_interval, interval); + int64_t interval = measurement_time - previous_frames_played_time; if (interval != 0) { conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; conn->frame_rate_valid = 1; + debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", rate: %f.", + frames_played_in_this_interval, interval, conn->frame_rate); } } From 7890188dcfaa307819211d1970013f472399a0cd Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Fri, 26 Nov 2021 18:01:36 +0000 Subject: [PATCH 3/5] Quieten some debug messages. --- player.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/player.c b/player.c index e568cc87..0991167c 100644 --- a/player.c +++ b/player.c @@ -2339,7 +2339,7 @@ void *player_thread_func(void *arg) { uint64_t actual_delay; stats_status = config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); - debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); + // debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); uint64_t frames_played = frames_sent_for_play - actual_delay; // If the status is zero, it means that there were no output problems since the // last time the stats call was made. Thus, the frame rate should be valid. @@ -2349,8 +2349,8 @@ void *player_thread_func(void *arg) { if (interval != 0) { conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; conn->frame_rate_valid = 1; - debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", rate: %f.", - frames_played_in_this_interval, interval, conn->frame_rate); + //debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", rate: %f.", + // frames_played_in_this_interval, interval, conn->frame_rate); } } From dc5b8f1a1171b18e704283f98c3dd2bf8e4a08ca Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Fri, 26 Nov 2021 18:02:23 +0000 Subject: [PATCH 4/5] Clang format --- audio_alsa.c | 16 ++++++++-------- player.c | 7 +++++-- 2 files changed, 13 insertions(+), 10 deletions(-) diff --git a/audio_alsa.c b/audio_alsa.c index 0910b9e7..f2e0b131 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -249,10 +249,10 @@ static int set_period_size_request, set_buffer_size_request; static uint64_t frames_sent_for_playing; - // set to true if there has been a discontinuity between the last reported frames_sent_for_playing - // and the present reported frames_sent_for_playing - // Not that it will be set when the device is opened, as any previous figures for frames_sent_for_playing - // (which Shairport Sync might hold) would be invalid. +// set to true if there has been a discontinuity between the last reported frames_sent_for_playing +// and the present reported frames_sent_for_playing +// Not that it will be set when the device is opened, as any previous figures for +// frames_sent_for_playing (which Shairport Sync might hold) would be invalid. static int frames_sent_break_occurred; static void help(void) { @@ -1660,8 +1660,8 @@ int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) if (ret == 0) ret = frames_sent_break_occurred; // will be zero unless an error like an underrun occurred else - ret = 1; // just indicate there was some kind of a break - frames_sent_break_occurred = 0; // reset it. + ret = 1; // just indicate there was some kind of a break + frames_sent_break_occurred = 0; // reset it. if (frames_sent_to_dac != NULL) *frames_sent_to_dac = frames_sent_for_playing; debug_mutex_unlock(&alsa_mutex, 0); @@ -1716,7 +1716,7 @@ int do_play(void *buf, int samples) { frames_sent_for_playing += samples; } else { frames_sent_break_occurred = 1; // note than an output error has occurred - if (ret == -EPIPE) { /* underrun */ + if (ret == -EPIPE) { /* underrun */ // It could be that the DAC was in the SND_PCM_STATE_XRUN state before // sending the samples to be output. If so, it will still be in @@ -1790,7 +1790,7 @@ int do_open(int do_auto_setup) { // do_mute(0); // complete unmute } frames_sent_break_occurred = 1; // there is a discontinuity with - // any previously-reported frame count + // any previously-reported frame count frames_sent_for_playing = 0; alsa_backend_state = abm_connected; // only do this if it really opened it. } diff --git a/player.c b/player.c index 0991167c..5e6e4133 100644 --- a/player.c +++ b/player.c @@ -2339,7 +2339,9 @@ void *player_thread_func(void *arg) { uint64_t actual_delay; stats_status = config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); - // debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, frames_sent_for_play - actual_delay); + // debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", + // frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, + // frames_sent_for_play - actual_delay); uint64_t frames_played = frames_sent_for_play - actual_delay; // If the status is zero, it means that there were no output problems since the // last time the stats call was made. Thus, the frame rate should be valid. @@ -2349,7 +2351,8 @@ void *player_thread_func(void *arg) { if (interval != 0) { conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; conn->frame_rate_valid = 1; - //debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", rate: %f.", + // debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", + // rate: %f.", // frames_played_in_this_interval, interval, conn->frame_rate); } } From 56bef8e7ddf01e9d76860fafb65b6d7330c186b1 Mon Sep 17 00:00:00 2001 From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sun, 28 Nov 2021 16:08:48 +0000 Subject: [PATCH 5/5] Use CLOCK_MONOLITHIC_RAW to avoid NTP effects, report raw and corrected timing from audio_alsa. Clean up statistics. Stop watchdog timing out AP2 sessions. CLean up some debug messages. --- activity_monitor.c | 2 +- audio.h | 3 +- audio_alsa.c | 12 ++-- common.c | 122 ++++++++++++++++++++++------------------- common.h | 9 ++- dacp.c | 2 +- nqptp-shm-structures.h | 2 +- player.c | 75 +++++++++++++++---------- player.h | 3 +- rtp.c | 2 +- rtsp.c | 4 ++ 11 files changed, 137 insertions(+), 99 deletions(-) diff --git a/activity_monitor.c b/activity_monitor.c index 1d301c49..deeab2b6 100644 --- a/activity_monitor.c +++ b/activity_monitor.c @@ -187,7 +187,7 @@ void *activity_monitor_thread_code(void *arg) { uint64_t time_to_wait_for_wakeup_ns = (uint64_t)(config.active_state_timeout * 1000000000); #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD - uint64_t time_of_wakeup_ns = get_absolute_time_in_ns() + time_to_wait_for_wakeup_ns; + uint64_t time_of_wakeup_ns = get_realtime_in_ns() + time_to_wait_for_wakeup_ns; sec = time_of_wakeup_ns / 1000000000; nsec = time_of_wakeup_ns % 1000000000; time_for_wait.tv_sec = sec; diff --git a/audio.h b/audio.h index 25742d7b..5ff14195 100644 --- a/audio.h +++ b/audio.h @@ -39,7 +39,8 @@ typedef struct { // will change dynamically, so keep watching it. Implemented in ALSA only. // returns a negative error code if there's a problem int (*delay)(long *the_delay); // snd_pcm_sframes_t is a signed long - int (*stats)(uint64_t *measurement_time, uint64_t *delay, + int (*stats)(uint64_t *raw_measurement_time, uint64_t *corrected_measurement_time, + uint64_t *delay, uint64_t *frames_sent_to_dac); // use this to get the true rate of the DAC // may be NULL, in which case soft volume is applied diff --git a/audio_alsa.c b/audio_alsa.c index f2e0b131..a007c419 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -60,8 +60,9 @@ static int play(void *buf, int samples); static void stop(void); static void flush(void); int delay(long *the_delay); -int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac); -// int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played); +int stats(uint64_t *raw_measurement_time, uint64_t *corrected_measurement_time, uint64_t *the_delay, + uint64_t *frames_sent_to_dac); + void *alsa_buffer_monitor_thread_code(void *arg); static void volume(double vol); @@ -1633,7 +1634,8 @@ int delay(long *the_delay) { return ret; } -int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) { +int stats(uint64_t *raw_measurement_time, uint64_t *corrected_measurement_time, uint64_t *the_delay, + uint64_t *frames_sent_to_dac) { // returns 0 if the device is in a valid state -- SND_PCM_STATE_RUNNING or // SND_PCM_STATE_PREPARED // or SND_PCM_STATE_DRAINING. @@ -1654,7 +1656,9 @@ int stats(uint64_t *the_time, uint64_t *the_delay, uint64_t *frames_sent_to_dac) if (alsa_handle == NULL) { ret = ENODEV; } else { - *the_time = get_absolute_time_in_ns(); + *raw_measurement_time = + get_absolute_time_in_ns(); // this is not conditioned ("disciplined") by NTP + *corrected_measurement_time = get_monotonic_time_in_ns(); // this is ("disciplined") by NTP ret = delay_and_status(&state, &my_delay, NULL); } if (ret == 0) diff --git a/common.c b/common.c index a947be41..bbe36780 100644 --- a/common.c +++ b/common.c @@ -1210,58 +1210,6 @@ double vol2attn(double vol, long max_db, long min_db) { return vol_setting; } -uint64_t get_absolute_time_in_fp() { - uint64_t time_now_fp; -#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD - struct timespec tn; - // can't use CLOCK_MONOTONIC_RAW as it's not implemented in OpenWrt - clock_gettime(CLOCK_MONOTONIC, &tn); - uint64_t tnfpsec = tn.tv_sec; - if (tnfpsec > 0x100000000) - warn("clock_gettime seconds overflow!"); - uint64_t tnfpnsec = tn.tv_nsec; - if (tnfpnsec > 0x100000000) - warn("clock_gettime nanoseconds seconds overflow!"); - tnfpsec = tnfpsec << 32; - tnfpnsec = tnfpnsec << 32; - tnfpnsec = tnfpnsec / 1000000000; - - time_now_fp = tnfpsec + tnfpnsec; // types okay -#endif -#ifdef COMPILE_FOR_OSX - uint64_t time_now_mach; - uint64_t elapsedNano; - static mach_timebase_info_data_t sTimebaseInfo = {0, 0}; - - time_now_mach = mach_absolute_time(); - - // If this is the first time we've run, get the timebase. - // We can use denom == 0 to indicate that sTimebaseInfo is - // uninitialised because it makes no sense to have a zero - // denominator in a fraction. - - if (sTimebaseInfo.denom == 0) { - debug(1, "Mac initialise timebase info."); - (void)mach_timebase_info(&sTimebaseInfo); - } - - // Do the maths. We hope that the multiplication doesn't - // overflow; the price you pay for working in fixed point. - - if (sTimebaseInfo.denom == 0) - die("could not initialise Mac timebase info in get_absolute_time_in_fp().") - // this gives us nanoseconds - uint64_t time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; - - // take the units and shift them to the upper half of the fp, and take the nanoseconds, shift them - // to the upper half and then divide the result to 1000000000 - time_now_fp = - ((time_now_ns / 1000000000) << 32) + (((time_now_ns % 1000000000) << 32) / 1000000000); - -#endif - return time_now_fp; -} - uint64_t get_monotonic_time_in_ns() { uint64_t time_now_ns; @@ -1308,10 +1256,57 @@ uint64_t get_monotonic_time_in_ns() { return time_now_ns; } -uint64_t get_absolute_time_in_ns() { +// all these clock things are now in macOS now since 10.13 (September 2017). Must update... +uint64_t get_monotonic_raw_time_in_ns() { + // CLOCK_MONOTONIC_RAW in FreeBSD etc, monotonic in MacOSX uint64_t time_now_ns; #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD + struct timespec tn; + clock_gettime(CLOCK_MONOTONIC_RAW, &tn); + uint64_t tnnsec = tn.tv_sec; + tnnsec = tnnsec * 1000000000; + uint64_t tnjnsec = tn.tv_nsec; + time_now_ns = tnnsec + tnjnsec; +#endif + +#ifdef COMPILE_FOR_OSX + uint64_t time_now_mach; + uint64_t elapsedNano; + static mach_timebase_info_data_t sTimebaseInfo = {0, 0}; + + // this actually give you a monotonic clock + // see https://news.ycombinator.com/item?id=6303755 + time_now_mach = mach_absolute_time(); + + // If this is the first time we've run, get the timebase. + // We can use denom == 0 to indicate that sTimebaseInfo is + // uninitialised because it makes no sense to have a zero + // denominator in a fraction. + + if (sTimebaseInfo.denom == 0) { + debug(1, "Mac initialise timebase info."); + (void)mach_timebase_info(&sTimebaseInfo); + } + + if (sTimebaseInfo.denom == 0) + die("could not initialise Mac timebase info in get_monotonic_time_in_ns().") + + // Do the maths. We hope that the multiplication doesn't + // overflow; the price you pay for working in fixed point. + + // this gives us nanoseconds + time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; +#endif + + return time_now_ns; +} + +#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD +// Not defined for macOS +uint64_t get_realtime_in_ns() { + uint64_t time_now_ns; + struct timespec tn; // can't use CLOCK_MONOTONIC_RAW as it's not implemented in OpenWrt // CLOCK_REALTIME because PTP uses it. @@ -1320,6 +1315,21 @@ uint64_t get_absolute_time_in_ns() { tnnsec = tnnsec * 1000000000; uint64_t tnjnsec = tn.tv_nsec; time_now_ns = tnnsec + tnjnsec; + return time_now_ns; +} +#endif + +uint64_t get_absolute_time_in_ns() { + // CLOCK_MONOTONIC_RAW in FreeBSD etc, monotonic in MacOSX + uint64_t time_now_ns; + +#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD + struct timespec tn; + clock_gettime(CLOCK_MONOTONIC_RAW, &tn); + uint64_t tnnsec = tn.tv_sec; + tnnsec = tnnsec * 1000000000; + uint64_t tnjnsec = tn.tv_nsec; + time_now_ns = tnnsec + tnjnsec; #endif #ifdef COMPILE_FOR_OSX @@ -1521,8 +1531,8 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); struct timespec timeoutTime; - uint64_t wait_until_time = dally_time * 1000; // to nanoseconds - uint64_t start_time = get_absolute_time_in_ns(); // this is from CLOCK_REALTIME + uint64_t wait_until_time = dally_time * 1000; // to nanoseconds + uint64_t start_time = get_realtime_in_ns(); // this is from CLOCK_REALTIME wait_until_time = wait_until_time + start_time; uint64_t wait_until_sec = wait_until_time / 1000000000; uint64_t wait_until_nsec = wait_until_time % 1000000000; @@ -1530,7 +1540,7 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time, timeoutTime.tv_nsec = wait_until_nsec; int r = pthread_mutex_timedlock(mutex, &timeoutTime); - uint64_t et = get_absolute_time_in_ns() - start_time; + uint64_t et = get_realtime_in_ns() - start_time; if ((debuglevel != 0) && (r != 0) && (debugmessage != NULL)) { char errstr[1000]; diff --git a/common.h b/common.h index 199b3d41..d9be0327 100644 --- a/common.h +++ b/common.h @@ -379,9 +379,12 @@ double flat_vol2attn(double vol, long max_db, long min_db); double vol2attn(double vol, long max_db, long min_db); // return a time in nanoseconds -// uint64_t get_absolute_time_in_fp(void); // obselete -uint64_t get_absolute_time_in_ns(void); -uint64_t get_monotonic_time_in_ns(void); // to try and get precise FPS values +#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD +// Not defined for macOS +uint64_t get_realtime_in_ns(void); +#endif +uint64_t get_absolute_time_in_ns(void); // monotonic_raw or monotonic +uint64_t get_monotonic_time_in_ns(void); // NTP-disciplined // time at startup for debugging timing extern uint64_t ns_time_at_startup, ns_time_at_last_debug_message; diff --git a/dacp.c b/dacp.c index ef2297e2..d6964133 100644 --- a/dacp.c +++ b/dacp.c @@ -529,7 +529,7 @@ void *dacp_monitor_thread_code(__attribute__((unused)) void *na) { (uint64_t)(1000000000 * config.missing_port_dacp_scan_interval_seconds); #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD - uint64_t time_of_wakeup_ns = get_absolute_time_in_ns() + time_to_wait_for_wakeup_ns; + uint64_t time_of_wakeup_ns = get_realtime_in_ns() + time_to_wait_for_wakeup_ns; uint64_t sec = time_of_wakeup_ns / 1000000000; uint64_t nsec = time_of_wakeup_ns % 1000000000; #endif diff --git a/nqptp-shm-structures.h b/nqptp-shm-structures.h index 36c8a813..f4db8c6e 100644 --- a/nqptp-shm-structures.h +++ b/nqptp-shm-structures.h @@ -22,7 +22,7 @@ #define STORAGE_ID "/nqptp" #define MAX_CLOCKS 32 -#define NQPTP_SHM_STRUCTURES_VERSION 5 +#define NQPTP_SHM_STRUCTURES_VERSION 6 #define NQPTP_CONTROL_PORT 9000 // the control port will accept a UDP packet with the first letter being: diff --git a/player.c b/player.c index 5e6e4133..9b0b86ca 100644 --- a/player.c +++ b/player.c @@ -1299,7 +1299,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) { time_to_wait_for_wakeup_ns /= 3; // two thirds of a packet time #ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD - uint64_t time_of_wakeup_ns = local_time_now + time_to_wait_for_wakeup_ns; + uint64_t time_of_wakeup_ns = get_realtime_in_ns() + time_to_wait_for_wakeup_ns; uint64_t sec = time_of_wakeup_ns / 1000000000; uint64_t nsec = time_of_wakeup_ns % 1000000000; @@ -1552,30 +1552,31 @@ int was_a_previous_column; int *statistics_print_profile; // these arrays specify which of the statistics specified by the statistics_item calls will actually -// be printed -- 1 means print, 0 means skip +// be printed -- 2 means print, 1 means print only in a debug mode, 0 means skip // don't display output fps -- not sure how accurate it is (change item 14 and 17 to 1 to restore) -int ap1_synced_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1}; -int ap1_nosync_statistics_print_profile[] = {1, 0, 0, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 0, 1, 1, 0}; -int ap1_nodelay_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, 1, 1, 0, 1, 1, 1, 1, 0, 1, 1, 0}; +int ap1_synced_statistics_print_profile[] = {2, 2, 2, 1, 2, 1, 1, 2, 1, 1, 1, 1, 1, 2, 2, 1, 1}; +int ap1_nosync_statistics_print_profile[] = {2, 0, 0, 1, 2, 1, 1, 2, 1, 1, 1, 1, 1, 0, 0, 1, 0}; +int ap1_nodelay_statistics_print_profile[] = {0, 0, 0, 1, 2, 1, 1, 2, 0, 1, 1, 1, 1, 0, 0, 1, 0}; -int ap2_realtime_synced_stream_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1, - 1, 1, 0, 0, 1, 0, 0, 0}; -int ap2_realtime_nosync_stream_statistics_print_profile[] = {1, 0, 0, 1, 1, 1, 1, 1, 1, - 1, 1, 0, 0, 0, 0, 0, 0}; -int ap2_realtime_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, 1, 1, 0, - 1, 1, 0, 0, 0, 0, 0, 0}; +int ap2_realtime_synced_stream_statistics_print_profile[] = {2, 2, 2, 1, 2, 1, 1, 2, 1, + 1, 1, 1, 1, 2, 2, 0, 0}; +int ap2_realtime_nosync_stream_statistics_print_profile[] = {2, 0, 0, 1, 2, 1, 1, 2, 1, + 1, 1, 1, 1, 0, 0, 0, 0}; +int ap2_realtime_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 2, 1, 1, 2, 0, + 1, 1, 1, 1, 0, 0, 0, 0}; // don't display output fps -- not sure how accurate it is (change item 14 1 to restore) -int ap2_buffered_synced_stream_statistics_print_profile[] = {1, 1, 1, 1, 0, 0, 0, 0, 1, - 1, 1, 0, 0, 1, 0, 0, 0}; -int ap2_buffered_nosync_stream_statistics_print_profile[] = {1, 0, 0, 1, 0, 0, 0, 0, 1, +int ap2_buffered_synced_stream_statistics_print_profile[] = {2, 2, 2, 1, 0, 0, 0, 0, 1, + 1, 1, 0, 0, 2, 2, 0, 0}; +int ap2_buffered_nosync_stream_statistics_print_profile[] = {2, 0, 0, 1, 0, 0, 0, 0, 1, 1, 1, 0, 0, 0, 0, 0, 0}; int ap2_buffered_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 0, 0, 0, 0, 0, 1, 1, 0, 0, 0, 0, 0, 0}; void statistics_item(const char *heading, const char *format, ...) { - if (statistics_print_profile[statistics_column] == 1) { // include this column? + if (((statistics_print_profile[statistics_column] == 1) && (debuglev != 0)) || + (statistics_print_profile[statistics_column] == 2)) { // include this column? if (was_a_previous_column != 0) strcat(line_of_stats, " "); if (statistics_row == 0) { @@ -1624,10 +1625,10 @@ void player_thread_cleanup_handler(void *arg) { int elapsedSec = rawSeconds % 60; if (conn->frame_rate_valid) inform("Connection %d: Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f, " - "output: %0.2f " + " Output: %0.2f (raw), %0.2f (corrected) " "frames per second.", conn->connection_number, elapsedHours, elapsedMin, elapsedSec, conn->input_frame_rate, - conn->frame_rate); + conn->raw_frame_rate, conn->corrected_frame_rate); else inform("Connection %d: Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f " "frames per second.", @@ -1727,7 +1728,8 @@ void *player_thread_func(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; uint64_t previous_frames_played; - uint64_t previous_frames_played_time; + uint64_t previous_raw_measurement_time; + uint64_t previous_corrected_measurement_time; int previous_frames_played_valid = 0; // pthread_cleanup_push(player_thread_initial_cleanup_handler, arg); @@ -1888,7 +1890,8 @@ void *player_thread_func(void *arg) { conn->playstart = time(NULL); - conn->frame_rate = 0.0; + conn->raw_frame_rate = 0.0; + conn->corrected_frame_rate = 0.0; conn->frame_rate_valid = 0; conn->input_frame_rate = 0.0; @@ -2335,10 +2338,12 @@ void *player_thread_func(void *arg) { int stats_status = 0; if ((config.output->delay) && (config.no_sync == 0) && (config.output->stats)) { uint64_t frames_sent_for_play; - uint64_t measurement_time; + uint64_t raw_measurement_time; + uint64_t corrected_measurement_time; uint64_t actual_delay; stats_status = - config.output->stats(&measurement_time, &actual_delay, &frames_sent_for_play); + config.output->stats(&raw_measurement_time, &corrected_measurement_time, + &actual_delay, &frames_sent_for_play); // debug(1,"status: %d, actual_delay: %" PRIu64 ", frames_sent_for_play: %" PRIu64 ", // frames_played: %" PRIu64 ".", stats_status, actual_delay, frames_sent_for_play, // frames_sent_for_play - actual_delay); @@ -2347,9 +2352,13 @@ void *player_thread_func(void *arg) { // last time the stats call was made. Thus, the frame rate should be valid. if ((stats_status == 0) && (previous_frames_played_valid != 0)) { uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; - int64_t interval = measurement_time - previous_frames_played_time; - if (interval != 0) { - conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; + int64_t raw_interval = raw_measurement_time - previous_raw_measurement_time; + int64_t corrected_interval = + corrected_measurement_time - previous_corrected_measurement_time; + if (raw_interval != 0) { + conn->raw_frame_rate = (1e9 * frames_played_in_this_interval) / raw_interval; + conn->corrected_frame_rate = + (1e9 * frames_played_in_this_interval) / corrected_interval; conn->frame_rate_valid = 1; // debug(1,"frames_played_in_this_interval: %" PRIu64 ", interval: %" PRId64 ", // rate: %f.", @@ -2365,7 +2374,8 @@ void *player_thread_func(void *arg) { if (stats_status != 0) conn->frame_rate_valid = 0; previous_frames_played = frames_played; - previous_frames_played_time = measurement_time; + previous_raw_measurement_time = raw_measurement_time; + previous_corrected_measurement_time = corrected_measurement_time; previous_frames_played_valid = 1; } } @@ -2411,15 +2421,19 @@ void *player_thread_func(void *arg) { statistics_item("min buffers", "%*" PRIu32 "", 11, minimum_buffer_occupancy); statistics_item("max buffers", "%*" PRIu32 "", 11, maximum_buffer_occupancy); statistics_item("nominal fps", "%*.2f", 11, conn->remote_frame_rate); - statistics_item(" actual fps", "%*.2f", 11, conn->input_frame_rate); - if (conn->frame_rate_valid) - statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); - else - statistics_item(" output fps", " N/A"); + statistics_item("received fps", "%*.2f", 12, conn->input_frame_rate); + if (conn->frame_rate_valid) { + statistics_item("output fps (r)", "%*.2f", 14, conn->raw_frame_rate); + statistics_item("output fps (c)", "%*.2f", 14, conn->corrected_frame_rate); + } else { + statistics_item("output fps (r)", " N/A"); + statistics_item("output fps (c)", " N/A"); + } statistics_item("source drift ppm", "%*.2f", 16, (conn->local_to_remote_time_gradient - 1.0) * 1000000); statistics_item("drift samples", "%*d", 13, conn->local_to_remote_time_gradient_sample_count); + /* statistics_item("estimated (unused) correction ppm", "%*.2f", strlen("estimated (unused) correction ppm"), (conn->frame_rate_valid != 0) @@ -2429,6 +2443,7 @@ void *player_thread_func(void *arg) { 1000000) / conn->frame_rate : 0.0); + */ statistics_row++; inform(line_of_stats); } while (statistics_row < 2); diff --git a/player.h b/player.h index b08a379e..d37f00c7 100644 --- a/player.h +++ b/player.h @@ -180,7 +180,8 @@ typedef struct { stats_t *statistics; // for holding the output rate information until printed out at the end of a session - double frame_rate; + double raw_frame_rate; + double corrected_frame_rate; int frame_rate_valid; // for holding input rate information until printed out at the end of a session diff --git a/rtp.c b/rtp.c index a79e0bbd..5b79ff4b 100644 --- a/rtp.c +++ b/rtp.c @@ -1762,7 +1762,7 @@ void rtp_realtime_audio_cleanup_handler(__attribute__((unused)) void *arg) { debug(2, "Realtime Audio Receiver Cleanup Start."); rtsp_conn_info *conn = (rtsp_conn_info *)arg; close(conn->realtime_audio_socket); - debug(1, "Connection %d: closing realtime audio port %u", conn->local_realtime_audio_port); + debug(2, "Connection %d: closing realtime audio port %u", conn->local_realtime_audio_port); conn->realtime_audio_socket = 0; debug(2, "Realtime Audio Receiver Cleanup Done."); } diff --git a/rtsp.c b/rtsp.c index 5f9fa9ab..079ad14d 100644 --- a/rtsp.c +++ b/rtsp.c @@ -583,7 +583,11 @@ void *player_watchdog_thread_code(void *arg) { do { usleep(2000000); // check every two seconds // debug(3, "Connection %d: Check the thread is doing something...", conn->connection_number); +#ifdef CONFIG_AIRPLAY_2 + if ((config.dont_check_timeout == 0) && (config.timeout != 0) && (conn->airplay_type == ap_1)) { +#else if ((config.dont_check_timeout == 0) && (config.timeout != 0)) { +#endif debug_mutex_lock(&conn->watchdog_mutex, 1000, 0); uint64_t last_watchdog_bark_time = conn->watchdog_bark_time; debug_mutex_unlock(&conn->watchdog_mutex, 0);