1 #include "print_latency.h"
5 #include "ref_counted_frame.h"
6 #include "shared/metrics.h"
8 #include "shared/shared_defs.h"
18 using namespace std::chrono;
20 ReceivedTimestamps find_received_timestamp(const vector<RefCountedFrame> &input_frames)
22 assert(input_frames.size() == MAX_VIDEO_CARDS * FRAME_HISTORY_LENGTH);
24 ReceivedTimestamps ts;
25 for (unsigned card_index = 0; card_index < MAX_VIDEO_CARDS; ++card_index) {
26 for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) {
27 const RefCountedFrame &input_frame = input_frames[card_index * FRAME_HISTORY_LENGTH + frame_index];
28 if (input_frame == nullptr ||
29 (frame_index > 0 && input_frame.get() == input_frames[card_index * FRAME_HISTORY_LENGTH + frame_index - 1].get())) {
30 ts.ts.push_back(steady_clock::time_point::min());
32 ts.ts.push_back(input_frame->received_timestamp);
39 void LatencyHistogram::init(const string &measuring_point)
41 summaries.resize(MAX_VIDEO_CARDS * FRAME_HISTORY_LENGTH * 2);
42 for (unsigned card_index = 0; card_index < MAX_VIDEO_CARDS; ++card_index) {
43 char card_index_str[64];
44 snprintf(card_index_str, sizeof(card_index_str), "%u", card_index);
45 summaries[card_index].resize(FRAME_HISTORY_LENGTH);
46 for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) {
47 char frame_index_str[64];
48 snprintf(frame_index_str, sizeof(frame_index_str), "%u", frame_index);
50 vector<double> quantiles{0.01, 0.1, 0.25, 0.5, 0.75, 0.9, 0.99};
51 summaries[card_index][frame_index].reset(new Summary[3]);
52 summaries[card_index][frame_index][0].init(quantiles, 60.0);
53 summaries[card_index][frame_index][1].init(quantiles, 60.0);
54 summaries[card_index][frame_index][2].init(quantiles, 60.0);
55 global_metrics.add("latency_seconds",
56 {{ "measuring_point", measuring_point },
57 { "card", card_index_str },
58 { "frame_age", frame_index_str },
59 { "frame_type", "i/p" }},
60 &summaries[card_index][frame_index][0],
61 Metrics::PRINT_WHEN_NONEMPTY);
62 global_metrics.add("latency_seconds",
63 {{ "measuring_point", measuring_point },
64 { "card", card_index_str },
65 { "frame_age", frame_index_str },
66 { "frame_type", "b" }},
67 &summaries[card_index][frame_index][1],
68 Metrics::PRINT_WHEN_NONEMPTY);
69 global_metrics.add("latency_seconds",
70 {{ "measuring_point", measuring_point },
71 { "card", card_index_str },
72 { "frame_age", frame_index_str },
73 { "frame_type", "total" }},
74 &summaries[card_index][frame_index][2],
75 Metrics::PRINT_WHEN_NONEMPTY);
80 void print_latency(const char *header, const ReceivedTimestamps &received_ts, bool is_b_frame, int *frameno, LatencyHistogram *histogram)
82 if (received_ts.ts.empty())
85 const steady_clock::time_point now = steady_clock::now();
87 if (global_mixer == nullptr) {
89 assert(received_ts.ts.size() == 1);
90 steady_clock::time_point ts = received_ts.ts[0];
91 if (ts != steady_clock::time_point::min()) {
92 duration<double> latency = now - ts;
93 histogram->summaries[0][0][is_b_frame].count_event(latency.count());
94 histogram->summaries[0][0][2].count_event(latency.count());
97 assert(received_ts.ts.size() == MAX_VIDEO_CARDS * FRAME_HISTORY_LENGTH);
98 for (unsigned card_index = 0; card_index < MAX_VIDEO_CARDS; ++card_index) {
99 for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) {
100 steady_clock::time_point ts = received_ts.ts[card_index * FRAME_HISTORY_LENGTH + frame_index];
101 if (ts == steady_clock::time_point::min()) {
104 duration<double> latency = now - ts;
105 histogram->summaries[card_index][frame_index][is_b_frame].count_event(latency.count());
106 histogram->summaries[card_index][frame_index][2].count_event(latency.count());
111 // 101 is chosen so that it's prime, which is unlikely to get the same frame type every time.
112 if (global_flags.print_video_latency && (++*frameno % 101) == 0) {
113 // Find min and max timestamp of all input frames that have a timestamp.
114 steady_clock::time_point min_ts = steady_clock::time_point::max(), max_ts = steady_clock::time_point::min();
115 for (const auto &ts : received_ts.ts) {
116 if (ts > steady_clock::time_point::min()) {
117 min_ts = min(min_ts, ts);
118 max_ts = max(max_ts, ts);
121 duration<double> lowest_latency = now - max_ts;
122 duration<double> highest_latency = now - min_ts;
124 printf("%-60s %4.0f ms (lowest-latency input), %4.0f ms (highest-latency input)",
125 header, 1e3 * lowest_latency.count(), 1e3 * highest_latency.count());
128 printf(" [on B-frame; potential extra latency]\n");