1 #include "print_latency.h"
13 using namespace std::chrono;
15 ReceivedTimestamps find_received_timestamp(const vector<RefCountedFrame> &input_frames)
17 unsigned num_cards = global_mixer->get_num_cards();
18 assert(input_frames.size() == num_cards * FRAME_HISTORY_LENGTH);
20 ReceivedTimestamps ts;
21 for (unsigned card_index = 0; card_index < num_cards; ++card_index) {
22 for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) {
23 const RefCountedFrame &input_frame = input_frames[card_index * FRAME_HISTORY_LENGTH + frame_index];
24 if (input_frame == nullptr ||
25 (frame_index > 0 && input_frame.get() == input_frames[card_index * FRAME_HISTORY_LENGTH + frame_index - 1].get())) {
26 ts.ts.push_back(steady_clock::time_point::min());
28 ts.ts.push_back(input_frame->received_timestamp);
35 void LatencyHistogram::init(const string &measuring_point)
37 unsigned num_cards = global_flags.num_cards; // The mixer might not be ready yet.
38 histograms.resize(num_cards * FRAME_HISTORY_LENGTH * 2);
39 for (unsigned card_index = 0; card_index < num_cards; ++card_index) {
40 char card_index_str[64];
41 snprintf(card_index_str, sizeof(card_index_str), "%u", card_index);
42 histograms[card_index].resize(FRAME_HISTORY_LENGTH);
43 for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) {
44 char frame_index_str[64];
45 snprintf(frame_index_str, sizeof(frame_index_str), "%u", frame_index);
47 histograms[card_index][frame_index].reset(new Histogram[2]);
48 histograms[card_index][frame_index][0].init_geometric(0.001, 10.0, 30);
49 histograms[card_index][frame_index][1].init_geometric(0.001, 10.0, 30);
50 global_metrics.add("latency_seconds",
51 {{ "measuring_point", measuring_point },
52 { "card", card_index_str },
53 { "frame_age", frame_index_str },
54 { "frame_type", "i/p" }},
55 &histograms[card_index][frame_index][0],
56 (frame_index == 0) ? Metrics::PRINT_ALWAYS : Metrics::PRINT_WHEN_NONEMPTY);
57 global_metrics.add("latency_seconds",
58 {{ "measuring_point", measuring_point },
59 { "card", card_index_str },
60 { "frame_age", frame_index_str },
61 { "frame_type", "b" }},
62 &histograms[card_index][frame_index][1],
63 Metrics::PRINT_WHEN_NONEMPTY);
68 void print_latency(const string &header, const ReceivedTimestamps &received_ts, bool is_b_frame, int *frameno, LatencyHistogram *histogram)
70 if (received_ts.ts.empty())
73 const steady_clock::time_point now = steady_clock::now();
75 unsigned num_cards = global_mixer->get_num_cards();
76 assert(received_ts.ts.size() == num_cards * FRAME_HISTORY_LENGTH);
77 for (unsigned card_index = 0; card_index < num_cards; ++card_index) {
78 for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) {
79 steady_clock::time_point ts = received_ts.ts[card_index * FRAME_HISTORY_LENGTH + frame_index];
80 if (ts == steady_clock::time_point::min()) {
83 duration<double> latency = now - ts;
84 histogram->histograms[card_index][frame_index][is_b_frame].count_event(latency.count());
88 // 101 is chosen so that it's prime, which is unlikely to get the same frame type every time.
89 if (global_flags.print_video_latency && (++*frameno % 101) == 0) {
90 // Find min and max timestamp of all input frames that have a timestamp.
91 steady_clock::time_point min_ts = steady_clock::time_point::max(), max_ts = steady_clock::time_point::min();
92 for (const auto &ts : received_ts.ts) {
93 if (ts > steady_clock::time_point::min()) {
94 min_ts = min(min_ts, ts);
95 max_ts = max(max_ts, ts);
98 duration<double> lowest_latency = now - max_ts;
99 duration<double> highest_latency = now - min_ts;
101 printf("%-60s %4.0f ms (lowest-latency input), %4.0f ms (highest-latency input)",
102 header.c_str(), 1e3 * lowest_latency.count(), 1e3 * highest_latency.count());
105 printf(" [on B-frame; potential extra latency]\n");