From: Mike Brady Date: Fri, 1 Jun 2018 07:29:48 +0000 (+0100) Subject: Replace all pthread_mutex_locks with debug_mutex_lock with a message and timer. Not... X-Git-Tag: 3.2RC11~3^2~20 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=18b37ea25423b4c7a8067c1ce0780f8a321b8bef;p=thirdparty%2Fshairport-sync.git Replace all pthread_mutex_locks with debug_mutex_lock with a message and timer. Not really tested. --- diff --git a/audio_alsa.c b/audio_alsa.c index 09903519..b1e4d1f8 100644 --- a/audio_alsa.c +++ b/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); diff --git a/common.c b/common.c index e835ab67..41218609 100644 --- a/common.c +++ b/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) { diff --git a/common.h b/common.h index e749d5f3..8878c390 100644 --- a/common.h +++ b/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 diff --git a/player.c b/player.c index 9e5dce1f..e7767e4a 100644 --- a/player.c +++ b/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; diff --git a/rtp.c b/rtp.c index 01c7706d..01f71c3f 100644 --- a/rtp.c +++ b/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);