Use CLOCK_MONOLITHIC_RAW to avoid NTP effects, report raw and correct…

…ed timing from audio_alsa. Clean up statistics. Stop watchdog timing out AP2 sessions. CLean up some debug messages.

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;

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

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)

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,16 +1531,16 @@ 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;
   timeoutTime.tv_sec = wait_until_sec;
   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];

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;

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

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:

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);

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