diff --git a/audio_alsa.c b/audio_alsa.c index f723cb7d..32f6c90f 100644 --- a/audio_alsa.c +++ b/audio_alsa.c @@ -60,7 +60,8 @@ static int play(void *buf, int samples); static void stop(void); static void flush(void); int delay(long *the_delay); -int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played); +int get_frames_sent_for_output(__attribute__ ((unused)) uint64_t *elapsed_time, uint64_t *frames_sent_to_dac); +// int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played); void *alsa_buffer_monitor_thread_code(void *arg); static void volume(double vol); @@ -88,7 +89,8 @@ audio_output audio_alsa = { .flush = &flush, .delay = &delay, .play = &play, - .rate_info = &get_rate_information, + .rate_info = &get_frames_sent_for_output, // will also include frames of silence sent to stop standby mode +// .rate_info = NULL, .mute = NULL, // a function will be provided if it can, and is allowed to, // do hardware mute .volume = NULL, // a function will be provided if it can do hardware volume @@ -239,22 +241,13 @@ int precision_delay_available() { return (precision_delay_available_status == YNDK_YES); } -// static int play_number; -// static int64_t accumulated_delay, accumulated_da_delay; int alsa_characteristics_already_listed = 0; static snd_pcm_uframes_t period_size_requested, buffer_size_requested; static int set_period_size_request, set_buffer_size_request; -static uint64_t measurement_start_time; -static uint64_t frames_played_at_measurement_start_time; - -static uint64_t measurement_time; -static uint64_t frames_played_at_measurement_time; - static uint64_t frames_sent_for_playing; -static uint64_t frame_index; -static int measurement_data_is_valid; +static int output_error_occurred; // set to true if an underrun or similar has occurred since last requested static void help(void) { printf(" -d output-device set the output device, default is \"default\".\n" @@ -1407,8 +1400,8 @@ static void start(__attribute__((unused)) int i_sample_rate, __attribute__((unused)) int i_sample_format) { debug(3, "audio_alsa start called."); - frame_index = 0; - measurement_data_is_valid = 0; + // frame_index = 0; + // measurement_data_is_valid = 0; stall_monitor_start_time = 0; stall_monitor_frame_count = 0; @@ -1430,8 +1423,8 @@ int standard_delay_and_status(snd_pcm_state_t *state, snd_pcm_sframes_t *delay, } else { // not running, thus no delay information, thus can't check for frame // rates - frame_index = 0; // we'll be starting over... - measurement_data_is_valid = 0; + // frame_index = 0; // we'll be starting over... + // measurement_data_is_valid = 0; *delay = 0; } @@ -1587,8 +1580,8 @@ int precision_delay_and_status(snd_pcm_state_t *state, snd_pcm_sframes_t *delay, // not running, thus no delay information, thus can't check for frame // rates - frame_index = 0; // we'll be starting over... - measurement_data_is_valid = 0; + // frame_index = 0; // we'll be starting over... + // measurement_data_is_valid = 0; } } else { debug(1, "alsa: can't get device's status."); @@ -1631,6 +1624,21 @@ int delay(long *the_delay) { return ret; } +int get_frames_sent_for_output(__attribute__ ((unused)) uint64_t *elapsed_time, uint64_t *frames_sent_to_dac) { + int ret = 0; + pthread_cleanup_debug_mutex_lock(&alsa_mutex, 10000, 0); + *frames_sent_to_dac = frames_sent_for_playing; + if (alsa_handle == NULL) + ret = ENODEV; + else + ret = output_error_occurred; // will be zero unless an error occurred + output_error_occurred = 0; // reset it. + debug_mutex_unlock(&alsa_mutex, 0); + pthread_cleanup_pop(0); + return ret; +} + +/* int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { // elapsed_time is in nanoseconds int response = 0; // zero means okay @@ -1644,6 +1652,7 @@ int get_rate_information(uint64_t *elapsed_time, uint64_t *frames_played) { } return response; } +*/ int do_play(void *buf, int samples) { // assuming the alsa_mutex has been acquired @@ -1671,34 +1680,9 @@ int do_play(void *buf, int samples) { ret = alsa_pcm_write(alsa_handle, buf, samples); if (ret == samples) { stall_monitor_frame_count += samples; - - if (frame_index == 0) { - frames_sent_for_playing = samples; - } else { - frames_sent_for_playing += samples; - } - - const uint64_t start_measurement_from_this_frame = - (2 * config.output_rate) / 352; // two seconds of frames - - frame_index++; - - 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_ns(); - frames_played_at_measurement_time = frames_sent_for_playing - my_delay - samples; - - if (frame_index == start_measurement_from_this_frame) { - // debug(1, "Start frame counting"); - frames_played_at_measurement_start_time = frames_played_at_measurement_time; - measurement_start_time = measurement_time; - measurement_data_is_valid = 1; - } - } + frames_sent_for_playing += samples; } else { - frame_index = 0; - measurement_data_is_valid = 0; + output_error_occurred = -ret; // note than an output error has occurred if (ret == -EPIPE) { /* underrun */ // It could be that the DAC was in the SND_PCM_STATE_XRUN state before @@ -1748,8 +1732,6 @@ int do_play(void *buf, int samples) { "alsa: device status returns fault status %d and SND_PCM_STATE_* " "%d for play.", ret, state); - frame_index = 0; - measurement_data_is_valid = 0; } pthread_setcancelstate(oldState, NULL); @@ -1774,7 +1756,8 @@ int do_open(int do_auto_setup) { // set accordingly // do_mute(0); // complete unmute } - + output_error_occurred = 0; + frames_sent_for_playing = 0; alsa_backend_state = abm_connected; // only do this if it really opened it. } } else { @@ -2005,8 +1988,8 @@ void *alsa_buffer_monitor_thread_code(__attribute__((unused)) void *arg) { "alsa_backend_state => abm_connected"); } else if ((alsa_backend_state == abm_connected) && (config.keep_dac_busy == 0)) { stall_monitor_start_time = 0; - frame_index = 0; - measurement_data_is_valid = 0; + // frame_index = 0; + // measurement_data_is_valid = 0; debug(2, "alsa: alsa_buffer_monitor_thread_code() -- closing the output " "device"); do_close(); diff --git a/common.c b/common.c index 866222c2..b1525a31 100644 --- a/common.c +++ b/common.c @@ -55,9 +55,9 @@ #endif #ifdef COMPILE_FOR_FREEBSD -#include -#include #include +#include +#include #endif #ifdef COMPILE_FOR_OSX @@ -1258,6 +1258,49 @@ uint64_t get_absolute_time_in_fp() { return time_now_fp; } +uint64_t get_monotonic_time_in_ns() { + uint64_t time_now_ns; + +#ifdef COMPILE_FOR_LINUX_AND_FREEBSD_AND_CYGWIN_AND_OPENBSD + struct timespec tn; + // can't use CLOCK_MONOTONIC_RAW as it's not implemented in OpenWrt + // CLOCK_REALTIME because PTP uses it. + clock_gettime(CLOCK_MONOTONIC, &tn); + uint64_t tnnsec = tn.tv_sec; + tnnsec = tnnsec * 1000000000; + uint64_t tnjnsec = tn.tv_nsec; + time_now_ns = tnnsec + tnjnsec; +#endif + +#ifdef COMPILE_FOR_OSX + uint64_t time_now_mach; + uint64_t elapsedNano; + static mach_timebase_info_data_t sTimebaseInfo = {0, 0}; + + // this actually give you a monotonic clock + // see https://news.ycombinator.com/item?id=6303755 + time_now_mach = mach_absolute_time(); + + // If this is the first time we've run, get the timebase. + // We can use denom == 0 to indicate that sTimebaseInfo is + // uninitialised because it makes no sense to have a zero + // denominator in a fraction. + + if (sTimebaseInfo.denom == 0) { + debug(1, "Mac initialise timebase info."); + (void)mach_timebase_info(&sTimebaseInfo); + } + + // Do the maths. We hope that the multiplication doesn't + // overflow; the price you pay for working in fixed point. + + // this gives us nanoseconds + time_now_ns = time_now_mach * sTimebaseInfo.numer / sTimebaseInfo.denom; +#endif + + return time_now_ns; +} + uint64_t get_absolute_time_in_ns() { uint64_t time_now_ns; @@ -1277,6 +1320,7 @@ uint64_t get_absolute_time_in_ns() { uint64_t elapsedNano; static mach_timebase_info_data_t sTimebaseInfo = {0, 0}; + // this actually give you a monotonic clock time_now_mach = mach_absolute_time(); // If this is the first time we've run, get the timebase. @@ -1963,7 +2007,7 @@ int get_device_id(uint8_t *id, int int_length) { t = id; int found = 0; for (ifa = ifaddr; ifa != NULL; ifa = ifa->ifa_next) { - #ifdef AF_PACKET +#ifdef AF_PACKET if ((ifa->ifa_addr) && (ifa->ifa_addr->sa_family == AF_PACKET)) { struct sockaddr_ll *s = (struct sockaddr_ll *)ifa->ifa_addr; if ((strcmp(ifa->ifa_name, "lo") != 0) && (found == 0)) { @@ -1973,25 +2017,23 @@ int get_device_id(uint8_t *id, int int_length) { found = 1; } } - #else - #ifdef AF_LINK - struct sockaddr_dl * sdl = (struct sockaddr_dl *) ifa->ifa_addr; - if ((sdl) && (sdl->sdl_family == AF_LINK)) { +#else +#ifdef AF_LINK + struct sockaddr_dl *sdl = (struct sockaddr_dl *)ifa->ifa_addr; + if ((sdl) && (sdl->sdl_family == AF_LINK)) { if (sdl->sdl_type == IFT_ETHER) { char *s = LLADDR(sdl); for (i = 0; i < sdl->sdl_alen; i++) { - debug(1,"char %d: \"%c\".", i, *s); - *t++ = (uint8_t)*s++; - } + debug(1, "char %d: \"%c\".", i, *s); + *t++ = (uint8_t)*s++; + } found = 1; } } - #endif - #endif - +#endif +#endif } freeifaddrs(ifaddr); } return response; } - diff --git a/common.h b/common.h index 9c3496f6..199b3d41 100644 --- a/common.h +++ b/common.h @@ -381,6 +381,7 @@ double vol2attn(double vol, long max_db, long min_db); // return a time in nanoseconds // uint64_t get_absolute_time_in_fp(void); // obselete uint64_t get_absolute_time_in_ns(void); +uint64_t get_monotonic_time_in_ns(void); // to try and get precise FPS values // time at startup for debugging timing extern uint64_t ns_time_at_startup, ns_time_at_last_debug_message; diff --git a/player.c b/player.c index 0084ab5e..67a0c086 100644 --- a/player.c +++ b/player.c @@ -1611,7 +1611,7 @@ void player_thread_cleanup_handler(void *arg) { int elapsedHours = rawSeconds / 3600; int elapsedMin = (rawSeconds / 60) % 60; int elapsedSec = rawSeconds % 60; - if (conn->frame_rate_status) + if (conn->frame_rate_valid) inform("Connection %d: Playback Stopped. Total playing time %02d:%02d:%02d. Input: %0.2f, " "output: %0.2f " "frames per second.", @@ -1714,6 +1714,11 @@ void player_thread_cleanup_handler(void *arg) { void *player_thread_func(void *arg) { rtsp_conn_info *conn = (rtsp_conn_info *)arg; + + uint64_t previous_frames_played; + uint64_t previous_frames_played_time; + int previous_frames_played_valid = 0; + // pthread_cleanup_push(player_thread_initial_cleanup_handler, arg); conn->packet_count = 0; conn->packet_count_since_flush = 0; @@ -1873,7 +1878,7 @@ void *player_thread_func(void *arg) { conn->playstart = time(NULL); conn->frame_rate = 0.0; - conn->frame_rate_status = 0; + conn->frame_rate_valid = 0; conn->input_frame_rate = 0.0; conn->input_frame_rate_starting_point_is_valid = 0; @@ -2066,7 +2071,7 @@ void *player_thread_func(void *arg) { pthread_testcancel(); // allow a pthread_cancel request to take effect. abuf_t *inframe = buffer_get_frame(conn); // this has cancellation point(s), but it's not // guaranteed that they'll always be executed - + uint64_t local_time_now = get_absolute_time_in_ns(); // types okay if (inframe) { inbuf = inframe->data; inbuflength = inframe->length; @@ -2252,8 +2257,6 @@ void *player_thread_func(void *arg) { at_least_one_frame_seen = 1; - uint64_t local_time_now = get_absolute_time_in_ns(); // types okay - // This is the timing error for the next audio frame in the DAC, if applicable int64_t sync_error = 0; @@ -2787,19 +2790,31 @@ void *player_thread_func(void *arg) { conn->input_frame_rate = 0.0; } + uint64_t frames_sent_for_play; + int status = -1; if ((config.output->delay) && (config.no_sync == 0) && (config.output->rate_info)) { - uint64_t elapsed_play_time, frames_played; - if (config.output->rate_info(&elapsed_play_time, &frames_played) == 0) - conn->frame_rate_status = 1; - else - conn->frame_rate_status = 0; - if (conn->frame_rate_status) { - conn->frame_rate = - (1.0E9 * frames_played) / - elapsed_play_time; // an IEEE double calculation with two 64-bit integers - } else { - conn->frame_rate = 0.0; + uint64_t monotonic_time_now = get_monotonic_time_in_ns(); + uint64_t elapsed_play_time; // dummy + status = config.output->rate_info(&elapsed_play_time, &frames_sent_for_play); + uint64_t frames_played = frames_sent_for_play - play_samples - current_delay; + // If the status is zero, it means that there were no output problems since the + // last time the rate_info call was made. Thus, the frame rate should be valid. + if ((status == 0) && (previous_frames_played_valid)) { + uint64_t frames_played_in_this_interval = frames_played - previous_frames_played; + uint64_t interval = monotonic_time_now - previous_frames_played_time; + conn->frame_rate = (1e9 * frames_played_in_this_interval) / interval; + conn->frame_rate_valid = 1; } + + // uncomment the if statement if your want to get as long a period for + // calculating the frame rate + // if ((status != 0) || (previous_frames_played_valid == 0)) { + // if we have just detected an outputting error, or if we have no + // starting information + previous_frames_played = frames_played; + previous_frames_played_time = monotonic_time_now; + previous_frames_played_valid = 1; + //} } // we can now calculate running averages for sync error (frames), corrections (ppm), @@ -2837,7 +2852,10 @@ void *player_thread_func(void *arg) { statistics_item("max buffers", "%*" PRIu32 "", 11, maximum_buffer_occupancy); statistics_item("nominal fps", "%*.2f", 11, conn->remote_frame_rate); statistics_item(" actual fps", "%*.2f", 11, conn->input_frame_rate); - statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); + if (conn->frame_rate_valid) + statistics_item(" output fps", "%*.2f", 11, conn->frame_rate); + else + statistics_item(" output fps", " N/A"); statistics_item("source drift ppm", "%*.2f", 16, (conn->local_to_remote_time_gradient - 1.0) * 1000000); statistics_item("drift samples", "%*d", 13, @@ -2845,7 +2863,7 @@ void *player_thread_func(void *arg) { statistics_item( "estimated (unused) correction ppm", "%*.2f", strlen("estimated (unused) correction ppm"), - (conn->frame_rate > 0.0) + (conn->frame_rate_valid != 0) ? ((conn->frame_rate - conn->remote_frame_rate * conn->output_sample_ratio * conn->local_to_remote_time_gradient) * 1000000) / @@ -2920,7 +2938,7 @@ void player_volume_without_notification(double airplay_volume, rtsp_conn_info *c else sw_min_db = (sw_max_db - desired_sw_range); } else { - hw_min_db = hw_max_db - desired_range_db; + hw_min_db = hw_max_db - desired_range_db; } } } else { diff --git a/player.h b/player.h index effd8b12..41cdc5bd 100644 --- a/player.h +++ b/player.h @@ -109,7 +109,6 @@ typedef enum { remote_control_stream } airplay_stream_c; // "c" for category - #ifdef CONFIG_AIRPLAY_2 typedef enum { ts_ntp, ts_ptp } timing_t; typedef enum { ap_1, ap_2 } airplay_t; @@ -181,7 +180,7 @@ typedef struct { // for holding the output rate information until printed out at the end of a session double frame_rate; - int frame_rate_status; + int frame_rate_valid; // for holding input rate information until printed out at the end of a session @@ -296,7 +295,8 @@ typedef struct { clock_status_t clock_status; airplay_stream_c - airplay_stream_category; // is it a remote control stream or a normal "full service" stream? (will be unspecified if not build for AirPlay 2) + airplay_stream_category; // is it a remote control stream or a normal "full service" stream? + // (will be unspecified if not build for AirPlay 2) #ifdef CONFIG_AIRPLAY_2 char *airplay_gid; // UUID in the Bonjour advertisement -- if NULL, the group UUID is the same as diff --git a/rtsp.c b/rtsp.c index 9e18a3b2..f1efb1cd 100644 --- a/rtsp.c +++ b/rtsp.c @@ -3784,7 +3784,7 @@ int send_metadata_to_queue(pc_queue *queue, uint32_t type, uint32_t code, char * int send_metadata(uint32_t type, uint32_t code, char *data, uint32_t length, rtsp_message *carrier, int block) { - int rc; + int rc = 0; if (config.metadata_enabled) { rc = send_metadata_to_queue(&metadata_queue, type, code, data, length, carrier, block); rc =