Replace all pthread_mutex_locks with debug_mutex_lock with a message and timer. Not really tested.

audio_alsa.c

@@ -166,7 +166,7 @@ void do_snd_mixer_selem_set_playback_dB_all(snd_mixer_elem_t *mix_elem, double v
 }
 
 static int init(int argc, char **argv) {
-  pthread_mutex_lock(&alsa_mutex);
+  debug_mutex_lock(&alsa_mutex, 1000, 1);
   // debug(2,"audio_alsa init called.");
   const char *str;
   int value;
@@ -227,7 +227,7 @@ static int init(int argc, char **argv) {
     /* Get the mute_using_playback_switch setting. */
     if (config_lookup_string(config.cfg, "alsa.mute_using_playback_switch", &str)) {
       inform("The alsa \"mute_using_playback_switch\" setting is deprecated. "
-             "Please use the \"use_hardware_mute_if_available\" setting instead.");      
+             "Please use the \"use_hardware_mute_if_available\" setting instead.");
       if (strcasecmp(str, "no") == 0)
         config.alsa_use_hardware_mute = 0;
       else if (strcasecmp(str, "yes") == 0)
@@ -817,7 +817,7 @@ int delay(long *the_delay) {
   if (alsa_handle == NULL) {
     return -ENODEV;
   } else {
-    pthread_mutex_lock(&alsa_mutex);
+    debug_mutex_lock(&alsa_mutex, 10000, 1);
     int derr;
     if (snd_pcm_state(alsa_handle) == SND_PCM_STATE_RUNNING) {
       *the_delay = 0; // just to see what happens
@@ -855,7 +855,7 @@ static void play(void *buf, int samples) {
   // debug(3,"audio_alsa play called.");
   int ret = 0;
   if (alsa_handle == NULL) {
-    pthread_mutex_lock(&alsa_mutex);
+    debug_mutex_lock(&alsa_mutex, 10000, 1);
     ret = open_alsa_device();
     if (ret == 0) {
       if (audio_alsa.volume)
@@ -866,7 +866,7 @@ static void play(void *buf, int samples) {
     pthread_mutex_unlock(&alsa_mutex);
   }
   if (ret == 0) {
-    pthread_mutex_lock(&alsa_mutex);
+    debug_mutex_lock(&alsa_mutex, 10000, 1);
     //    snd_pcm_sframes_t current_delay = 0;
     int err;
     if (snd_pcm_state(alsa_handle) == SND_PCM_STATE_XRUN) {
@@ -903,7 +903,7 @@ static void play(void *buf, int samples) {
 
 static void flush(void) {
   // debug(2,"audio_alsa flush called.");
-  pthread_mutex_lock(&alsa_mutex);
+  debug_mutex_lock(&alsa_mutex, 10000, 1);
   int derr;
   do_mute(1);
   if (alsa_handle) {
@@ -973,7 +973,7 @@ void do_volume(double vol) { // caller is assumed to have the alsa_mutex when us
 }
 
 void volume(double vol) {
-  pthread_mutex_lock(&alsa_mutex);
+  debug_mutex_lock(&alsa_mutex, 1000, 1);
   volume_set_request = 1; // an external request has been made to set the volume
   do_volume(vol);
   pthread_mutex_unlock(&alsa_mutex);
@@ -999,7 +999,7 @@ static void linear_volume(double vol) {
 
 static void mute(int mute_state_requested) {
   // debug(1,"External Mute Request: %d",mute_state_requested);
-  pthread_mutex_lock(&alsa_mutex);
+  debug_mutex_lock(&alsa_mutex, 10000, 1);
   mute_request_pending = 1;
   overriding_mute_state_requested = mute_state_requested;
   do_mute(mute_state_requested);

common.c

@@ -795,17 +795,16 @@ uint64_t get_absolute_time_in_fp() {
   // 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)
+  if (tnfpsec > 0x100000000)
     warn("clock_gettime seconds overflow!");
   uint64_t tnfpnsec = tn.tv_nsec;
-  if (tnfpnsec>0x100000000)
+  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
+  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;
@@ -1014,15 +1013,9 @@ void sps_nanosleep(const time_t sec, const long nanosec) {
     debug(1, "Error in sps_nanosleep of %d sec and %ld nanoseconds: %d.", sec, nanosec, errno);
 }
 
-char *previous_debug_message = NULL;
-
 int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time,
                                 const char *debugmessage, int debuglevel) {
 
-  if (previous_debug_message)
-    free(previous_debug_message);
-  previous_debug_message = strdup(debugmessage);
-
   useconds_t time_to_wait = dally_time;
   int r = pthread_mutex_trylock(mutex);
   while ((r == EBUSY) && (time_to_wait > 0)) {
@@ -1036,17 +1029,26 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time,
   if (r != 0) {
     char errstr[1000];
     if (r == EBUSY)
-      debug(debuglevel,
-            "error EBUSY waiting for a mutex: \"%s\". Previous debug message was: \"%s\".",
-            debugmessage, previous_debug_message);
+      debug(debuglevel, "timeout at %d microseconds while waiting for a mutex: \"%s\".", dally_time,
+            debugmessage);
     else
-      debug(debuglevel,
-            "error %d: \"%s\" waiting for a mutex: \"%s\". Previous debug message was: \"%s\".", r,
-            strerror_r(r, errstr, sizeof(errstr)), debugmessage, previous_debug_message);
+      debug(debuglevel, "error %d: \"%s\" waiting for a mutex: \"%s\".", r,
+            strerror_r(r, errstr, sizeof(errstr)), debugmessage);
   }
   return r;
 }
 
+int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char *filename,
+                      const int line, int debuglevel) {
+  char dstring[1000];
+  memset(dstring, 0, sizeof(dstring));
+  snprintf(dstring, sizeof(dstring), "%s%d", filename, line);
+  int result = sps_pthread_mutex_timedlock(mutex, dally_time, dstring, debuglevel);
+  if (result == EBUSY)
+    result = pthread_mutex_lock(mutex);
+  return result;
+}
+
 char *get_version_string() {
   char *version_string = malloc(200);
   if (version_string) {

common.h

@@ -264,6 +264,12 @@ extern sigset_t pselect_sigset;
 // wait for the specified time in microseconds -- it checks every 20 milliseconds
 int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time,
                                 const char *debugmessage, int debuglevel);
+// wait for the specified time, checking every 20 milliseconds, and block if it can't acquire the
+// lock
+int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char *filename,
+                      const int line, int debuglevel);
+
+#define debug_mutex_lock(mu, t, d) _debug_mutex_lock(mu, t, __FILE__, __LINE__, d)
 
 char *get_version_string(); // mallocs a string space -- remember to free it afterwards
 

player.c

@@ -478,13 +478,13 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp
 
       // ignore a request to flush that has been made before the first packet...
       if (conn->packet_count == 0) {
-        pthread_mutex_lock(&conn->flush_mutex);
+        debug_mutex_lock(&conn->flush_mutex, 1000, 1);
         conn->flush_requested = 0;
         conn->flush_rtp_timestamp = 0;
         pthread_mutex_unlock(&conn->flush_mutex);
       }
 
-      pthread_mutex_lock(&conn->ab_mutex);
+      debug_mutex_lock(&conn->ab_mutex, 10000, 1);
       conn->packet_count++;
       conn->time_of_last_audio_packet = get_absolute_time_in_fp();
       if (conn->connection_state_to_output) { // if we are supposed to be processing these packets
@@ -787,13 +787,12 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
   abuf_t *curframe = 0;
   int notified_buffer_empty = 0; // diagnostic only
 
-  pthread_mutex_lock(&conn->ab_mutex);
+  debug_mutex_lock(&conn->ab_mutex, 10000, 1);
   int wait;
   long dac_delay = 0; // long because alsa returns a long
   do {
     // get the time
     local_time_now = get_absolute_time_in_fp(); // type okay
-
     // if config.timeout (default 120) seconds have elapsed since the last audio packet was
     // received, then we should stop.
     // config.timeout of zero means don't check..., but iTunes may be confused by a long gap
@@ -818,13 +817,13 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
       conn->connection_state_to_output = rco;
       // change happening
       if (conn->connection_state_to_output == 0) { // going off
-        pthread_mutex_lock(&conn->flush_mutex);
+        debug_mutex_lock(&conn->flush_mutex, 1000, 1);
         conn->flush_requested = 1;
         pthread_mutex_unlock(&conn->flush_mutex);
       }
     }
 
-    pthread_mutex_lock(&conn->flush_mutex);
+    debug_mutex_lock(&conn->flush_mutex, 1000, 1);
     if (conn->flush_requested == 1) {
       if (config.output->flush)
         config.output->flush();
@@ -1201,6 +1200,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
            (!conn->player_thread_please_stop);
 
     if (wait) {
+      debug(3, "buffer_get_frame is iterating");
       uint64_t time_to_wait_for_wakeup_fp =
           ((uint64_t)1 << 32) / conn->input_rate; // this is time period of one frame
       time_to_wait_for_wakeup_fp *= 4 * 352;      // four full 352-frame packets
@@ -1294,7 +1294,7 @@ static int stuff_buffer_basic_32(int32_t *inptr, int length, enum sps_format_t l
     stuffsamp =
         (rand() % (length - 2)) + 1; // ensure there's always a sample before and after the item
 
-  pthread_mutex_lock(&conn->vol_mutex);
+  debug_mutex_lock(&conn->vol_mutex, 1000, 1);
   for (i = 0; i < stuffsamp; i++) { // the whole frame, if no stuffing
     process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn);
     process_sample(*inptr++, &l_outptr, l_output_format, conn->fix_volume, dither, conn);
@@ -2582,7 +2582,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c
   // debug(1,"Software attenuation set to %f, i.e %f out of 65,536, for airplay volume of
   // %f",software_attenuation,temp_fix_volume,airplay_volume);
 
-  pthread_mutex_lock(&conn->vol_mutex);
+  debug_mutex_lock(&conn->vol_mutex, 1000, 1);
   conn->fix_volume = temp_fix_volume;
   pthread_mutex_unlock(&conn->vol_mutex);
 
@@ -2617,7 +2617,7 @@ void player_volume(double airplay_volume, rtsp_conn_info *conn) {
 
 void do_flush(int64_t timestamp, rtsp_conn_info *conn) {
   debug(3, "Flush requested up to %u. It seems as if 0 is special.", timestamp);
-  pthread_mutex_lock(&conn->flush_mutex);
+  debug_mutex_lock(&conn->flush_mutex, 1000, 1);
   conn->flush_requested = 1;
   // if (timestamp!=0)
   conn->flush_rtp_timestamp = timestamp; // flush all packets up to (and including?) this
@@ -2679,15 +2679,15 @@ int player_play(rtsp_conn_info *conn) {
 }
 
 int player_stop(rtsp_conn_info *conn) {
-	debug(3,"player_stop");
+  debug(3, "player_stop");
   pthread_rwlock_wrlock(&conn->player_thread_lock);
-	debug(3,"player_thread_lock acquired");
+  debug(3, "player_thread_lock acquired");
   if (conn->player_thread) {
-		debug(3,"player_thread exists");
+    debug(3, "player_thread exists");
     conn->player_thread_please_stop = 1;
     pthread_cond_signal(&conn->flowcontrol); // tell it to give up
     pthread_kill(*conn->player_thread, SIGUSR1);
-		debug(3,"player_thread signalled");
+    debug(3, "player_thread signalled");
     pthread_join(*conn->player_thread, NULL);
     free(conn->player_thread);
     conn->player_thread = NULL;

rtp.c

@@ -328,7 +328,7 @@ void *rtp_control_receiver(void *arg) {
               }
             }
 
-            pthread_mutex_lock(&conn->reference_time_mutex);
+            debug_mutex_lock(&conn->reference_time_mutex, 1000, 1);
 
             // this is for debugging
             // uint64_t old_remote_reference_time = conn->remote_reference_timestamp_time;
@@ -812,8 +812,8 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, uint16_t cport, uint16_t tport
     inet_ntop(conn->connection_ip_family, self_addr, conn->self_ip_string,
               sizeof(conn->self_ip_string));
 
-    debug(2, "Connection %d: SETUP -- Connection from %s to self at %s.",
-          conn->connection_number,conn->client_ip_string, conn->self_ip_string);
+    debug(2, "Connection %d: SETUP -- Connection from %s to self at %s.", conn->connection_number,
+          conn->client_ip_string, conn->self_ip_string);
 
     // set up a the record of the remote's control socket
     struct addrinfo hints;
@@ -891,7 +891,7 @@ void rtp_setup(SOCKADDR *local, SOCKADDR *remote, uint16_t cport, uint16_t tport
 void get_reference_timestamp_stuff(int64_t *timestamp, uint64_t *timestamp_time,
                                    uint64_t *remote_timestamp_time, rtsp_conn_info *conn) {
   // types okay
-  pthread_mutex_lock(&conn->reference_time_mutex);
+  debug_mutex_lock(&conn->reference_time_mutex, 1000, 1);
   *timestamp = conn->reference_timestamp;
   *timestamp_time = conn->reference_timestamp_time;
   // if ((*timestamp == 0) && (*timestamp_time == 0)) {
@@ -902,7 +902,7 @@ void get_reference_timestamp_stuff(int64_t *timestamp, uint64_t *timestamp_time,
 }
 
 void clear_reference_timestamp(rtsp_conn_info *conn) {
-  pthread_mutex_lock(&conn->reference_time_mutex);
+  debug_mutex_lock(&conn->reference_time_mutex, 1000, 1);
   conn->reference_timestamp = 0;
   conn->reference_timestamp_time = 0;
   pthread_mutex_unlock(&conn->reference_time_mutex);