From: Mike Brady Date: Mon, 24 Feb 2020 19:40:44 +0000 (+0000) Subject: partial move to using a nanosecond-based system timer. More to come. X-Git-Tag: 3.3.7d12~120 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=67e9b1b6cd2efd23532a618ee7e9a0651f55ce4a;p=thirdparty%2Fshairport-sync.git partial move to using a nanosecond-based system timer. More to come. --- diff --git a/activity_monitor.c b/activity_monitor.c index bcc25d24..ce7edc5f 100644 --- a/activity_monitor.c +++ b/activity_monitor.c @@ -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 diff --git a/audio_alsa.c b/audio_alsa.c index 39e4d051..40287909 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -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); } diff --git a/audio_jack.c b/audio_jack.c index db6e1899..5caa6c68 100644 --- a/audio_jack.c +++ b/audio_jack.c @@ -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); diff --git a/common.c b/common.c index 3bdf17de..b3942f78 100644 --- 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; diff --git a/common.h b/common.h index 96d59b7d..92095387 100644 --- 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 f3111a83..4c36de34 100644 --- 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; diff --git a/player.c b/player.c index 5876bd33..a034346c 100644 --- 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 6cf53927..dca0ecb5 100644 --- 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); diff --git a/shairport.c b/shairport.c index 5e375916..881ecd97 100644 --- a/shairport.c +++ b/shairport.c @@ -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);