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

   1 #include "print_latency.h"
   2
   3 #include "defs.h"
   4 #include "flags.h"
   5 #include "ref_counted_frame.h"
   6 #include "shared/metrics.h"
   7 #include "mixer.h"
   8 #include "shared/shared_defs.h"
   9
  10 #include <assert.h>
  11 #include <stdio.h>
  12 #include <algorithm>
  13 #include <chrono>
  14 #include <string>
  15 #include <vector>
  16
  17 using namespace std;
  18 using namespace std::chrono;
  19
  20 ReceivedTimestamps find_received_timestamp(const vector<RefCountedFrame> &input_frames)
  21 {
  22         assert(input_frames.size() == MAX_VIDEO_CARDS * FRAME_HISTORY_LENGTH);
  23
  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());
  31                         } else {
  32                                 ts.ts.push_back(input_frame->received_timestamp);
  33                         }
  34                 }
  35         }
  36         return ts;
  37 }
  38
  39 void LatencyHistogram::init(const string &measuring_point)
  40 {
  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);
  49
  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);
  76                 }
  77         }
  78 }
  79
  80 void print_latency(const char *header, const ReceivedTimestamps &received_ts, bool is_b_frame, int *frameno, LatencyHistogram *histogram)
  81 {
  82         if (received_ts.ts.empty())
  83                 return;
  84
  85         const steady_clock::time_point now = steady_clock::now();
  86
  87         if (global_mixer == nullptr) {
  88                 // Kaeru.
  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());
  95                 }
  96         } else {
  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()) {
 102                                         continue;
 103                                 }
 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());
 107                         }
 108                 }
 109         }
 110
 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);
 119                         }
 120                 }
 121                 duration<double> lowest_latency = now - max_ts;
 122                 duration<double> highest_latency = now - min_ts;
 123
 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());
 126
 127                 if (is_b_frame) {
 128                         printf("  [on B-frame; potential extra latency]\n");
 129                 } else {
 130                         printf("\n");
 131                 }
 132         }
 133 }