X-Git-Url: https://git.sesse.net/?a=blobdiff_plain;f=print_latency.cpp;h=9b5be9ea0be3f0457f430e16118ea90f1bd51241;hb=96cb6414f85e0ef4d660b7bd56267303e80fcd05;hp=0b0a1ae483e9bb2ce3ce6df15413942f89870b82;hpb=63a912898083c06cc75f336f8d9a367a707e378a;p=nageru

diff --git a/print_latency.cpp b/print_latency.cpp
index 0b0a1ae..9b5be9e 100644
--- a/print_latency.cpp
+++ b/print_latency.cpp
@@ -1,25 +1,105 @@
 #include "print_latency.h"
+
 #include "flags.h"
+#include "metrics.h"
+#include "mixer.h"
 
 #include <stdio.h>
+#include <algorithm>
 #include <chrono>
 #include <string>
 
 using namespace std;
 using namespace std::chrono;
 
-void print_latency(const string &header, const ReceivedTimestamps &received_ts, bool is_b_frame, int *frameno)
+ReceivedTimestamps find_received_timestamp(const vector<RefCountedFrame> &input_frames)
+{
+	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 ts;
+}
+
+void LatencyHistogram::init(const string &measuring_point)
 {
-	if (received_ts.max_ts == steady_clock::time_point::min())
+	unsigned num_cards = global_flags.num_cards;  // The mixer might not be ready yet.
+	histograms.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);
+		histograms[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);
+
+			histograms[card_index][frame_index].reset(new Histogram[2]);
+			histograms[card_index][frame_index][0].init_geometric(0.001, 10.0, 30);
+			histograms[card_index][frame_index][1].init_geometric(0.001, 10.0, 30);
+			global_metrics.add("latency_seconds",
+				{{ "measuring_point", measuring_point },
+				 { "card", card_index_str },
+				 { "frame_age", frame_index_str },
+				 { "frame_type", "i/p" }},
+				 &histograms[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" }},
+				 &histograms[card_index][frame_index][1],
+				Metrics::PRINT_WHEN_NONEMPTY);
+		}
+	}
+}
+
+void print_latency(const string &header, const ReceivedTimestamps &received_ts, bool is_b_frame, int *frameno, LatencyHistogram *histogram)
+{
+	if (received_ts.ts.empty())
 		return;
 
+	const steady_clock::time_point now = steady_clock::now();
+
+	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<double> latency = now - ts;
+			histogram->histograms[card_index][frame_index][is_b_frame].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) {
-		const steady_clock::time_point now = steady_clock::now();
+		// 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<double> lowest_latency = now - max_ts;
+		duration<double> highest_latency = now - min_ts;
+
 		printf("%-60s %4.0f ms (lowest-latency input), %4.0f ms (highest-latency input)",
-			header.c_str(),
-			1e3 * std::chrono::duration<double>(now - received_ts.max_ts).count(),
-			1e3 * std::chrono::duration<double>(now - received_ts.min_ts).count());
+			header.c_str(), 1e3 * lowest_latency.count(), 1e3 * highest_latency.count());
 
 		if (is_b_frame) {
 			printf("  [on B-frame; potential extra latency]\n");