X-Git-Url: https://git.sesse.net/?a=blobdiff_plain;f=print_latency.cpp;h=72440ae0fe41a3ec13df76c595450ca409090aec;hb=e284d1c7a2e18ee7e4aea082c4a57a3504a0f5e8;hp=a80ac4f3242a2e7e1b44b5bb3215b8986fe1f728;hpb=1df7849fad1d0647a02951abaa60f9e4f40ce360;p=nageru diff --git a/print_latency.cpp b/print_latency.cpp index a80ac4f..72440ae 100644 --- a/print_latency.cpp +++ b/print_latency.cpp @@ -2,8 +2,10 @@ #include "flags.h" #include "metrics.h" +#include "mixer.h" #include +#include #include #include @@ -12,59 +14,113 @@ using namespace std::chrono; ReceivedTimestamps find_received_timestamp(const vector &input_frames) { - // Find min and max timestamp of all input frames that have a timestamp. - steady_clock::time_point min_ts = steady_clock::time_point::max(), max_ts = steady_clock::time_point::min(); - for (const RefCountedFrame &input_frame : input_frames) { - if (input_frame && input_frame->received_timestamp > steady_clock::time_point::min()) { - min_ts = min(min_ts, input_frame->received_timestamp); - max_ts = max(max_ts, input_frame->received_timestamp); + unsigned num_cards = global_mixer->get_num_cards(); + assert(input_frames.size() == num_cards * FRAME_HISTORY_LENGTH); + + ReceivedTimestamps ts; + for (unsigned card_index = 0; card_index < num_cards; ++card_index) { + for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) { + const RefCountedFrame &input_frame = input_frames[card_index * FRAME_HISTORY_LENGTH + frame_index]; + if (input_frame == nullptr || + (frame_index > 0 && input_frame.get() == input_frames[card_index * FRAME_HISTORY_LENGTH + frame_index - 1].get())) { + ts.ts.push_back(steady_clock::time_point::min()); + } else { + ts.ts.push_back(input_frame->received_timestamp); + } } } - return { min_ts, max_ts }; + return ts; } void LatencyHistogram::init(const string &measuring_point) { - histogram_lowest_latency_input.init_geometric(0.001, 10.0, 30); - histogram_highest_latency_input.init_geometric(0.001, 10.0, 30); - histogram_lowest_latency_input_bframe.init_geometric(0.001, 10.0, 30); - histogram_highest_latency_input_bframe.init_geometric(0.001, 10.0, 30); + unsigned num_cards = global_flags.num_cards; // The mixer might not be ready yet. + summaries.resize(num_cards * FRAME_HISTORY_LENGTH * 2); + for (unsigned card_index = 0; card_index < num_cards; ++card_index) { + char card_index_str[64]; + snprintf(card_index_str, sizeof(card_index_str), "%u", card_index); + summaries[card_index].resize(FRAME_HISTORY_LENGTH); + for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) { + char frame_index_str[64]; + snprintf(frame_index_str, sizeof(frame_index_str), "%u", frame_index); - global_metrics.add("latency_seconds", - {{ "measuring_point", measuring_point }, { "input", "lowest_latency" }, { "frame_type", "i/p" }}, - &histogram_lowest_latency_input); - global_metrics.add("latency_seconds", - {{ "measuring_point", measuring_point }, { "input", "highest_latency" }, { "frame_type", "i/p" }}, - &histogram_highest_latency_input); - global_metrics.add("latency_seconds", - {{ "measuring_point", measuring_point }, { "input", "lowest_latency" }, { "frame_type", "b" }}, - &histogram_lowest_latency_input_bframe); - global_metrics.add("latency_seconds", - {{ "measuring_point", measuring_point }, { "input", "highest_latency" }, { "frame_type", "b" }}, - &histogram_highest_latency_input_bframe); + vector quantiles{0.01, 0.1, 0.25, 0.5, 0.75, 0.9, 0.99}; + summaries[card_index][frame_index].reset(new Summary[3]); + summaries[card_index][frame_index][0].init(quantiles, 60.0); + summaries[card_index][frame_index][1].init(quantiles, 60.0); + summaries[card_index][frame_index][2].init(quantiles, 60.0); + global_metrics.add("latency_seconds", + {{ "measuring_point", measuring_point }, + { "card", card_index_str }, + { "frame_age", frame_index_str }, + { "frame_type", "i/p" }}, + &summaries[card_index][frame_index][0], + (frame_index == 0) ? Metrics::PRINT_ALWAYS : Metrics::PRINT_WHEN_NONEMPTY); + global_metrics.add("latency_seconds", + {{ "measuring_point", measuring_point }, + { "card", card_index_str }, + { "frame_age", frame_index_str }, + { "frame_type", "b" }}, + &summaries[card_index][frame_index][1], + Metrics::PRINT_WHEN_NONEMPTY); + global_metrics.add("latency_seconds", + {{ "measuring_point", measuring_point }, + { "card", card_index_str }, + { "frame_age", frame_index_str }, + { "frame_type", "total" }}, + &summaries[card_index][frame_index][2], + (frame_index == 0) ? Metrics::PRINT_ALWAYS : Metrics::PRINT_WHEN_NONEMPTY); + } + } } -void print_latency(const string &header, const ReceivedTimestamps &received_ts, bool is_b_frame, int *frameno, LatencyHistogram *histogram) +void print_latency(const char *header, const ReceivedTimestamps &received_ts, bool is_b_frame, int *frameno, LatencyHistogram *histogram) { - if (received_ts.max_ts == steady_clock::time_point::min()) + if (received_ts.ts.empty()) return; const steady_clock::time_point now = steady_clock::now(); - duration lowest_latency = now - received_ts.max_ts; - duration highest_latency = now - received_ts.min_ts; - if (is_b_frame) { - histogram->histogram_lowest_latency_input_bframe.count_event(lowest_latency.count()); - histogram->histogram_highest_latency_input_bframe.count_event(highest_latency.count()); + if (global_mixer == nullptr) { + // Kaeru. + assert(received_ts.ts.size() == 1); + steady_clock::time_point ts = received_ts.ts[0]; + if (ts != steady_clock::time_point::min()) { + duration latency = now - ts; + histogram->summaries[0][0][is_b_frame].count_event(latency.count()); + histogram->summaries[0][0][2].count_event(latency.count()); + } } else { - histogram->histogram_lowest_latency_input.count_event(lowest_latency.count()); - histogram->histogram_highest_latency_input.count_event(highest_latency.count()); + unsigned num_cards = global_mixer->get_num_cards(); + assert(received_ts.ts.size() == num_cards * FRAME_HISTORY_LENGTH); + for (unsigned card_index = 0; card_index < num_cards; ++card_index) { + for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) { + steady_clock::time_point ts = received_ts.ts[card_index * FRAME_HISTORY_LENGTH + frame_index]; + if (ts == steady_clock::time_point::min()) { + continue; + } + duration latency = now - ts; + histogram->summaries[card_index][frame_index][is_b_frame].count_event(latency.count()); + histogram->summaries[card_index][frame_index][2].count_event(latency.count()); + } + } } // 101 is chosen so that it's prime, which is unlikely to get the same frame type every time. if (global_flags.print_video_latency && (++*frameno % 101) == 0) { + // Find min and max timestamp of all input frames that have a timestamp. + steady_clock::time_point min_ts = steady_clock::time_point::max(), max_ts = steady_clock::time_point::min(); + for (const auto &ts : received_ts.ts) { + if (ts > steady_clock::time_point::min()) { + min_ts = min(min_ts, ts); + max_ts = max(max_ts, ts); + } + } + duration lowest_latency = now - max_ts; + duration highest_latency = now - min_ts; + printf("%-60s %4.0f ms (lowest-latency input), %4.0f ms (highest-latency input)", - header.c_str(), 1e3 * lowest_latency.count(), 1e3 * highest_latency.count()); + header, 1e3 * lowest_latency.count(), 1e3 * highest_latency.count()); if (is_b_frame) { printf(" [on B-frame; potential extra latency]\n");