]> git.ipfire.org Git - thirdparty/shairport-sync.git/commitdiff
partial move to using a nanosecond-based system timer. More to come.
authorMike Brady <mikebradydublin@icloud.com>
Mon, 24 Feb 2020 19:40:44 +0000 (19:40 +0000)
committerMike Brady <mikebradydublin@icloud.com>
Mon, 24 Feb 2020 19:40:44 +0000 (19:40 +0000)
activity_monitor.c
audio_alsa.c
audio_jack.c
common.c
common.h
dacp.c
player.c
rtsp.c
shairport.c

index bcc25d245886ff5c973fb5990c6420a6efca0a41..ce7edc5f537ba7419b72155496ae0359d83b90b4 100644 (file)
@@ -196,21 +196,19 @@ void *activity_monitor_thread_code(void *arg) {
       } else {
         state = am_timing_out;
 
-        uint64_t time_to_wait_for_wakeup_fp =
-            (uint64_t)(config.active_state_timeout * 1000000); // resolution of microseconds
-        time_to_wait_for_wakeup_fp = time_to_wait_for_wakeup_fp << 32;
-        time_to_wait_for_wakeup_fp = time_to_wait_for_wakeup_fp / 1000000;
+        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_fp = get_absolute_time_in_fp() + time_to_wait_for_wakeup_fp;
-        sec = time_of_wakeup_fp >> 32;
-        nsec = ((time_of_wakeup_fp & 0xffffffff) * 1000000000) >> 32;
+        uint64_t time_of_wakeup_ns = get_absolute_time_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;
         time_for_wait.tv_nsec = nsec;
 #endif
+
 #ifdef COMPILE_FOR_OSX
-        sec = time_to_wait_for_wakeup_fp >> 32;
-        nsec = ((time_to_wait_for_wakeup_fp & 0xffffffff) * 1000000000) >> 32;
+        sec = time_to_wait_for_wakeup_ns / 1000000000;
+        nsec = time_to_wait_for_wakeup_ns % 1000000000;
         time_for_wait.tv_sec = sec;
         time_for_wait.tv_nsec = nsec;
 #endif
index 39e4d05148c6267424c53c2981a727197c418954..40287909101643583a380eb4c2e08c4807122b5b 100644 (file)
@@ -210,9 +210,6 @@ int precision_delay_available() {
           generate_zero_frames(silence, frames_of_silence, config.output_format,
                                use_dither, // i.e. with dither
                                dither_random_number_store);
-      // debug(1,"Play %d frames of silence with most_recent_write_time of
-      // %" PRIx64 ".",
-      //    frames_of_silence,most_recent_write_time);
       do_play(silence, frames_of_silence);
       pthread_cleanup_pop(1);
       // now we can get the delay, and we'll note if it uses update timestamps
@@ -255,8 +252,6 @@ static uint64_t frames_played_at_measurement_start_time;
 static uint64_t measurement_time;
 static uint64_t frames_played_at_measurement_time;
 
-volatile uint64_t most_recent_write_time;
-
 static uint64_t frames_sent_for_playing;
 static uint64_t frame_index;
 static int measurement_data_is_valid;
@@ -1350,7 +1345,6 @@ static int init(int argc, char **argv) {
   // length of the queue
   // if the queue gets too short, stuff it with silence
 
-  most_recent_write_time = 0; // could be used by the alsa_buffer_monitor_thread_code
   pthread_create(&alsa_buffer_monitor_thread, NULL, &alsa_buffer_monitor_thread_code, NULL);
 
   return response;
@@ -1605,6 +1599,7 @@ int delay(long *the_delay) {
 }
 
 int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) {
+  // elapsed_time is in nanoseconds
   int response = 0; // zero means okay
   if (measurement_data_is_valid) {
     *elapsed_time = measurement_time - measurement_start_time;
@@ -1657,7 +1652,7 @@ int do_play(void *buf, int samples) {
         if ((frame_index == start_measurement_from_this_frame) ||
             ((frame_index > start_measurement_from_this_frame) && (frame_index % 32 == 0))) {
 
-          measurement_time = get_absolute_time_in_fp();
+          measurement_time = get_absolute_time_in_ns();
           frames_played_at_measurement_time = frames_sent_for_playing - my_delay - samples;
 
           if (frame_index == start_measurement_from_this_frame) {
@@ -1744,6 +1739,7 @@ int do_close() {
     // debug(1,"alsa: do_close() -- closing the output device");
     if ((derr = snd_pcm_drop(alsa_handle)))
       debug(1, "Error %d (\"%s\") dropping output device.", derr, snd_strerror(derr));
+    usleep(5000);
     if ((derr = snd_pcm_hw_free(alsa_handle)))
       debug(1, "Error %d (\"%s\") freeing the output device hardware.", derr, snd_strerror(derr));
 
@@ -1946,7 +1942,7 @@ void *alsa_buffer_monitor_thread_code(__attribute__((unused)) void *arg) {
       alsa_device_init();
       alsa_device_initialised = 1;
     }
-    int sleep_time_ms = (int)(config.disable_standby_mode_silence_scan_interval * 1000);
+    int sleep_time_us = (int)(config.disable_standby_mode_silence_scan_interval * 1000000);
     pthread_cleanup_debug_mutex_lock(&alsa_mutex, 200000, 0);
     // check possible state transitions here
     if ((alsa_backend_state == abm_disconnected) && (config.keep_dac_busy != 0)) {
@@ -1974,57 +1970,51 @@ void *alsa_buffer_monitor_thread_code(__attribute__((unused)) void *arg) {
       int reply;
       long buffer_size = 0;
       snd_pcm_state_t state;
-      uint64_t present_time = get_absolute_time_in_fp();
-      if ((most_recent_write_time == 0) || (present_time > most_recent_write_time)) {
-        reply = delay_and_status(&state, &buffer_size, NULL);
-        if (reply != 0) {
-          buffer_size = 0;
-          char errorstring[1024];
-          strerror_r(-reply, (char *)errorstring, sizeof(errorstring));
-          debug(1, "alsa: alsa_buffer_monitor_thread_code delay error %d: \"%s\".", reply,
-                (char *)errorstring);
-        }
-        long buffer_size_threshold =
-            (long)(config.disable_standby_mode_silence_threshold * config.output_rate);
-        size_t size_of_silence_buffer;
-        if (buffer_size < buffer_size_threshold) {
-          uint64_t sleep_time_in_fp = sleep_time_ms;
-          sleep_time_in_fp = sleep_time_in_fp << 32;
-          sleep_time_in_fp = sleep_time_in_fp / 1000;
-          int frames_of_silence = 1024;
-          size_of_silence_buffer = frames_of_silence * frame_size;
-          void *silence = malloc(size_of_silence_buffer);
-          if (silence == NULL) {
-            warn("disable_standby_mode has been turned off because a memory allocation error "
-                 "occurred.");
-            error_detected = 1;
-          } else {
-            int ret;
-            pthread_cleanup_push(malloc_cleanup, silence);
-            int use_dither = 0;
-            if ((alsa_mix_ctrl == NULL) && (config.ignore_volume_control == 0) &&
-                (config.airplay_volume != 0.0))
-              use_dither = 1;
-            dither_random_number_store =
-                generate_zero_frames(silence, frames_of_silence, config.output_format,
-                                     use_dither, // i.e. with dither
-                                     dither_random_number_store);
-            ret = do_play(silence, frames_of_silence);
-            frame_count++;
-            pthread_cleanup_pop(1); // free malloced buffer
-            if (ret < 0) {
-              error_count++;
-              char errorstring[1024];
-              strerror_r(-ret, (char *)errorstring, sizeof(errorstring));
-              debug(2, "alsa: alsa_buffer_monitor_thread_code error %d (\"%s\") writing %d samples "
-                       "to alsa device -- %d errors in %d trials.",
-                    ret, (char *)errorstring, frames_of_silence, error_count, frame_count);
-              if ((error_count > 40) && (frame_count < 100)) {
-                warn("disable_standby_mode has been turned off because too many underruns "
-                     "occurred. Is Shairport Sync outputting to a virtual device or running in a "
-                     "virtual machine?");
-                error_detected = 1;
-              }
+      reply = delay_and_status(&state, &buffer_size, NULL);
+      if (reply != 0) {
+        buffer_size = 0;
+        char errorstring[1024];
+        strerror_r(-reply, (char *)errorstring, sizeof(errorstring));
+        debug(1, "alsa: alsa_buffer_monitor_thread_code delay error %d: \"%s\".", reply,
+              (char *)errorstring);
+      }
+      long buffer_size_threshold =
+          (long)(config.disable_standby_mode_silence_threshold * config.output_rate);
+      size_t size_of_silence_buffer;
+      if (buffer_size < buffer_size_threshold) {
+        int frames_of_silence = 1024;
+        size_of_silence_buffer = frames_of_silence * frame_size;
+        void *silence = malloc(size_of_silence_buffer);
+        if (silence == NULL) {
+          warn("disable_standby_mode has been turned off because a memory allocation error "
+               "occurred.");
+          error_detected = 1;
+        } else {
+          int ret;
+          pthread_cleanup_push(malloc_cleanup, silence);
+          int use_dither = 0;
+          if ((alsa_mix_ctrl == NULL) && (config.ignore_volume_control == 0) &&
+              (config.airplay_volume != 0.0))
+            use_dither = 1;
+          dither_random_number_store =
+              generate_zero_frames(silence, frames_of_silence, config.output_format,
+                                   use_dither, // i.e. with dither
+                                   dither_random_number_store);
+          ret = do_play(silence, frames_of_silence);
+          frame_count++;
+          pthread_cleanup_pop(1); // free malloced buffer
+          if (ret < 0) {
+            error_count++;
+            char errorstring[1024];
+            strerror_r(-ret, (char *)errorstring, sizeof(errorstring));
+            debug(2, "alsa: alsa_buffer_monitor_thread_code error %d (\"%s\") writing %d samples "
+                     "to alsa device -- %d errors in %d trials.",
+                  ret, (char *)errorstring, frames_of_silence, error_count, frame_count);
+            if ((error_count > 40) && (frame_count < 100)) {
+              warn("disable_standby_mode has been turned off because too many underruns "
+                   "occurred. Is Shairport Sync outputting to a virtual device or running in a "
+                   "virtual machine?");
+              error_detected = 1;
             }
           }
         }
@@ -2032,7 +2022,7 @@ void *alsa_buffer_monitor_thread_code(__attribute__((unused)) void *arg) {
     }
     debug_mutex_unlock(&alsa_mutex, 0);
     pthread_cleanup_pop(0);       // release the mutex
-    usleep(sleep_time_ms * 1000); // has a cancellation point in it
+    usleep(sleep_time_us); // has a cancellation point in it
   }
   pthread_exit(NULL);
 }
index db6e18994ee3fc413ca1e63fb822d6f482a07ace..5caa6c68a087d9ddaec84763f70ee980ad8ec3f7 100644 (file)
@@ -395,13 +395,13 @@ int jack_delay(long *the_delay) {
   // occupancy after another transfer had occurred, so we could "lose" a full transfer
   // (e.g. 1024 frames @ 44,100 fps ~ 23.2 milliseconds)
   pthread_mutex_lock(&buffer_mutex);
-  int64_t time_now = get_absolute_time_in_fp();
-  int64_t delta = time_now - time_of_latest_transfer;
+  int64_t time_now = get_absolute_time_in_ns();
+  int64_t delta = time_now - time_of_latest_transfer; // nanoseconds
   size_t audio_occupancy_now = jack_ringbuffer_read_space(jackbuf) / bytes_per_frame;
   debug(2, "audio_occupancy_now is %d.", audio_occupancy_now);
   pthread_mutex_unlock(&buffer_mutex);
 
-  int64_t frames_processed_since_latest_latency_check = (delta * sample_rate) >> 32;
+  int64_t frames_processed_since_latest_latency_check = (delta * sample_rate) / 1000000000;
   // debug(1,"delta: %" PRId64 " frames.",frames_processed_since_latest_latency_check);
   // jack_latency is set by the graph() callback, it's the average of the maximum
   // latencies of all our output ports. Adjust this constant baseline delay according
@@ -456,7 +456,7 @@ int play(void *buf, int samples) {
     }
 #endif
   }
-  time_of_latest_transfer = get_absolute_time_in_fp();
+  time_of_latest_transfer = get_absolute_time_in_ns();
   pthread_mutex_unlock(&buffer_mutex);
   if (samples) {
     warn("JACK ringbuffer overrun. Dropped %d samples.", samples);
index 3bdf17de8dc32d8bbb0102b5791880c7d0fa02d5..b3942f78a517cc1b2a5e60b7c96e96cda10bbe6b 100644 (file)
--- a/common.c
+++ b/common.c
@@ -89,9 +89,9 @@ void set_alsa_out_dev(char *);
 
 config_t config_file_stuff;
 pthread_t main_thread_id;
-uint64_t fp_time_at_startup, fp_time_at_last_debug_message;
+uint64_t ns_time_at_startup, ns_time_at_last_debug_message;
 
-// always lock use this when accessing the fp_time_at_last_debug_message
+// always lock use this when accessing the ns_time_at_last_debug_message
 static pthread_mutex_t debug_timing_lock = PTHREAD_MUTEX_INITIALIZER;
 
 pthread_mutex_t the_conn_lock = PTHREAD_MUTEX_INITIALIZER;
@@ -218,14 +218,13 @@ void _die(const char *filename, const int linenumber, const char *format, ...) {
   char *s;
   if (debuglev) {
     pthread_mutex_lock(&debug_timing_lock);
-    uint64_t time_now = get_absolute_time_in_fp();
-    uint64_t time_since_start = time_now - fp_time_at_startup;
-    uint64_t time_since_last_debug_message = time_now - fp_time_at_last_debug_message;
-    fp_time_at_last_debug_message = time_now;
+    uint64_t time_now = get_absolute_time_in_ns();
+    uint64_t time_since_start = time_now - ns_time_at_startup;
+    uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message;
+    ns_time_at_last_debug_message = time_now;
     pthread_mutex_unlock(&debug_timing_lock);
-    uint64_t divisor = (uint64_t)1 << 32;
-    s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / divisor,
-                                    1.0 * time_since_last_debug_message / divisor, filename,
+    s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000,
+                                    1.0 * time_since_last_debug_message / 1000000000, filename,
                                     linenumber, " *fatal error: ");
   } else {
     s = b;
@@ -247,14 +246,13 @@ void _warn(const char *filename, const int linenumber, const char *format, ...)
   char *s;
   if (debuglev) {
     pthread_mutex_lock(&debug_timing_lock);
-    uint64_t time_now = get_absolute_time_in_fp();
-    uint64_t time_since_start = time_now - fp_time_at_startup;
-    uint64_t time_since_last_debug_message = time_now - fp_time_at_last_debug_message;
-    fp_time_at_last_debug_message = time_now;
+    uint64_t time_now = get_absolute_time_in_ns();
+    uint64_t time_since_start = time_now - ns_time_at_startup;
+    uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message;
+    ns_time_at_last_debug_message = time_now;
     pthread_mutex_unlock(&debug_timing_lock);
-    uint64_t divisor = (uint64_t)1 << 32;
-    s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / divisor,
-                                    1.0 * time_since_last_debug_message / divisor, filename,
+    s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000,
+                                    1.0 * time_since_last_debug_message / 1000000000, filename,
                                     linenumber, " *warning: ");
   } else {
     s = b;
@@ -275,14 +273,13 @@ void _debug(const char *filename, const int linenumber, int level, const char *f
   char b[1024];
   b[0] = 0;
   pthread_mutex_lock(&debug_timing_lock);
-  uint64_t time_now = get_absolute_time_in_fp();
-  uint64_t time_since_start = time_now - fp_time_at_startup;
-  uint64_t time_since_last_debug_message = time_now - fp_time_at_last_debug_message;
-  fp_time_at_last_debug_message = time_now;
+  uint64_t time_now = get_absolute_time_in_ns();
+  uint64_t time_since_start = time_now - ns_time_at_startup;
+  uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message;
+  ns_time_at_last_debug_message = time_now;
   pthread_mutex_unlock(&debug_timing_lock);
-  uint64_t divisor = (uint64_t)1 << 32;
-  char *s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / divisor,
-                                        1.0 * time_since_last_debug_message / divisor, filename,
+  char *s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000,
+                                        1.0 * time_since_last_debug_message / 1000000000, filename,
                                         linenumber, " ");
   va_list args;
   va_start(args, format);
@@ -300,14 +297,13 @@ void _inform(const char *filename, const int linenumber, const char *format, ...
   char *s;
   if (debuglev) {
     pthread_mutex_lock(&debug_timing_lock);
-    uint64_t time_now = get_absolute_time_in_fp();
-    uint64_t time_since_start = time_now - fp_time_at_startup;
-    uint64_t time_since_last_debug_message = time_now - fp_time_at_last_debug_message;
-    fp_time_at_last_debug_message = time_now;
+    uint64_t time_now = get_absolute_time_in_ns();
+    uint64_t time_since_start = time_now - ns_time_at_startup;
+    uint64_t time_since_last_debug_message = time_now - ns_time_at_last_debug_message;
+    ns_time_at_last_debug_message = time_now;
     pthread_mutex_unlock(&debug_timing_lock);
-    uint64_t divisor = (uint64_t)1 << 32;
-    s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / divisor,
-                                    1.0 * time_since_last_debug_message / divisor, filename,
+    s = generate_preliminary_string(b, sizeof(b), 1.0 * time_since_start / 1000000000,
+                                    1.0 * time_since_last_debug_message / 1000000000, filename,
                                     linenumber, " ");
   } else {
     s = b;
@@ -1133,7 +1129,9 @@ char *str_replace(const char *string, const char *substr, const char *replacemen
 
 /* from http://burtleburtle.net/bob/rand/smallprng.html */
 
-// this is not thread-safe, so we need a mutex on it to use it properly// always lock use this when accessing the fp_time_at_last_debug_message
+// this is not thread-safe, so we need a mutex on it to use it properly.
+// always lock use this when accessing the fp_time_at_last_debug_message
+
 pthread_mutex_t r64_mutex = PTHREAD_MUTEX_INITIALIZER;
 
 // typedef uint64_t u8;
@@ -1241,18 +1239,17 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time,
 
   timeoutTime.tv_sec = time_then;
   timeoutTime.tv_nsec = time_then_nsec;
-  int64_t start_time = get_absolute_time_in_fp();
+  int64_t start_time = get_absolute_time_in_ns();
   int r = pthread_mutex_timedlock(mutex, &timeoutTime);
-  int64_t et = get_absolute_time_in_fp() - start_time;
+  int64_t et = get_absolute_time_in_ns() - start_time;
 
   if ((debuglevel != 0) && (r != 0) && (debugmessage != NULL)) {
-    et = (et * 1000000) >> 32; // microseconds
     char errstr[1000];
     if (r == ETIMEDOUT)
       debug(debuglevel,
             "timed out waiting for a mutex, having waiting %f seconds, with a maximum "
             "waiting time of %d microseconds. \"%s\".",
-            (1.0 * et) / 1000000, dally_time, debugmessage);
+            (1.0 * et) / 1000000000, dally_time, debugmessage);
     else
       debug(debuglevel, "error %d: \"%s\" waiting for a mutex: \"%s\".", r,
             strerror_r(r, errstr, sizeof(errstr)), debugmessage);
@@ -1301,7 +1298,7 @@ int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char
     return pthread_mutex_lock(mutex);
   int oldState;
   pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState);
-  uint64_t time_at_start = get_absolute_time_in_fp();
+  uint64_t time_at_start = get_absolute_time_in_ns();
   char dstring[1000];
   memset(dstring, 0, sizeof(dstring));
   snprintf(dstring, sizeof(dstring), "%s:%d", filename, line);
@@ -1310,12 +1307,10 @@ int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char
   int result = sps_pthread_mutex_timedlock(mutex, dally_time, dstring, debuglevel);
   if (result == ETIMEDOUT) {
     result = pthread_mutex_lock(mutex);
-    uint64_t time_delay = get_absolute_time_in_fp() - time_at_start;
-    uint64_t divisor = (uint64_t)1 << 32;
-    double delay = 1.0 * time_delay / divisor;
+    uint64_t time_delay = get_absolute_time_in_ns() - time_at_start;
     debug(debuglevel,
           "mutex_lock \"%s\" at \"%s\" expected max wait: %0.9f, actual wait: %0.9f sec.",
-          mutexname, dstring, (1.0 * dally_time) / 1000000, delay);
+          mutexname, dstring, (1.0 * dally_time) / 1000000, 0.000000001 * time_delay);
   }
   pthread_setcancelstate(oldState, NULL);
   return result;
index 96d59b7da96f83b60785199eb390feedf73f8def..92095387a188a20cb3d54824426660be99a9a664 100644 (file)
--- a/common.h
+++ b/common.h
@@ -353,7 +353,7 @@ uint64_t get_absolute_time_in_fp(void);
 uint64_t get_absolute_time_in_ns(void);
 
 // time at startup for debugging timing
-extern uint64_t fp_time_at_startup, fp_time_at_last_debug_message;
+extern uint64_t ns_time_at_startup, ns_time_at_last_debug_message;
 
 // this is for reading an unsigned 32 bit number, such as an RTP timestamp
 
diff --git a/dacp.c b/dacp.c
index f3111a8382a3d9b65c3ea47906c53ff16b4f8cae..4c36de3473f4d6e306405288b02d242c06736c67 100644 (file)
--- a/dacp.c
+++ b/dacp.c
@@ -201,7 +201,7 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) {
       // debug(1,"Error %d \"%s\" at getaddrinfo.",ires,gai_strerror(ires));
       response.code = 498; // Bad Address information for the DACP server
     } else {
-      uint64_t start_time = get_absolute_time_in_fp();
+      uint64_t start_time = get_absolute_time_in_ns();
       pthread_cleanup_push(addrinfo_cleanup, (void *)&res);
       // only do this one at a time -- not sure it is necessary, but better safe than sorry
 
@@ -352,10 +352,9 @@ int dacp_send_command(const char *command, char **body, ssize_t *bodysize) {
       }
       pthread_cleanup_pop(1); // this should free the addrinfo
       // freeaddrinfo(res);
-      uint64_t et = get_absolute_time_in_fp() - start_time;
-      et = (et * 1000000) >> 32; // microseconds
+      uint64_t et = get_absolute_time_in_ns() - start_time; // this will be in nanoseconds
       debug(3, "dacp_send_command: %f seconds, response code %d, command \"%s\".",
-            (1.0 * et) / 1000000, response.code, command);
+            (1.0 * et) / 1000000000, response.code, command);
     }
     *body = response.body;
     *bodysize = response.size;
index 5876bd334a2ccfef2323a7fa9da81f277e0e4339..a034346c6b6e9cd8e83e553c740d1ef9d21fda03 100644 (file)
--- a/player.c
+++ b/player.c
@@ -124,7 +124,7 @@ static void ab_resync(rtsp_conn_info *conn) {
     conn->audio_buffer[i].ready = 0;
     conn->audio_buffer[i].resend_request_number = 0;
     conn->audio_buffer[i].resend_time = 0; // this is either zero or the time the last resend was requested.
-    conn->audio_buffer[i].initialisation_time = 0; // this is either the time the packet was received or the time it was noticed the packet was missing.    
+    conn->audio_buffer[i].initialisation_time = 0; // this is either the time the packet was received or the time it was noticed the packet was missing.
     conn->audio_buffer[i].sequence_number = 0;
   }
   conn->ab_synced = 0;
@@ -564,7 +564,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
       int rc = pthread_cond_signal(&conn->flowcontrol);
       if (rc)
         debug(1, "Error signalling flowcontrol.");
-      
+
       // resend checks
       {
        uint64_t minimum_wait_time = (uint64_t)(config.resend_control_first_check_time * (uint64_t)0x100000000);
@@ -572,7 +572,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
        uint64_t minimum_remaining_time = (uint64_t)((config.resend_control_last_check_time + config.audio_backend_buffer_desired_length)* (uint64_t)0x100000000);
        uint64_t latency_time = (uint64_t)(conn->latency * (uint64_t)0x100000000);
        latency_time = latency_time / (uint64_t)conn->input_rate;
-               
+
         int x;  // this is the first frame to be checked
         // if we detected a first empty frame before and if it's still in the buffer!
         if ((first_possibly_missing_frame >= 0) && (position_in_modulo_uint16_t_buffer(first_possibly_missing_frame, conn->ab_read, conn->ab_write, NULL))) {
@@ -580,9 +580,9 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
         } else {
           x = conn->ab_read;
         }
-        
+
         first_possibly_missing_frame = -1; // has not been set
-        
+
        int missing_frame_run_count = 0;
        int start_of_missing_frame_run = -1;
         int number_of_missing_frames = 0;
@@ -604,12 +604,12 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
             if (too_early)
               check_buf->status |= 1<<3; // too early
             else
-              check_buf->status &= 0xFF-(1<<3); // not too early                            
+              check_buf->status &= 0xFF-(1<<3); // not too early
             if (too_soon_after_last_request)
               check_buf->status |= 1<<4; // too soon after last request
             else
               check_buf->status &= 0xFF-(1<<4); // not too soon after last request
-                            
+
             if ((!too_soon_after_last_request) && (!too_late) && (!too_early)){
               if (start_of_missing_frame_run == -1) {
                 start_of_missing_frame_run = x;
@@ -619,7 +619,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
               }
               check_buf->resend_time = time_now; // setting the time to now because we are definitely going to take action
               check_buf->resend_request_number++;
-              debug(3,"Frame %d is missing with ab_read of %u and ab_write of %u.", x, conn->ab_read, conn->ab_write);            
+              debug(3,"Frame %d is missing with ab_read of %u and ab_write of %u.", x, conn->ab_read, conn->ab_write);
             }
             // if (too_late) {
             //   debug(1,"too late to get missing frame %u.", x);
@@ -631,13 +631,13 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, uint8_t *data, in
           if (((check_buf->ready) || (x == conn->ab_write)) && (missing_frame_run_count > 0)) {
           // send a resend request
                if (missing_frame_run_count > 1)
-                 debug(2,"request resend of %d packets starting at seqno %u.", missing_frame_run_count, start_of_missing_frame_run);         
+                 debug(2,"request resend of %d packets starting at seqno %u.", missing_frame_run_count, start_of_missing_frame_run);
             if (config.disable_resend_requests == 0) {
               debug_mutex_unlock(&conn->ab_mutex, 3);
               rtp_request_resend(start_of_missing_frame_run, missing_frame_run_count, conn);
               debug_mutex_lock(&conn->ab_mutex, 20000, 1);
               conn->resend_requests++;
-            }      
+            }
             start_of_missing_frame_run = -1;
             missing_frame_run_count = 0;
           }
@@ -1454,7 +1454,7 @@ static int stuff_buffer_basic_32(int32_t *inptr, int length, sps_format_t l_outp
 int32_t stat_n = 0;
 double stat_mean = 0.0;
 double stat_M2 = 0.0;
-double longest_soxr_execution_time_us = 0.0;
+double longest_soxr_execution_time = 0.0;
 int64_t packets_processed = 0;
 
 int stuff_buffer_soxr_32(int32_t *inptr, int32_t *scratchBuffer, int length,
@@ -1482,7 +1482,7 @@ int stuff_buffer_soxr_32(int32_t *inptr, int32_t *scratchBuffer, int length,
 
     size_t odone;
 
-    uint64_t soxr_start_time = get_absolute_time_in_fp();
+    uint64_t soxr_start_time = get_absolute_time_in_ns();
 
     soxr_error_t error = soxr_oneshot(length, length + tstuff, 2, // Rates and # of chans.
                                       inptr, length, NULL,        // Input.
@@ -1499,15 +1499,15 @@ int stuff_buffer_soxr_32(int32_t *inptr, int32_t *scratchBuffer, int length,
     // mean and variance calculations from "online_variance" algorithm at
     // https://en.wikipedia.org/wiki/Algorithms_for_calculating_variance#Online_algorithm
 
-    double soxr_execution_time_us =
-        (((get_absolute_time_in_fp() - soxr_start_time) * 1000000) >> 32) * 1.0;
+    double soxr_execution_time =
+        (get_absolute_time_in_ns() - soxr_start_time) * 0.000000001;
     // debug(1,"soxr_execution_time_us: %10.1f",soxr_execution_time_us);
-    if (soxr_execution_time_us > longest_soxr_execution_time_us)
-      longest_soxr_execution_time_us = soxr_execution_time_us;
+    if (soxr_execution_time > longest_soxr_execution_time)
+      longest_soxr_execution_time = soxr_execution_time;
     stat_n += 1;
-    double stat_delta = soxr_execution_time_us - stat_mean;
+    double stat_delta = soxr_execution_time - stat_mean;
     stat_mean += stat_delta / stat_n;
-    stat_M2 += stat_delta * (soxr_execution_time_us - stat_mean);
+    stat_M2 += stat_delta * (soxr_execution_time - stat_mean);
 
     int i;
     int32_t *ip, *op;
@@ -1553,15 +1553,15 @@ int stuff_buffer_soxr_32(int32_t *inptr, int32_t *scratchBuffer, int length,
   }
 
   if (packets_processed % 1250 == 0) {
-    debug(3, "soxr_oneshot execution time in microseconds: mean, standard deviation and max "
+    debug(3, "soxr_oneshot execution time in nanoseconds: mean, standard deviation and max "
              "for %" PRId32 " interpolations in the last "
-             "1250 packets. %10.1f, %10.1f, %10.1f.",
+             "1250 packets. %10.6f, %10.6f, %10.6f.",
           stat_n, stat_mean, stat_n <= 1 ? 0.0 : sqrtf(stat_M2 / (stat_n - 1)),
-          longest_soxr_execution_time_us);
+          longest_soxr_execution_time);
     stat_n = 0;
     stat_mean = 0.0;
     stat_M2 = 0.0;
-    longest_soxr_execution_time_us = 0.0;
+    longest_soxr_execution_time = 0.0;
   }
 
   conn->amountStuffed = tstuff;
@@ -2365,11 +2365,11 @@ void *player_thread_func(void *arg) {
                 amount_to_stuff = 0; // no stuffing if it's been disabled
 
               // Apply DSP here
-              
+
               // check the state of loudness and convolution flags here and don't change them for the frame
-              
+
               int do_loudness = config.loudness;
-    
+
 
 #ifdef CONFIG_CONVOLUTION
               int do_convolution = 0;
@@ -2377,12 +2377,12 @@ void *player_thread_func(void *arg) {
                 do_convolution = 1;
 
               // we will apply the convolution gain if convolution is enabled, even if there is no valid convolution happening
-              
+
               int convolution_is_enabled = 0;
               if (config.convolution)
                 convolution_is_enabled = 1;
 #endif
-                
+
               if (do_loudness
 #ifdef CONFIG_CONVOLUTION
                   || convolution_is_enabled
@@ -2533,7 +2533,7 @@ void *player_thread_func(void *arg) {
 
           // update the watchdog
           if ((config.dont_check_timeout == 0) && (config.timeout != 0)) {
-            uint64_t time_now = get_absolute_time_in_fp();
+            uint64_t time_now = get_absolute_time_in_ns();
             debug_mutex_lock(&conn->watchdog_mutex, 1000, 0);
             conn->watchdog_bark_time = time_now;
             debug_mutex_unlock(&conn->watchdog_mutex, 0);
@@ -2620,12 +2620,8 @@ void *player_thread_func(void *arg) {
               conn->frame_rate_status = 0;
             if (conn->frame_rate_status) {
               conn->frame_rate =
-                  (1.0 * frames_played) /
+                  (1000000000.0 * frames_played) /
                   elapsed_play_time; // an IEEE double calculation with two 64-bit integers
-              conn->frame_rate =
-                  conn->frame_rate * (uint64_t)0x100000000; // this should just change the [binary]
-              // exponent in the IEEE FP representation;
-              // the mantissa should be unaffected.
             } else {
               conn->frame_rate = 0.0;
             }
@@ -2758,7 +2754,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
 
   int32_t hw_max_db = 0, hw_min_db = 0; // zeroed to quieten an incorrect uninitialised warning
   int32_t sw_max_db = 0, sw_min_db = -9630;
-  
+
   if (config.output->parameters) {
     volume_mode = vol_hw_only;
     audio_parameters audio_information;
@@ -2928,7 +2924,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
       if (config.logOutputLevel) {
         inform("Output Level set to: %.2f dB.", scaled_attenuation / 100.0);
       }
-      
+
 #ifdef CONFIG_METADATA
   // here, send the 'pvol' metadata message when the airplay volume information
   // is being used by shairport sync to control the output volume
@@ -2938,7 +2934,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
         if (volume_mode == vol_both) {
           // normalise the maximum output to the hardware device's max output
           snprintf(dv, 127, "%.2f,%.2f,%.2f,%.2f", airplay_volume, (scaled_attenuation - max_db + hw_max_db) / 100.0,
-                   (min_db - max_db + hw_max_db) / 100.0, (max_db - max_db + hw_max_db) / 100.0);        
+                   (min_db - max_db + hw_max_db) / 100.0, (max_db - max_db + hw_max_db) / 100.0);
         } else {
           snprintf(dv, 127, "%.2f,%.2f,%.2f,%.2f", airplay_volume, scaled_attenuation / 100.0,
                    min_db / 100.0, max_db / 100.0);
@@ -2972,7 +2968,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
   }
 #endif
 
+
   // here, store the volume for possible use in the future
   config.airplay_volume = airplay_volume;
   debug_mutex_unlock(&conn->volume_control_mutex, 3);
diff --git a/rtsp.c b/rtsp.c
index 6cf5392762409e440498c2e753daca008d1997c5..dca0ecb57b8ee874278fdfdc950b77d6dbc84744 100644 (file)
--- a/rtsp.c
+++ b/rtsp.c
@@ -286,7 +286,7 @@ void *player_watchdog_thread_code(void *arg) {
       uint64_t last_watchdog_bark_time = conn->watchdog_bark_time;
       debug_mutex_unlock(&conn->watchdog_mutex, 0);
       if (last_watchdog_bark_time != 0) {
-        uint64_t time_since_last_bark = (get_absolute_time_in_fp() - last_watchdog_bark_time) >> 32;
+        uint64_t time_since_last_bark = (get_absolute_time_in_ns() - last_watchdog_bark_time) / 1000000000;
         uint64_t ct = config.timeout; // go from int to 64-bit int
 
         if (time_since_last_bark >= ct) {
@@ -666,7 +666,7 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes
   }
 
   uint64_t threshold_time =
-      get_absolute_time_in_fp() + ((uint64_t)15 << 32); // i.e. fifteen seconds from now
+      get_absolute_time_in_ns() + ((uint64_t)15000000000); // i.e. fifteen seconds from now
   int warning_message_sent = 0;
 
   const size_t max_read_chunk = 1024 * 1024 / 16;
@@ -679,7 +679,7 @@ enum rtsp_read_request_response rtsp_read_request(rtsp_conn_info *conn, rtsp_mes
     // metadata
 
     if (warning_message_sent == 0) {
-      uint64_t time_now = get_absolute_time_in_fp();
+      uint64_t time_now = get_absolute_time_in_ns();
       if (time_now > threshold_time) { // it's taking too long
         debug(1, "Error receiving metadata from source -- transmission seems "
                  "to be stalled.");
@@ -2319,7 +2319,7 @@ static void *rtsp_conversation_thread_func(void *pconn) {
   rtsp_conn_info *conn = pconn;
 
   // create the watchdog mutex, initialise the watchdog time and start the watchdog thread;
-  conn->watchdog_bark_time = get_absolute_time_in_fp();
+  conn->watchdog_bark_time = get_absolute_time_in_ns();
   pthread_mutex_init(&conn->watchdog_mutex, NULL);
   pthread_create(&conn->player_watchdog_thread, NULL, &player_watchdog_thread_code, (void *)conn);
 
index 5e375916c3802f8a77e4faf09363ec09db609dc3..881ecd97b0ca02b02cccef660a5326896f16c333 100644 (file)
@@ -143,10 +143,10 @@ void *soxr_time_check(__attribute__((unused)) void *arg) {
   int i;
 
   int number_of_iterations = 0;
-  uint64_t soxr_start_time = get_absolute_time_in_fp();
+  uint64_t soxr_start_time = get_absolute_time_in_ns();
   uint64_t loop_until_time =
-      (uint64_t)0x180000000 + soxr_start_time; // loop for a second and a half, max -- no need to be able to cancel it, do _don't even try_!
-  while (get_absolute_time_in_fp() < loop_until_time) {
+      (uint64_t)1500000000 + soxr_start_time; // loop for a second and a half, max -- no need to be able to cancel it, do _don't even try_!
+  while (get_absolute_time_in_ns() < loop_until_time) {
 
     number_of_iterations++;
     for (i = 0; i < buffer_length; i++) {
@@ -184,11 +184,11 @@ void *soxr_time_check(__attribute__((unused)) void *arg) {
                  NULL, NULL);                          // Default configuration.
   }
 
-  double soxr_execution_time_us =
-      (((get_absolute_time_in_fp() - soxr_start_time) * 1000000) >> 32) * 1.0;
+  double soxr_execution_time_ns =
+      (get_absolute_time_in_ns() - soxr_start_time) * 1.0;
   // free(outbuffer);
   // free(inbuffer);
-  config.soxr_delay_index = (int)(0.9 + soxr_execution_time_us / (number_of_iterations * 1000));
+  config.soxr_delay_index = (int)(0.9 + soxr_execution_time_ns / (number_of_iterations * 1000000));
   debug(2, "soxr_delay_index: %d.", config.soxr_delay_index);
   if ((config.packet_stuffing == ST_soxr) &&
       (config.soxr_delay_index > config.soxr_delay_threshold))
@@ -1393,8 +1393,8 @@ int main(int argc, char **argv) {
   conns = NULL; // no connections active
   memset((void *)&main_thread_id, 0, sizeof(main_thread_id));
   memset(&config, 0, sizeof(config)); // also clears all strings, BTW
-  fp_time_at_startup = get_absolute_time_in_fp();
-  fp_time_at_last_debug_message = fp_time_at_startup;
+  ns_time_at_startup = get_absolute_time_in_ns();
+  ns_time_at_last_debug_message = ns_time_at_startup;
   // this is a bit weird, but necessary -- basename() may modify the argument passed in
   char *basec = strdup(argv[0]);
   char *bname = basename(basec);