git.sesse.net Git - nageru/blob - print_latency.cpp

   1 #include "print_latency.h"
   2
   3 #include "flags.h"
   4 #include "metrics.h"
   5 #include "mixer.h"
   6
   7 #include <stdio.h>
   8 #include <algorithm>
   9 #include <chrono>
  10 #include <string>
  11
  12 using namespace std;
  13 using namespace std::chrono;
  14
  15 ReceivedTimestamps find_received_timestamp(const vector<RefCountedFrame> &input_frames)
  16 {
  17         unsigned num_cards = global_mixer->get_num_cards();
  18         assert(input_frames.size() == num_cards * FRAME_HISTORY_LENGTH);
  19
  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());
  27                         } else {
  28                                 ts.ts.push_back(input_frame->received_timestamp);
  29                         }
  30                 }
  31         }
  32         return ts;
  33 }
  34
  35 void LatencyHistogram::init(const string &measuring_point)
  36 {
  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);
  46
  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);
  64                 }
  65         }
  66 }
  67
  68 void print_latency(const string &header, const ReceivedTimestamps &received_ts, bool is_b_frame, int *frameno, LatencyHistogram *histogram)
  69 {
  70         if (received_ts.ts.empty())
  71                 return;
  72
  73         const steady_clock::time_point now = steady_clock::now();
  74         duration<double> lowest_latency = now - *max_element(received_ts.ts.begin(), received_ts.ts.end());
  75         duration<double> highest_latency = now - *min_element(received_ts.ts.begin(), received_ts.ts.end());
  76
  77         unsigned num_cards = global_mixer->get_num_cards();
  78         assert(received_ts.ts.size() == num_cards * FRAME_HISTORY_LENGTH);
  79         for (unsigned card_index = 0; card_index < num_cards; ++card_index) {
  80                 for (unsigned frame_index = 0; frame_index < FRAME_HISTORY_LENGTH; ++frame_index) {
  81                         steady_clock::time_point ts = received_ts.ts[card_index * FRAME_HISTORY_LENGTH + frame_index];
  82                         if (ts == steady_clock::time_point::min()) {
  83                                 continue;
  84                         }
  85                         duration<double> latency = now - ts;
  86                         histogram->histograms[card_index][frame_index][is_b_frame].count_event(latency.count());
  87                 }
  88         }
  89
  90         // 101 is chosen so that it's prime, which is unlikely to get the same frame type every time.
  91         if (global_flags.print_video_latency && (++*frameno % 101) == 0) {
  92                 printf("%-60s %4.0f ms (lowest-latency input), %4.0f ms (highest-latency input)",
  93                         header.c_str(), 1e3 * lowest_latency.count(), 1e3 * highest_latency.count());
  94
  95                 if (is_b_frame) {
  96                         printf("  [on B-frame; potential extra latency]\n");
  97                 } else {
  98                         printf("\n");
  99                 }
 100         }
 101 }