From: Mike Brady <4265913+mikebrady@users.noreply.github.com> Date: Sun, 28 Nov 2021 16:08:48 +0000 (+0000) Subject: Use CLOCK_MONOLITHIC_RAW to avoid NTP effects, report raw and corrected timing from... X-Git-Tag: 4.1-rc1~24^2~367^2 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=56bef8e7ddf01e9d76860fafb65b6d7330c186b1;p=thirdparty%2Fshairport-sync.git 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. --- 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,29 +1210,27 @@ 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; +uint64_t get_monotonic_time_in_ns() { + uint64_t time_now_ns; + #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_REALTIME because PTP uses it. 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 + 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. @@ -1245,31 +1243,27 @@ uint64_t get_absolute_time_in_fp() { (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; + die("could not initialise Mac timebase info in get_monotonic_time_in_ns().") - // 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); + // 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_fp; + + return time_now_ns; } -uint64_t get_monotonic_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; - // can't use CLOCK_MONOTONIC_RAW as it's not implemented in OpenWrt - // CLOCK_REALTIME because PTP uses it. - clock_gettime(CLOCK_MONOTONIC, &tn); + clock_gettime(CLOCK_MONOTONIC_RAW, &tn); uint64_t tnnsec = tn.tv_sec; tnnsec = tnnsec * 1000000000; uint64_t tnjnsec = tn.tv_nsec; @@ -1308,10 +1302,11 @@ uint64_t get_monotonic_time_in_ns() { return time_now_ns; } -uint64_t get_absolute_time_in_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; -#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_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);