From: Mike Brady <mikebrady@eircom.net>
Date: Fri, 1 Jun 2018 15:00:20 +0000 (+0100)
Subject: add some more debugging messages.
X-Git-Tag: 3.2RC11~3^2~14
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=eee822b932cd46f2c1a87e5cf17fb862b0afa117;p=thirdparty%2Fshairport-sync.git

add some more debugging messages.
---

diff --git a/common.c b/common.c
index ae87d6c4..306b3c2f 100644
--- a/common.c
+++ b/common.c
@@ -1026,11 +1026,12 @@ int sps_pthread_mutex_timedlock(pthread_mutex_t *mutex, useconds_t dally_time,
     time_to_wait -= st;
     r = pthread_mutex_trylock(mutex);
   }
-  if (r != 0) {
+  if ((r != 0) && (debugmessage != NULL)) {
     char errstr[1000];
     if (r == EBUSY)
-      debug(debuglevel, "timeout at %d microseconds while waiting for a mutex: \"%s\".", dally_time,
-            debugmessage);
+      debug(debuglevel,
+            "waiting for a mutex, maximum expected time of %d microseconds exceeded \"%s\".",
+            dally_time, debugmessage);
     else
       debug(debuglevel, "error %d: \"%s\" waiting for a mutex: \"%s\".", r,
             strerror_r(r, errstr, sizeof(errstr)), debugmessage);
@@ -1051,7 +1052,9 @@ int _debug_mutex_lock(pthread_mutex_t *mutex, useconds_t dally_time, const char
     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;
-    debug(debuglevel, "debug_mutex_lock  at \"%s\" -- wait time: %0.9f sec.", dstring, delay);
+    debug(debuglevel,
+          "debug_mutex_lock at \"%s\" expected max wait: %0.9f, actual wait: %0.9f sec.", dstring,
+          (1.0 * dally_time) / 1000000, delay);
   }
   return result;
 }
diff --git a/player.c b/player.c
index e5d8d995..ed844f6a 100644
--- a/player.c
+++ b/player.c
@@ -484,7 +484,7 @@ void player_put_packet(seq_t seqno, uint32_t actual_timestamp, int64_t timestamp
         debug_mutex_unlock(&conn->flush_mutex, 3);
       }
 
-      debug_mutex_lock(&conn->ab_mutex, 20000, 1);
+      debug_mutex_lock(&conn->ab_mutex, 30000, 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
@@ -791,7 +791,7 @@ static abuf_t *buffer_get_frame(rtsp_conn_info *conn) {
   abuf_t *curframe = 0;
   int notified_buffer_empty = 0; // diagnostic only
 
-  debug_mutex_lock(&conn->ab_mutex, 20000, 1);
+  debug_mutex_lock(&conn->ab_mutex, 30000, 1);
   int wait;
   long dac_delay = 0; // long because alsa returns a long
   do {