Make the idle timeout on the RTSP link the same as the overall timeout -- 30 seconds is a bit short. Add checks to the alsa interface timing -- 15 ms to write a packet of frames, 1 ms to ask for the delay.

2018-12-08 14:12:33 +00:00
parent 50700b46a5
commit e5452e5172
4 changed files with 69 additions and 20 deletions
@@ -216,6 +216,10 @@ static int init(int argc, char **argv) {
  config.audio_backend_latency_offset = 0;
  config.audio_backend_buffer_desired_length = 0.15;

+  config.alsa_maximum_write_time = 0.016; // 16 milliseconds -- if it takes longer, we need to know
+  config.alsa_maximum_interface_response_time =
+      0.001; // one millisecond -- if it takes longer, we need to know
+
  // get settings from settings file first, allow them to be overridden by
  // command line options

@@ -223,6 +227,7 @@ static int init(int argc, char **argv) {
  parse_general_audio_options();

  if (config.cfg != NULL) {
+    double dvalue;

    /* Get the Output Device Name. */
    if (config_lookup_string(config.cfg, "alsa.output_device", &str)) {
@@ -371,6 +376,28 @@ static int init(int argc, char **argv) {
        buffer_size_requested = value;
      }
    }
+
+    /* Get the optional alsa_maximum_interface_response_time setting. */
+    if (config_lookup_float(config.cfg, "alsa.maximum_interface_response_time", &dvalue)) {
+      if (dvalue < 0.0) {
+        warn("Invalid alsa maximum interface response time setting \"%f\". It "
+             "must be greater than 0. Default is \"%f\". No setting is made.",
+             dvalue, config.alsa_maximum_interface_response_time);
+      } else {
+        config.alsa_maximum_interface_response_time = dvalue;
+      }
+    }
+
+    /* Get the optional alsa_maximum_write_time setting. */
+    if (config_lookup_float(config.cfg, "alsa.maximum_write_time", &dvalue)) {
+      if (dvalue < 0.0) {
+        warn("Invalid alsa maximum write time setting \"%f\". It "
+             "must be greater than 0. Default is \"%f\". No setting is made.",
+             dvalue, config.alsa_maximum_write_time);
+      } else {
+        config.alsa_maximum_write_time = dvalue;
+      }
+    }
  }

  optind = 1; // optind=0 is equivalent to optind=1 plus special behaviour
@@ -956,12 +983,15 @@ int delay(long *the_delay) {
  } else {
    int oldState;
    pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldState); // make this un-cancellable
-    pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 1);
+    pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0);
    int derr;
    snd_pcm_state_t dac_state = snd_pcm_state(alsa_handle);
    if (dac_state == SND_PCM_STATE_RUNNING) {
      *the_delay = 0; // just to see what happens
+      uint64_t time_before = get_absolute_time_in_fp();
      reply = snd_pcm_delay(alsa_handle, the_delay);
+      uint64_t response_time = get_absolute_time_in_fp() - time_before;
+
      if (reply != 0) {
        debug(1, "Error %d in delay(): \"%s\". Delay reported is %d frames.", reply,
              snd_strerror(reply), *the_delay);
@@ -979,6 +1009,15 @@ int delay(long *the_delay) {
          measurement_data_is_valid = 0;
        }
      }
+      uint64_t maximum_permitted_response_time =
+          (uint64_t)(config.alsa_maximum_interface_response_time * 1000000); // microseconds
+      maximum_permitted_response_time = (maximum_permitted_response_time << 32) / 1000000;
+      if (response_time > maximum_permitted_response_time) {
+        debug(3, "Maximum response time of %8.2f us exceeded reading delay. Response time was "
+                 "%12.2f us.",
+              (1000000.0 * maximum_permitted_response_time) / (uint64_t)0x100000000,
+              (1000000.0 * response_time) / (uint64_t)0x100000000);
+      }
    } else {
      reply = -EIO;    // shomething is wrong
      frame_index = 0; // we'll be starting over...
@@ -1066,13 +1105,15 @@ static int play(void *buf, int samples) {
      if (samples == 0)
        debug(1, "empty buffer being passed to pcm_writei -- skipping it");
      if ((samples != 0) && (buf != NULL)) {
-        debug(3, "write %d frames.", samples);
-        uint64_t nominal_playing_time = samples;
-        nominal_playing_time = (nominal_playing_time << 32) / desired_sample_rate;        
+        // debug(3, "write %d frames.", samples);
+
+        uint64_t maximum_permitted_writing_time = (config.alsa_maximum_write_time * 1000000000);
+        maximum_permitted_writing_time = (maximum_permitted_writing_time << 32) / 1000000000;
+
        uint64_t time_before = get_absolute_time_in_fp();
        err = alsa_pcm_write(alsa_handle, buf, samples);
        uint64_t writing_time = get_absolute_time_in_fp() - time_before;
-        
+
        if (err < 0) {
          frame_index = 0;
          measurement_data_is_valid = 0;
@@ -1084,11 +1125,14 @@ static int play(void *buf, int samples) {
                 "play():  \"%s\".",
                 err, samples, snd_strerror(err));
        }
-        
-        if (writing_time > nominal_playing_time) {
-          debug(1,"Taking too long to write %d samples. Playing time: %8.2f us, writing time: %8.2f us.", samples,(1000000.0 * nominal_playing_time)/(uint64_t)0x100000000, (1000000.0 * writing_time)/(uint64_t)0x100000000);
+
+        if (writing_time > maximum_permitted_writing_time) {
+          debug(3, "Taking too long to write %d samples. Playing time: %8.2f us, writing time: "
+                   "%8.2f us.",
+                samples, (1000000.0 * maximum_permitted_writing_time) / (uint64_t)0x100000000,
+                (1000000.0 * writing_time) / (uint64_t)0x100000000);
        }
-        
+
        if (frame_index == 0) {
          frames_sent_for_playing = samples;
        } else {
@@ -184,6 +184,10 @@ typedef struct {
  int loudness;
  float loudness_reference_volume_db;
  int alsa_use_hardware_mute;
+
+  double alsa_maximum_interface_response_time;
+  double alsa_maximum_write_time;
+
 #if defined(CONFIG_DBUS_INTERFACE)
  enum dbus_session_type dbus_service_bus_type;
 #endif
@@ -377,7 +377,7 @@ void *rtp_control_receiver(void *arg) {
              }
            }

-            debug_mutex_lock(&conn->reference_time_mutex, 1000, 1);
+            debug_mutex_lock(&conn->reference_time_mutex, 1000, 0);

            if (conn->packet_stream_established) {
              if (conn->initial_reference_time == 0) {
@@ -414,7 +414,7 @@ void *rtp_control_receiver(void *arg) {
            //    remote_time_of_sync - local_to_remote_time_difference_now(conn);
            conn->reference_timestamp = sync_rtp_timestamp;
            conn->latency_delayed_timestamp = rtp_timestamp_less_latency;
-            debug_mutex_unlock(&conn->reference_time_mutex, 3);
+            debug_mutex_unlock(&conn->reference_time_mutex, 0);

            conn->reference_to_previous_time_difference =
                remote_time_of_sync - old_remote_reference_time;
@@ -273,7 +273,7 @@ void *player_watchdog_thread_code(void *arg) {
  rtsp_conn_info *conn = (rtsp_conn_info *)arg;
  do {
    usleep(2000000); // check every two seconds
-    debug(3, "Connection %d: Check the thread is doing something...", conn->connection_number);
+    // debug(3, "Connection %d: Check the thread is doing something...", conn->connection_number);
    if ((config.dont_check_timeout == 0) && (config.timeout != 0)) {
      debug_mutex_lock(&conn->watchdog_mutex, 1000, 0);
      uint64_t last_watchdog_bark_time = conn->watchdog_bark_time;
@@ -482,9 +482,9 @@ static void debug_print_msg_content(int level, rtsp_message *msg) {
 void msg_free(rtsp_message *msg) {

  if (msg) {
-    debug_mutex_lock(&reference_counter_lock, 1000, 3);
+    debug_mutex_lock(&reference_counter_lock, 1000, 0);
    msg->referenceCount--;
-    debug_mutex_unlock(&reference_counter_lock, 3);
+    debug_mutex_unlock(&reference_counter_lock, 0);
    if (msg->referenceCount == 0) {
      unsigned int i;
      for (i = 0; i < msg->nheaders; i++) {
@@ -2151,7 +2151,7 @@ void rtsp_conversation_thread_cleanup_function(void *arg) {
 }

 void msg_cleanup_function(void *arg) {
-  debug(3, "msg_cleanup_function called.");
+  // debug(3, "msg_cleanup_function called.");
  msg_free((rtsp_message *)arg);
 }

@@ -2409,11 +2409,12 @@ void rtsp_listen_loop(void) {
    if (setsockopt(fd, SOL_SOCKET, SO_SNDTIMEO, (const char *)&tv, sizeof tv) == -1)
      debug(1, "Error %d setting send timeout for rtsp writeback.", errno);

-    tv.tv_sec = 30; // 30 seconds read timeout
-    tv.tv_usec = 0;
-    if (setsockopt(fd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1)
-      debug(1, "Error %d setting send timeout for rtsp writeback.", errno);
-
+    if ((config.dont_check_timeout == 0) && (config.timeout != 0)) {
+      tv.tv_sec = config.timeout; // 120 seconds read timeout by default.
+      tv.tv_usec = 0;
+      if (setsockopt(fd, SOL_SOCKET, SO_RCVTIMEO, (const char *)&tv, sizeof tv) == -1)
+        debug(1, "Error %d setting read timeout for rtsp connection.", errno);
+    }
 #ifdef IPV6_V6ONLY
    // some systems don't support v4 access on v6 sockets, but some do.
    // since we need to account for two sockets we might as well