nils/shairport-sync
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Clean up the statistics output to make it provide information for the stream type. Parameterise it so that it's a bit easier to manage.

Browse Source
This commit is contained in:
Mike Brady
2021-06-02 17:17:54 +01:00
parent 5b8d76cfbe
commit 8bee92a4e6
2 changed files with 161 additions and 138 deletions
Download Patch File Download Diff File Expand all files Collapse all files
player.c
+127 -124
View File
@@ -35,6 +35,7 @@
#include <limits.h>
#include <math.h>
#include <pthread.h>
#include <stdarg.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
@@ -1560,6 +1561,54 @@ void player_thread_initial_cleanup_handler(__attribute__((unused)) void *arg) {
conn->connection_number);
}
char line_of_stats[1024];
int statistics_row; // statistics_line 0 means print the headings; anything else 1 means print the
// values. Set to 0 the first time out.
int statistics_column; // used to index through the statistics_print_profile array to check if it
// should be printed
int was_a_previous_column;
int *statistics_print_profile;
// these arrays specify which of the statistics specified by the statistics_item calls will actually
// be printed -- 1 means print, 0 means skip
int ap1_synced_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1};
int ap1_nosync_statistics_print_profile[] = {1, 0, 0, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 0, 1, 1, 0};
int ap1_nodelay_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, 1, 1, 0, 1, 1, 1, 1, 0, 1, 1, 0};
int ap2_realtime_synced_stream_statistics_print_profile[] = {1, 1, 1, 1, 1, 1, 1, 1, 1,
1, 1, 0, 0, 1, 0, 0, 0};
int ap2_realtime_nosync_stream_statistics_print_profile[] = {1, 0, 0, 1, 1, 1, 1, 1, 1,
1, 1, 0, 0, 0, 0, 0, 0};
int ap2_realtime_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 1, 1, 1, 1, 0,
1, 1, 0, 0, 0, 0, 0, 0};
int ap2_buffered_synced_stream_statistics_print_profile[] = {1, 1, 1, 1, 0, 0, 0, 0, 1,
1, 1, 0, 0, 1, 0, 0, 0};
int ap2_buffered_nosync_stream_statistics_print_profile[] = {1, 0, 0, 1, 0, 0, 0, 0, 1,
1, 1, 0, 0, 0, 0, 0, 0};
int ap2_buffered_nodelay_stream_statistics_print_profile[] = {0, 0, 0, 1, 0, 0, 0, 0, 0,
1, 1, 0, 0, 0, 0, 0, 0};
void statistics_item(const char *heading, const char *format, ...) {
if (statistics_print_profile[statistics_column] == 1) { // include this column?
if (was_a_previous_column != 0)
strcat(line_of_stats, ", ");
if (statistics_row == 0) {
strcat(line_of_stats, heading);
} else {
char b[1024];
b[0] = 0;
va_list args;
va_start(args, format);
vsnprintf(b, sizeof(b), format, args);
va_end(args);
strcat(line_of_stats, b);
}
was_a_previous_column = 1;
}
statistics_column++;
}
void player_thread_cleanup_handler(void *arg) {
rtsp_conn_info *conn = (rtsp_conn_info *)arg;
if (pthread_mutex_trylock(&playing_conn_lock) == 0) {
@@ -1907,55 +1956,45 @@ void *player_thread_func(void *arg) {
conn->framesProcessedInThisEpoch = 0;
conn->framesGeneratedInThisEpoch = 0;
conn->correctionsRequestedInThisEpoch = 0;
statistics_row = 0; // statistics_line 0 means print the headings; anything else 1 means print the
// values. Set to 0 the first time out.
if (config.statistics_requested) {
if ((config.output->delay)) {
if (config.no_sync == 0) {
inform("sync error in milliseconds, "
"net correction in ppm, "
"corrections in ppm, "
"total packets, "
"missing packets, "
"late packets, "
"too late packets, "
"resend requests, "
"min DAC queue size, "
"min buffer occupancy, "
"max buffer occupancy, "
"source nominal frames per second, "
"source actual frames per second, "
"output frames per second, "
"source clock drift in ppm, "
"source clock drift sample count, "
"rough calculated correction in ppm");
// decide on what statistics profile to use
#ifdef CONFIG_AIRPLAY_2
if (conn->airplay_type == ap_2) {
if (conn->airplay_stream_type == realtime_stream) {
if (config.output->delay) {
if (config.no_sync == 0)
statistics_print_profile = ap2_realtime_synced_stream_statistics_print_profile;
else
statistics_print_profile = ap2_realtime_nosync_stream_statistics_print_profile;
} else {
statistics_print_profile = ap2_realtime_nodelay_stream_statistics_print_profile;
}
} else {
inform("sync error in milliseconds, "
"total packets, "
"missing packets, "
"late packets, "
"too late packets, "
"resend requests, "
"min DAC queue size, "
"min buffer occupancy, "
"max buffer occupancy, "
"source nominal frames per second, "
"source actual frames per second, "
"source clock drift in ppm, "
"source clock drift sample count");
if (config.output->delay) {
if (config.no_sync == 0)
statistics_print_profile = ap2_buffered_synced_stream_statistics_print_profile;
else
statistics_print_profile = ap2_buffered_nosync_stream_statistics_print_profile;
} else {
statistics_print_profile = ap2_buffered_nodelay_stream_statistics_print_profile;
}
}
} else {
inform("total packets, "
"missing packets, "
"late packets, "
"too late packets, "
"resend requests, "
"min buffer occupancy, "
"max buffer occupancy, "
"source nominal frames per second, "
"source actual frames per second, "
"source clock drift in ppm, "
"source clock drift sample count");
#endif
if (config.output->delay) {
if (config.no_sync == 0)
statistics_print_profile = ap1_synced_statistics_print_profile;
else
statistics_print_profile = ap1_nosync_statistics_print_profile;
} else {
statistics_print_profile = ap1_nodelay_statistics_print_profile;
}
// airplay 1 stuff here
#ifdef CONFIG_AIRPLAY_2
}
#endif
}
#ifdef CONFIG_AIRPLAY_2
@@ -2726,87 +2765,51 @@ void *player_thread_func(void *arg) {
(1.0 * tsum_of_insertions_and_deletions) / number_of_statistics;
// double moving_average_drift = (1.0 * tsum_of_drifts) / number_of_statistics;
// if ((play_number/print_interval)%20==0)
if (config.statistics_requested) {
if (at_least_one_frame_seen) {
// figure out which statistics profile to use, depending on the kind of stream
if ((config.output->delay)) {
if (config.no_sync == 0) {
inform(
"%*.2f," /* Sync error in milliseconds */
"%*.1f," /* net correction in ppm */
"%*.1f," /* corrections in ppm */
"%*d," /* total packets */
"%*" PRIu64 "," /* missing packets */
"%*" PRIu64 "," /* late packets */
"%*" PRIu64 "," /* too late packets */
"%*" PRIu64 "," /* resend requests */
"%*" PRIu64 "," /* min DAC queue size */
"%*" PRId32 "," /* min buffer occupancy */
"%*" PRId32 "," /* max buffer occupancy */
"%*.2f," /* source nominal frame rate */
"%*.2f," /* source actual (average) frame rate */
"%*.2f," /* output frame rate */
"%*.2f," /* source clock drift */
"%*d," /* source clock drift sample count */
"%*.2f", /* rough calculated correction in ppm */
10, 1000 * moving_average_sync_error / config.output_rate, 10,
moving_average_correction * 1000000 / (352 * conn->output_sample_ratio), 10,
moving_average_insertions_plus_deletions * 1000000 /
(352 * conn->output_sample_ratio),
12, play_number, 7, conn->missing_packets, 7, conn->late_packets, 7,
conn->too_late_packets, 7, conn->resend_requests, 7, minimum_dac_queue_size,
5, minimum_buffer_occupancy, 5, maximum_buffer_occupancy, 11,
conn->remote_frame_rate, 11, conn->input_frame_rate, 11, conn->frame_rate, 10,
(conn->local_to_remote_time_gradient - 1.0) * 1000000, 6,
conn->local_to_remote_time_gradient_sample_count, 10,
(conn->frame_rate > 0.0)
? ((conn->frame_rate - conn->remote_frame_rate *
conn->output_sample_ratio *
conn->local_to_remote_time_gradient) *
1000000) /
conn->frame_rate
: 0.0);
} else {
inform("%*.2f," /* Sync error in milliseconds */
"%*d," /* total packets */
"%*" PRIu64 "," /* missing packets */
"%*" PRIu64 "," /* late packets */
"%*" PRIu64 "," /* too late packets */
"%*" PRIu64 "," /* resend requests */
"%*" PRIu64 "," /* min DAC queue size */
"%*" PRId32 "," /* min buffer occupancy */
"%*" PRId32 "," /* max buffer occupancy */
"%*.2f," /* source nominal frame rate */
"%*.2f," /* source actual (average) frame rate */
"%*.2f," /* source clock drift */
"%*d", /* source clock drift sample count */
10, 1000 * moving_average_sync_error / config.output_rate, 12, play_number,
7, conn->missing_packets, 7, conn->late_packets, 7, conn->too_late_packets,
7, conn->resend_requests, 7, minimum_dac_queue_size, 5,
minimum_buffer_occupancy, 5, maximum_buffer_occupancy, 11,
conn->remote_frame_rate, 11, conn->input_frame_rate, 10,
(conn->local_to_remote_time_gradient - 1.0) * 1000000, 6,
conn->local_to_remote_time_gradient_sample_count);
}
} else {
inform("%*d," /* total packets */
"%*" PRIu64 "," /* missing packets */
"%*" PRIu64 "," /* late packets */
"%*" PRIu64 "," /* too late packets */
"%*" PRIu64 "," /* resend requests */
"%*" PRId32 "," /* min buffer occupancy */
"%*" PRId32 "," /* max buffer occupancy */
"%*.2f," /* source nominal frame rate */
"%*.2f," /* source actual (average) frame rate */
"%*.2f," /* source clock drift */
"%*d", /* source clock drift sample count */
12, play_number, 7, conn->missing_packets, 7, conn->late_packets, 7,
conn->too_late_packets, 7, conn->resend_requests, 5,
minimum_buffer_occupancy, 5, maximum_buffer_occupancy, 11,
conn->remote_frame_rate, 11, conn->input_frame_rate, 10,
(conn->local_to_remote_time_gradient - 1.0) * 1000000, 6,
conn->local_to_remote_time_gradient_sample_count);
}
if (config.statistics_requested) {
if (at_least_one_frame_seen) {
do {
line_of_stats[0] = '\0';
statistics_column = 0;
was_a_previous_column = 0;
statistics_item("sync error ms", "%*.2f", 13,
1000 * moving_average_sync_error / config.output_rate);
statistics_item("net sync ppm", "%*.1f", 12,
moving_average_correction * 1000000 /
(352 * conn->output_sample_ratio));
statistics_item("all sync ppm", "%*.1f", 12,
moving_average_insertions_plus_deletions * 1000000 /
(352 * conn->output_sample_ratio));
statistics_item(" packets", "%*d", 11, play_number);
statistics_item("missing", "%*" PRIu64 "", 7, conn->missing_packets);
statistics_item(" late", "%*" PRIu64 "", 6, conn->late_packets);
statistics_item("too late", "%*" PRIu64 "", 8, conn->too_late_packets);
statistics_item("resend reqs", "%*" PRIu64 "", 11, conn->resend_requests);
statistics_item("min DAC queue", "%*" PRIu64 "", 13, minimum_dac_queue_size);
statistics_item("min buffers", "%*" PRIu32 "", 11, minimum_buffer_occupancy);
statistics_item("max buffers", "%*" PRIu32 "", 11, maximum_buffer_occupancy);
statistics_item("source nominal frames per second", "%*.2f", 10,
conn->remote_frame_rate);
statistics_item("source actual frames per second", "%*.2f", 10,
conn->input_frame_rate);
statistics_item("output fps", "%*.2f", 10, conn->frame_rate);
statistics_item("source clock drift ppm", "%*.2f", 9,
(conn->local_to_remote_time_gradient - 1.0) * 1000000);
statistics_item("source clock drift samples", "%*d", 5,
conn->local_to_remote_time_gradient_sample_count);
statistics_item(
"rough calculated correction in ppm", "%*.2f", 9,
(conn->frame_rate > 0.0)
? ((conn->frame_rate - conn->remote_frame_rate * conn->output_sample_ratio *
conn->local_to_remote_time_gradient) *
1000000) /
conn->frame_rate
: 0.0);
statistics_row++;
inform(line_of_stats);
} while (statistics_row < 2);
} else {
inform("No frames received in the last sampling interval.");
}
rtp.c
+34 -14
View File
@@ -290,8 +290,8 @@ void *rtp_control_receiver(void *arg) {
obfp += 2;
};
*obfp = 0;
// get raw timestamp information
// I think that a good way to understand these timestamps is that
// (1) the rtlt below is the timestamp of the frame that should be playing at the
@@ -302,19 +302,19 @@ void *rtp_control_receiver(void *arg) {
// Thus, (3) the latency can be calculated by subtracting the second from the
// first.
// There must be more to it -- there something missing.
// In addition, it seems that if the value of the short represented by the second
// pair of bytes in the packet is 7
// then an extra time lag is expected to be added, presumably by
// the AirPort Express.
// Best guess is that this delay is 11,025 frames.
uint32_t rtlt = nctohl(&packet[4]); // raw timestamp less latency
uint32_t rt = nctohl(&packet[16]); // raw timestamp
uint32_t fl = nctohs(&packet[2]); //
debug(1,"Sync Packet of %d bytes received: \"%s\", flags: %d, timestamps %u and %u,
giving a latency of %d frames.",plen,obf,fl,rt,rtlt,rt-rtlt);
//debug(1,"Monotonic timestamps are: %" PRId64 " and %" PRId64 "
@@ -1327,16 +1327,36 @@ int get_ptp_anchor_local_time_info(rtsp_conn_info *conn, uint32_t *anchorRTP,
// we know its local time, so we use the new clocks's offset to
// calculate what time that must be on the new clock
// but if the master clock has become equal to the actual anchor clock
// then we can reinstate it all
// first, calculate the cumulative offset after swapping all the clocks...
conn->anchor_time = conn->last_anchor_local_time + actual_offset;
// we can check how much of a deviation there was going from clock to clock and bakc around to the master clock
// Now, the thing is that while the anchor clock and master clock for a
// buffered session starts off the same,
// the master clock can change without the anchor clock changing.
// SPS allows the new master clock time to settle down and then
// calculates the appropriate offset to it by
// calculating back from the local anchor information and the new clock's
// advertised offset. Of course, small errors will occur.
// More importantly, the new master clock(s) and the original one will
// drift at different rates. So, after all this, if the original master
// clock becomes the master again, then there could be quite a difference
// in the time information that was calculated through all the clock
// changes and the actual master clock's time information.
// What do we do? We can hardly ignore this new and reliable information
// so we'll take it. Maybe we should add code to slowly correct towards it
// but at present, we just take it.
// So, if the master clock has again become equal to the actual anchor clock
// then we can reinstate it all.
// first, let us calculate the cumulative offset after swapping all the clocks...
conn->anchor_time = conn->last_anchor_local_time + actual_offset;
// we can check how much of a deviation there was going from clock to clock and back
// around to the master clock
if (actual_clock_id == conn->actual_anchor_clock) {
int64_t cumulative_deviation = conn->actual_anchor_time - conn->anchor_time;
debug(1, "Master clock has become equal to the anchor clock. The actual clock is %f ms ahead/behind (+/-) the calculated clock.", 0.000001 * cumulative_deviation);
int64_t cumulative_deviation = conn->anchor_time - conn->actual_anchor_time;
debug(1,
"Master clock has become equal to the anchor clock. The estimated clock time "
"was %f ms ahead(+) or behind (-) the real clock time.",
0.000001 * cumulative_deviation);
conn->anchor_clock = conn->actual_anchor_clock;
conn->anchor_time = conn->actual_anchor_time;
conn->anchor_rtptime = conn->actual_anchor_rtptime;