stats_event_subscriber.cc 25 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729
  1. // Copyright 2014 The Chromium Authors. All rights reserved.
  2. // Use of this source code is governed by a BSD-style license that can be
  3. // found in the LICENSE file.
  4. #include "media/cast/logging/stats_event_subscriber.h"
  5. #include <algorithm>
  6. #include <cmath>
  7. #include <memory>
  8. #include <utility>
  9. #include "base/check_op.h"
  10. #include "base/format_macros.h"
  11. #include "base/notreached.h"
  12. #include "base/strings/stringprintf.h"
  13. #include "base/values.h"
  14. #define STAT_ENUM_TO_STRING(enum) \
  15. case enum: \
  16. return #enum
  17. namespace media {
  18. namespace cast {
  19. namespace {
  20. using media::cast::CastLoggingEvent;
  21. using media::cast::EventMediaType;
  22. const size_t kMaxPacketEventTimeMapSize = 1000;
  23. bool IsReceiverEvent(CastLoggingEvent event) {
  24. return event == FRAME_DECODED
  25. || event == FRAME_PLAYOUT
  26. || event == FRAME_ACK_SENT
  27. || event == PACKET_RECEIVED;
  28. }
  29. } // namespace
  30. StatsEventSubscriber::SimpleHistogram::SimpleHistogram(int64_t min,
  31. int64_t max,
  32. int64_t width)
  33. : min_(min), max_(max), width_(width), buckets_((max - min) / width + 2) {
  34. CHECK_GT(buckets_.size(), 2u);
  35. CHECK_EQ(0, (max_ - min_) % width_);
  36. }
  37. StatsEventSubscriber::SimpleHistogram::~SimpleHistogram() = default;
  38. void StatsEventSubscriber::SimpleHistogram::Add(int64_t sample) {
  39. if (sample < min_) {
  40. ++buckets_.front();
  41. } else if (sample >= max_) {
  42. ++buckets_.back();
  43. } else {
  44. size_t index = 1 + (sample - min_) / width_;
  45. DCHECK_LT(index, buckets_.size());
  46. ++buckets_[index];
  47. }
  48. }
  49. void StatsEventSubscriber::SimpleHistogram::Reset() {
  50. buckets_.assign(buckets_.size(), 0);
  51. }
  52. base::Value::List StatsEventSubscriber::SimpleHistogram::GetHistogram() const {
  53. base::Value::List histo;
  54. if (buckets_.front()) {
  55. base::Value::Dict bucket;
  56. bucket.Set(base::StringPrintf("<%" PRId64, min_), buckets_.front());
  57. histo.Append(std::move(bucket));
  58. }
  59. for (size_t i = 1; i < buckets_.size() - 1; i++) {
  60. if (!buckets_[i])
  61. continue;
  62. base::Value::Dict bucket;
  63. int64_t lower = min_ + (i - 1) * width_;
  64. int64_t upper = lower + width_ - 1;
  65. bucket.Set(base::StringPrintf("%" PRId64 "-%" PRId64, lower, upper),
  66. buckets_[i]);
  67. histo.Append(std::move(bucket));
  68. }
  69. if (buckets_.back()) {
  70. base::Value::Dict bucket;
  71. bucket.Set(base::StringPrintf(">=%" PRId64, max_), buckets_.back());
  72. histo.Append(std::move(bucket));
  73. }
  74. return histo;
  75. }
  76. StatsEventSubscriber::StatsEventSubscriber(
  77. EventMediaType event_media_type,
  78. const base::TickClock* clock,
  79. ReceiverTimeOffsetEstimator* offset_estimator)
  80. : event_media_type_(event_media_type),
  81. clock_(clock),
  82. offset_estimator_(offset_estimator),
  83. capture_latency_datapoints_(0),
  84. encode_time_datapoints_(0),
  85. queueing_latency_datapoints_(0),
  86. network_latency_datapoints_(0),
  87. packet_latency_datapoints_(0),
  88. frame_latency_datapoints_(0),
  89. e2e_latency_datapoints_(0),
  90. num_frames_dropped_by_encoder_(0),
  91. num_frames_late_(0),
  92. start_time_(clock_->NowTicks()) {
  93. DCHECK(event_media_type == AUDIO_EVENT || event_media_type == VIDEO_EVENT);
  94. InitHistograms();
  95. }
  96. StatsEventSubscriber::~StatsEventSubscriber() {
  97. DCHECK(thread_checker_.CalledOnValidThread());
  98. }
  99. void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
  100. DCHECK(thread_checker_.CalledOnValidThread());
  101. CastLoggingEvent type = frame_event.type;
  102. if (frame_event.media_type != event_media_type_)
  103. return;
  104. auto it = frame_stats_.find(type);
  105. if (it == frame_stats_.end()) {
  106. FrameLogStats stats;
  107. stats.event_counter = 1;
  108. stats.sum_size = frame_event.size;
  109. stats.sum_delay = frame_event.delay_delta;
  110. frame_stats_.insert(std::make_pair(type, stats));
  111. } else {
  112. ++(it->second.event_counter);
  113. it->second.sum_size += frame_event.size;
  114. it->second.sum_delay += frame_event.delay_delta;
  115. }
  116. bool is_receiver_event = IsReceiverEvent(type);
  117. UpdateFirstLastEventTime(frame_event.timestamp, is_receiver_event);
  118. if (type == FRAME_CAPTURE_BEGIN) {
  119. RecordFrameCaptureTime(frame_event);
  120. } else if (type == FRAME_CAPTURE_END) {
  121. RecordCaptureLatency(frame_event);
  122. } else if (type == FRAME_ENCODED) {
  123. RecordEncodeLatency(frame_event);
  124. } else if (type == FRAME_ACK_SENT) {
  125. RecordFrameTxLatency(frame_event);
  126. } else if (type == FRAME_PLAYOUT) {
  127. RecordE2ELatency(frame_event);
  128. base::TimeDelta delay_delta = frame_event.delay_delta;
  129. // Positive delay_delta means the frame is late.
  130. if (delay_delta.is_positive()) {
  131. num_frames_late_++;
  132. histograms_[LATE_FRAME_MS_HISTO]->Add(delay_delta.InMillisecondsF());
  133. }
  134. }
  135. if (is_receiver_event)
  136. UpdateLastResponseTime(frame_event.timestamp);
  137. }
  138. void StatsEventSubscriber::OnReceivePacketEvent(
  139. const PacketEvent& packet_event) {
  140. DCHECK(thread_checker_.CalledOnValidThread());
  141. CastLoggingEvent type = packet_event.type;
  142. if (packet_event.media_type != event_media_type_)
  143. return;
  144. auto it = packet_stats_.find(type);
  145. if (it == packet_stats_.end()) {
  146. PacketLogStats stats;
  147. stats.event_counter = 1;
  148. stats.sum_size = packet_event.size;
  149. packet_stats_.insert(std::make_pair(type, stats));
  150. } else {
  151. ++(it->second.event_counter);
  152. it->second.sum_size += packet_event.size;
  153. }
  154. bool is_receiver_event = IsReceiverEvent(type);
  155. UpdateFirstLastEventTime(packet_event.timestamp, is_receiver_event);
  156. if (type == PACKET_SENT_TO_NETWORK ||
  157. type == PACKET_RECEIVED) {
  158. RecordPacketRelatedLatencies(packet_event);
  159. } else if (type == PACKET_RETRANSMITTED) {
  160. // We only measure network latency using packets that doesn't have to be
  161. // retransmitted as there is precisely one sent-receive timestamp pairs.
  162. ErasePacketSentTime(packet_event);
  163. }
  164. if (is_receiver_event)
  165. UpdateLastResponseTime(packet_event.timestamp);
  166. }
  167. void StatsEventSubscriber::UpdateFirstLastEventTime(base::TimeTicks timestamp,
  168. bool is_receiver_event) {
  169. if (is_receiver_event) {
  170. base::TimeDelta receiver_offset;
  171. if (!GetReceiverOffset(&receiver_offset))
  172. return;
  173. timestamp -= receiver_offset;
  174. }
  175. if (first_event_time_.is_null()) {
  176. first_event_time_ = timestamp;
  177. } else {
  178. first_event_time_ = std::min(first_event_time_, timestamp);
  179. }
  180. if (last_event_time_.is_null()) {
  181. last_event_time_ = timestamp;
  182. } else {
  183. last_event_time_ = std::max(last_event_time_, timestamp);
  184. }
  185. }
  186. base::Value::Dict StatsEventSubscriber::GetStats() const {
  187. StatsMap stats_map;
  188. GetStatsInternal(&stats_map);
  189. base::Value::Dict ret;
  190. base::Value::Dict stats;
  191. for (StatsMap::const_iterator it = stats_map.begin(); it != stats_map.end();
  192. ++it) {
  193. // Round to 3 digits after the decimal point.
  194. stats.Set(CastStatToString(it->first), round(it->second * 1000.0) / 1000.0);
  195. }
  196. // Populate all histograms.
  197. for (auto it = histograms_.begin(); it != histograms_.end(); ++it) {
  198. stats.Set(CastStatToString(it->first), it->second->GetHistogram());
  199. }
  200. ret.Set(event_media_type_ == AUDIO_EVENT ? "audio" : "video",
  201. std::move(stats));
  202. return ret;
  203. }
  204. void StatsEventSubscriber::Reset() {
  205. DCHECK(thread_checker_.CalledOnValidThread());
  206. frame_stats_.clear();
  207. packet_stats_.clear();
  208. total_capture_latency_ = base::TimeDelta();
  209. capture_latency_datapoints_ = 0;
  210. total_encode_time_ = base::TimeDelta();
  211. encode_time_datapoints_ = 0;
  212. total_queueing_latency_ = base::TimeDelta();
  213. queueing_latency_datapoints_ = 0;
  214. total_network_latency_ = base::TimeDelta();
  215. network_latency_datapoints_ = 0;
  216. total_packet_latency_ = base::TimeDelta();
  217. packet_latency_datapoints_ = 0;
  218. total_frame_latency_ = base::TimeDelta();
  219. frame_latency_datapoints_ = 0;
  220. total_e2e_latency_ = base::TimeDelta();
  221. e2e_latency_datapoints_ = 0;
  222. num_frames_dropped_by_encoder_ = 0;
  223. num_frames_late_ = 0;
  224. recent_frame_infos_.clear();
  225. packet_sent_times_.clear();
  226. start_time_ = clock_->NowTicks();
  227. last_response_received_time_ = base::TimeTicks();
  228. for (auto it = histograms_.begin(); it != histograms_.end(); ++it) {
  229. it->second->Reset();
  230. }
  231. first_event_time_ = base::TimeTicks();
  232. last_event_time_ = base::TimeTicks();
  233. }
  234. // static
  235. const char* StatsEventSubscriber::CastStatToString(CastStat stat) {
  236. switch (stat) {
  237. STAT_ENUM_TO_STRING(CAPTURE_FPS);
  238. STAT_ENUM_TO_STRING(ENCODE_FPS);
  239. STAT_ENUM_TO_STRING(DECODE_FPS);
  240. STAT_ENUM_TO_STRING(AVG_CAPTURE_LATENCY_MS);
  241. STAT_ENUM_TO_STRING(AVG_ENCODE_TIME_MS);
  242. STAT_ENUM_TO_STRING(AVG_QUEUEING_LATENCY_MS);
  243. STAT_ENUM_TO_STRING(AVG_NETWORK_LATENCY_MS);
  244. STAT_ENUM_TO_STRING(AVG_PACKET_LATENCY_MS);
  245. STAT_ENUM_TO_STRING(AVG_FRAME_LATENCY_MS);
  246. STAT_ENUM_TO_STRING(AVG_E2E_LATENCY_MS);
  247. STAT_ENUM_TO_STRING(ENCODE_KBPS);
  248. STAT_ENUM_TO_STRING(TRANSMISSION_KBPS);
  249. STAT_ENUM_TO_STRING(RETRANSMISSION_KBPS);
  250. STAT_ENUM_TO_STRING(MS_SINCE_LAST_RECEIVER_RESPONSE);
  251. STAT_ENUM_TO_STRING(NUM_FRAMES_CAPTURED);
  252. STAT_ENUM_TO_STRING(NUM_FRAMES_DROPPED_BY_ENCODER);
  253. STAT_ENUM_TO_STRING(NUM_FRAMES_LATE);
  254. STAT_ENUM_TO_STRING(NUM_PACKETS_SENT);
  255. STAT_ENUM_TO_STRING(NUM_PACKETS_RETRANSMITTED);
  256. STAT_ENUM_TO_STRING(NUM_PACKETS_RECEIVED);
  257. STAT_ENUM_TO_STRING(NUM_PACKETS_RTX_REJECTED);
  258. STAT_ENUM_TO_STRING(FIRST_EVENT_TIME_MS);
  259. STAT_ENUM_TO_STRING(LAST_EVENT_TIME_MS);
  260. STAT_ENUM_TO_STRING(CAPTURE_LATENCY_MS_HISTO);
  261. STAT_ENUM_TO_STRING(ENCODE_TIME_MS_HISTO);
  262. STAT_ENUM_TO_STRING(QUEUEING_LATENCY_MS_HISTO);
  263. STAT_ENUM_TO_STRING(NETWORK_LATENCY_MS_HISTO);
  264. STAT_ENUM_TO_STRING(PACKET_LATENCY_MS_HISTO);
  265. STAT_ENUM_TO_STRING(FRAME_LATENCY_MS_HISTO);
  266. STAT_ENUM_TO_STRING(E2E_LATENCY_MS_HISTO);
  267. STAT_ENUM_TO_STRING(LATE_FRAME_MS_HISTO);
  268. }
  269. NOTREACHED();
  270. return "";
  271. }
  272. const int kDefaultMaxLatencyBucketMs = 800;
  273. const int kDefaultBucketWidthMs = 20;
  274. // For small latency values.
  275. const int kSmallMaxLatencyBucketMs = 100;
  276. const int kSmallBucketWidthMs = 5;
  277. // For large latency values.
  278. const int kLargeMaxLatencyBucketMs = 1200;
  279. const int kLargeBucketWidthMs = 50;
  280. void StatsEventSubscriber::InitHistograms() {
  281. histograms_[E2E_LATENCY_MS_HISTO] = std::make_unique<SimpleHistogram>(
  282. 0, kLargeMaxLatencyBucketMs, kLargeBucketWidthMs);
  283. histograms_[QUEUEING_LATENCY_MS_HISTO] = std::make_unique<SimpleHistogram>(
  284. 0, kDefaultMaxLatencyBucketMs, kDefaultBucketWidthMs);
  285. histograms_[NETWORK_LATENCY_MS_HISTO] = std::make_unique<SimpleHistogram>(
  286. 0, kDefaultMaxLatencyBucketMs, kDefaultBucketWidthMs);
  287. histograms_[PACKET_LATENCY_MS_HISTO] = std::make_unique<SimpleHistogram>(
  288. 0, kDefaultMaxLatencyBucketMs, kDefaultBucketWidthMs);
  289. histograms_[FRAME_LATENCY_MS_HISTO] = std::make_unique<SimpleHistogram>(
  290. 0, kDefaultMaxLatencyBucketMs, kDefaultBucketWidthMs);
  291. histograms_[LATE_FRAME_MS_HISTO] = std::make_unique<SimpleHistogram>(
  292. 0, kDefaultMaxLatencyBucketMs, kDefaultBucketWidthMs);
  293. histograms_[CAPTURE_LATENCY_MS_HISTO] = std::make_unique<SimpleHistogram>(
  294. 0, kSmallMaxLatencyBucketMs, kSmallBucketWidthMs);
  295. histograms_[ENCODE_TIME_MS_HISTO] = std::make_unique<SimpleHistogram>(
  296. 0, kSmallMaxLatencyBucketMs, kSmallBucketWidthMs);
  297. }
  298. void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
  299. DCHECK(thread_checker_.CalledOnValidThread());
  300. stats_map->clear();
  301. base::TimeTicks end_time = clock_->NowTicks();
  302. PopulateFpsStat(
  303. end_time, FRAME_CAPTURE_BEGIN, CAPTURE_FPS, stats_map);
  304. PopulateFpsStat(
  305. end_time, FRAME_ENCODED, ENCODE_FPS, stats_map);
  306. PopulateFpsStat(
  307. end_time, FRAME_DECODED, DECODE_FPS, stats_map);
  308. PopulateFrameBitrateStat(end_time, stats_map);
  309. PopulatePacketBitrateStat(end_time,
  310. PACKET_SENT_TO_NETWORK,
  311. TRANSMISSION_KBPS,
  312. stats_map);
  313. PopulatePacketBitrateStat(end_time,
  314. PACKET_RETRANSMITTED,
  315. RETRANSMISSION_KBPS,
  316. stats_map);
  317. PopulateFrameCountStat(FRAME_CAPTURE_END, NUM_FRAMES_CAPTURED, stats_map);
  318. PopulatePacketCountStat(PACKET_SENT_TO_NETWORK, NUM_PACKETS_SENT, stats_map);
  319. PopulatePacketCountStat(
  320. PACKET_RETRANSMITTED, NUM_PACKETS_RETRANSMITTED, stats_map);
  321. PopulatePacketCountStat(PACKET_RECEIVED, NUM_PACKETS_RECEIVED, stats_map);
  322. PopulatePacketCountStat(
  323. PACKET_RTX_REJECTED, NUM_PACKETS_RTX_REJECTED, stats_map);
  324. if (capture_latency_datapoints_ > 0) {
  325. double avg_capture_latency_ms =
  326. total_capture_latency_.InMillisecondsF() / capture_latency_datapoints_;
  327. stats_map->insert(
  328. std::make_pair(AVG_CAPTURE_LATENCY_MS, avg_capture_latency_ms));
  329. }
  330. if (encode_time_datapoints_ > 0) {
  331. double avg_encode_time_ms =
  332. total_encode_time_.InMillisecondsF() / encode_time_datapoints_;
  333. stats_map->insert(
  334. std::make_pair(AVG_ENCODE_TIME_MS, avg_encode_time_ms));
  335. }
  336. if (queueing_latency_datapoints_ > 0) {
  337. double avg_queueing_latency_ms =
  338. total_queueing_latency_.InMillisecondsF() /
  339. queueing_latency_datapoints_;
  340. stats_map->insert(
  341. std::make_pair(AVG_QUEUEING_LATENCY_MS, avg_queueing_latency_ms));
  342. }
  343. if (network_latency_datapoints_ > 0) {
  344. double avg_network_latency_ms =
  345. total_network_latency_.InMillisecondsF() / network_latency_datapoints_;
  346. stats_map->insert(
  347. std::make_pair(AVG_NETWORK_LATENCY_MS, avg_network_latency_ms));
  348. }
  349. if (packet_latency_datapoints_ > 0) {
  350. double avg_packet_latency_ms =
  351. total_packet_latency_.InMillisecondsF() / packet_latency_datapoints_;
  352. stats_map->insert(
  353. std::make_pair(AVG_PACKET_LATENCY_MS, avg_packet_latency_ms));
  354. }
  355. if (frame_latency_datapoints_ > 0) {
  356. double avg_frame_latency_ms =
  357. total_frame_latency_.InMillisecondsF() / frame_latency_datapoints_;
  358. stats_map->insert(
  359. std::make_pair(AVG_FRAME_LATENCY_MS, avg_frame_latency_ms));
  360. }
  361. if (e2e_latency_datapoints_ > 0) {
  362. double avg_e2e_latency_ms =
  363. total_e2e_latency_.InMillisecondsF() / e2e_latency_datapoints_;
  364. stats_map->insert(std::make_pair(AVG_E2E_LATENCY_MS, avg_e2e_latency_ms));
  365. }
  366. if (!last_response_received_time_.is_null()) {
  367. stats_map->insert(
  368. std::make_pair(MS_SINCE_LAST_RECEIVER_RESPONSE,
  369. (end_time - last_response_received_time_).InMillisecondsF()));
  370. }
  371. stats_map->insert(std::make_pair(NUM_FRAMES_DROPPED_BY_ENCODER,
  372. num_frames_dropped_by_encoder_));
  373. stats_map->insert(std::make_pair(NUM_FRAMES_LATE, num_frames_late_));
  374. if (!first_event_time_.is_null()) {
  375. stats_map->insert(std::make_pair(
  376. FIRST_EVENT_TIME_MS,
  377. (first_event_time_ - base::TimeTicks::UnixEpoch()).InMillisecondsF()));
  378. }
  379. if (!last_event_time_.is_null()) {
  380. stats_map->insert(std::make_pair(
  381. LAST_EVENT_TIME_MS,
  382. (last_event_time_ - base::TimeTicks::UnixEpoch()).InMillisecondsF()));
  383. }
  384. }
  385. StatsEventSubscriber::SimpleHistogram*
  386. StatsEventSubscriber::GetHistogramForTesting(
  387. CastStat stats) const {
  388. DCHECK(histograms_.find(stats) != histograms_.end());
  389. return histograms_.find(stats)->second.get();
  390. }
  391. bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
  392. base::TimeDelta receiver_offset_lower_bound;
  393. base::TimeDelta receiver_offset_upper_bound;
  394. if (!offset_estimator_->GetReceiverOffsetBounds(
  395. &receiver_offset_lower_bound, &receiver_offset_upper_bound)) {
  396. return false;
  397. }
  398. *offset = (receiver_offset_lower_bound + receiver_offset_upper_bound) / 2;
  399. return true;
  400. }
  401. void StatsEventSubscriber::MaybeInsertFrameInfo(RtpTimeTicks rtp_timestamp,
  402. const FrameInfo& frame_info) {
  403. // No need to insert if |rtp_timestamp| is the smaller than every key in the
  404. // map as it is just going to get erased anyway.
  405. if (recent_frame_infos_.size() == kMaxFrameInfoMapSize &&
  406. rtp_timestamp < recent_frame_infos_.begin()->first) {
  407. return;
  408. }
  409. recent_frame_infos_.insert(std::make_pair(rtp_timestamp, frame_info));
  410. if (recent_frame_infos_.size() >= kMaxFrameInfoMapSize) {
  411. auto erase_it = recent_frame_infos_.begin();
  412. if (erase_it->second.encode_end_time.is_null())
  413. num_frames_dropped_by_encoder_++;
  414. recent_frame_infos_.erase(erase_it);
  415. }
  416. }
  417. void StatsEventSubscriber::RecordFrameCaptureTime(
  418. const FrameEvent& frame_event) {
  419. FrameInfo frame_info;
  420. frame_info.capture_time = frame_event.timestamp;
  421. MaybeInsertFrameInfo(frame_event.rtp_timestamp, frame_info);
  422. }
  423. void StatsEventSubscriber::RecordCaptureLatency(const FrameEvent& frame_event) {
  424. auto it = recent_frame_infos_.find(frame_event.rtp_timestamp);
  425. if (it == recent_frame_infos_.end()) {
  426. return;
  427. }
  428. if (!it->second.capture_time.is_null()) {
  429. base::TimeDelta latency = frame_event.timestamp - it->second.capture_time;
  430. total_capture_latency_ += latency;
  431. capture_latency_datapoints_++;
  432. histograms_[CAPTURE_LATENCY_MS_HISTO]->Add(latency.InMillisecondsF());
  433. }
  434. it->second.capture_end_time = frame_event.timestamp;
  435. }
  436. void StatsEventSubscriber::RecordEncodeLatency(const FrameEvent& frame_event) {
  437. auto it = recent_frame_infos_.find(frame_event.rtp_timestamp);
  438. if (it == recent_frame_infos_.end()) {
  439. FrameInfo frame_info;
  440. frame_info.encode_end_time = frame_event.timestamp;
  441. MaybeInsertFrameInfo(frame_event.rtp_timestamp, frame_info);
  442. return;
  443. }
  444. if (!it->second.capture_end_time.is_null()) {
  445. base::TimeDelta latency =
  446. frame_event.timestamp - it->second.capture_end_time;
  447. total_encode_time_ += latency;
  448. encode_time_datapoints_++;
  449. histograms_[ENCODE_TIME_MS_HISTO]->Add(latency.InMillisecondsF());
  450. }
  451. it->second.encode_end_time = frame_event.timestamp;
  452. }
  453. void StatsEventSubscriber::RecordFrameTxLatency(const FrameEvent& frame_event) {
  454. auto it = recent_frame_infos_.find(frame_event.rtp_timestamp);
  455. if (it == recent_frame_infos_.end())
  456. return;
  457. if (it->second.encode_end_time.is_null())
  458. return;
  459. base::TimeDelta receiver_offset;
  460. if (!GetReceiverOffset(&receiver_offset))
  461. return;
  462. base::TimeTicks sender_time = frame_event.timestamp - receiver_offset;
  463. base::TimeDelta latency = sender_time - it->second.encode_end_time;
  464. total_frame_latency_ += latency;
  465. frame_latency_datapoints_++;
  466. histograms_[FRAME_LATENCY_MS_HISTO]->Add(latency.InMillisecondsF());
  467. }
  468. void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
  469. base::TimeDelta receiver_offset;
  470. if (!GetReceiverOffset(&receiver_offset))
  471. return;
  472. auto it = recent_frame_infos_.find(frame_event.rtp_timestamp);
  473. if (it == recent_frame_infos_.end())
  474. return;
  475. base::TimeTicks playout_time = frame_event.timestamp - receiver_offset;
  476. base::TimeDelta latency = playout_time - it->second.capture_time;
  477. total_e2e_latency_ += latency;
  478. e2e_latency_datapoints_++;
  479. histograms_[E2E_LATENCY_MS_HISTO]->Add(latency.InMillisecondsF());
  480. }
  481. void StatsEventSubscriber::UpdateLastResponseTime(
  482. base::TimeTicks receiver_time) {
  483. base::TimeDelta receiver_offset;
  484. if (!GetReceiverOffset(&receiver_offset))
  485. return;
  486. base::TimeTicks sender_time = receiver_time - receiver_offset;
  487. last_response_received_time_ = sender_time;
  488. }
  489. void StatsEventSubscriber::ErasePacketSentTime(
  490. const PacketEvent& packet_event) {
  491. std::pair<RtpTimeTicks, uint16_t> key(
  492. std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
  493. packet_sent_times_.erase(key);
  494. }
  495. void StatsEventSubscriber::RecordPacketRelatedLatencies(
  496. const PacketEvent& packet_event) {
  497. // Log queueing latency.
  498. if (packet_event.type == PACKET_SENT_TO_NETWORK) {
  499. auto it = recent_frame_infos_.find(packet_event.rtp_timestamp);
  500. if (it != recent_frame_infos_.end()) {
  501. base::TimeDelta latency =
  502. packet_event.timestamp - it->second.encode_end_time;
  503. total_queueing_latency_ += latency;
  504. queueing_latency_datapoints_++;
  505. histograms_[QUEUEING_LATENCY_MS_HISTO]->Add(
  506. latency.InMillisecondsF());
  507. }
  508. }
  509. // Log network latency and total packet latency;
  510. base::TimeDelta receiver_offset;
  511. if (!GetReceiverOffset(&receiver_offset))
  512. return;
  513. std::pair<RtpTimeTicks, uint16_t> key(
  514. std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
  515. auto it = packet_sent_times_.find(key);
  516. if (it == packet_sent_times_.end()) {
  517. std::pair<base::TimeTicks, CastLoggingEvent> value =
  518. std::make_pair(packet_event.timestamp, packet_event.type);
  519. packet_sent_times_.insert(std::make_pair(key, value));
  520. if (packet_sent_times_.size() > kMaxPacketEventTimeMapSize)
  521. packet_sent_times_.erase(packet_sent_times_.begin());
  522. } else {
  523. std::pair<base::TimeTicks, CastLoggingEvent> value = it->second;
  524. CastLoggingEvent recorded_type = value.second;
  525. bool match = false;
  526. base::TimeTicks packet_sent_time;
  527. base::TimeTicks packet_received_time;
  528. if (recorded_type == PACKET_SENT_TO_NETWORK &&
  529. packet_event.type == PACKET_RECEIVED) {
  530. packet_sent_time = value.first;
  531. packet_received_time = packet_event.timestamp;
  532. match = true;
  533. } else if (recorded_type == PACKET_RECEIVED &&
  534. packet_event.type == PACKET_SENT_TO_NETWORK) {
  535. packet_sent_time = packet_event.timestamp;
  536. packet_received_time = value.first;
  537. match = true;
  538. }
  539. if (match) {
  540. packet_sent_times_.erase(it);
  541. // Subtract by offset.
  542. packet_received_time -= receiver_offset;
  543. base::TimeDelta latency_delta = packet_received_time - packet_sent_time;
  544. total_network_latency_ += latency_delta;
  545. network_latency_datapoints_++;
  546. histograms_[NETWORK_LATENCY_MS_HISTO]->Add(
  547. latency_delta.InMillisecondsF());
  548. // Log total network latency.
  549. auto frame_it = recent_frame_infos_.find(packet_event.rtp_timestamp);
  550. if (frame_it != recent_frame_infos_.end()) {
  551. base::TimeDelta latency =
  552. packet_received_time - frame_it->second.encode_end_time;
  553. total_packet_latency_ += latency;
  554. packet_latency_datapoints_++;
  555. histograms_[PACKET_LATENCY_MS_HISTO]->Add(
  556. latency.InMillisecondsF());
  557. }
  558. }
  559. }
  560. }
  561. void StatsEventSubscriber::PopulateFpsStat(base::TimeTicks end_time,
  562. CastLoggingEvent event,
  563. CastStat stat,
  564. StatsMap* stats_map) const {
  565. auto it = frame_stats_.find(event);
  566. if (it != frame_stats_.end()) {
  567. double fps = 0.0;
  568. base::TimeDelta duration = (end_time - start_time_);
  569. int count = it->second.event_counter;
  570. if (duration.is_positive())
  571. fps = count / duration.InSecondsF();
  572. stats_map->insert(std::make_pair(stat, fps));
  573. }
  574. }
  575. void StatsEventSubscriber::PopulateFrameCountStat(CastLoggingEvent event,
  576. CastStat stat,
  577. StatsMap* stats_map) const {
  578. auto it = frame_stats_.find(event);
  579. if (it != frame_stats_.end()) {
  580. stats_map->insert(std::make_pair(stat, it->second.event_counter));
  581. }
  582. }
  583. void StatsEventSubscriber::PopulatePacketCountStat(CastLoggingEvent event,
  584. CastStat stat,
  585. StatsMap* stats_map) const {
  586. auto it = packet_stats_.find(event);
  587. if (it != packet_stats_.end()) {
  588. stats_map->insert(std::make_pair(stat, it->second.event_counter));
  589. }
  590. }
  591. void StatsEventSubscriber::PopulateFrameBitrateStat(base::TimeTicks end_time,
  592. StatsMap* stats_map) const {
  593. auto it = frame_stats_.find(FRAME_ENCODED);
  594. if (it != frame_stats_.end()) {
  595. double kbps = 0.0;
  596. base::TimeDelta duration = end_time - start_time_;
  597. if (duration.is_positive()) {
  598. kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
  599. }
  600. stats_map->insert(std::make_pair(ENCODE_KBPS, kbps));
  601. }
  602. }
  603. void StatsEventSubscriber::PopulatePacketBitrateStat(
  604. base::TimeTicks end_time,
  605. CastLoggingEvent event,
  606. CastStat stat,
  607. StatsMap* stats_map) const {
  608. auto it = packet_stats_.find(event);
  609. if (it != packet_stats_.end()) {
  610. double kbps = 0;
  611. base::TimeDelta duration = end_time - start_time_;
  612. if (duration.is_positive()) {
  613. kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
  614. }
  615. stats_map->insert(std::make_pair(stat, kbps));
  616. }
  617. }
  618. StatsEventSubscriber::FrameLogStats::FrameLogStats()
  619. : event_counter(0), sum_size(0) {}
  620. StatsEventSubscriber::FrameLogStats::~FrameLogStats() = default;
  621. StatsEventSubscriber::PacketLogStats::PacketLogStats()
  622. : event_counter(0), sum_size(0) {}
  623. StatsEventSubscriber::PacketLogStats::~PacketLogStats() = default;
  624. StatsEventSubscriber::FrameInfo::FrameInfo() : encoded(false) {
  625. }
  626. StatsEventSubscriber::FrameInfo::~FrameInfo() = default;
  627. } // namespace cast
  628. } // namespace media