summaryrefslogtreecommitdiffstats
path: root/media
diff options
context:
space:
mode:
authorimcheng@chromium.org <imcheng@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98>2014-04-28 15:29:01 +0000
committerimcheng@chromium.org <imcheng@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98>2014-04-28 15:29:01 +0000
commit146eae3d95239b048fc4f1e778f43e0f59be9b96 (patch)
treecd02ac59e57fac3d27b713a294a5cc98e540603f /media
parent393a6465013d3b962c67d38131fae58037c748e5 (diff)
downloadchromium_src-146eae3d95239b048fc4f1e778f43e0f59be9b96.zip
chromium_src-146eae3d95239b048fc4f1e778f43e0f59be9b96.tar.gz
chromium_src-146eae3d95239b048fc4f1e778f43e0f59be9b96.tar.bz2
Cast: Provide more meaningful stats.
- Instead of giving generic stats for each event type, StatsEventSubsriber will now provide more specific stats. It also provide new kinds of stats (packet loss %, latency) - stats_util to convert output of StatsEventSubscriber to a base::DictionaryValue is moved into the subscriber implementation. - Introduced ReceiverTimeOffsetEstimator to estimate receiver offset based on raw events received. It is used by StatsEventSubscriber to determine stats such as latency. The estimator itself is implemented as a RawEventSubscriber and is shared between the audio and video StatsEventSubscriber objects. - Move stats related structs from logging_defines.{cc,h} into stats_event_subscriber.{cc,h} BUG=353019 Review URL: https://codereview.chromium.org/236123003 git-svn-id: svn://svn.chromium.org/chrome/trunk/src@266574 0039d316-1c4b-4281-b951-d872f2087c98
Diffstat (limited to 'media')
-rw-r--r--media/cast/cast.gyp7
-rw-r--r--media/cast/cast_testing.gypi3
-rw-r--r--media/cast/logging/logging_defines.cc10
-rw-r--r--media/cast/logging/logging_defines.h27
-rw-r--r--media/cast/logging/raw_event_subscriber_bundle.cc99
-rw-r--r--media/cast/logging/raw_event_subscriber_bundle.h84
-rw-r--r--media/cast/logging/receiver_time_offset_estimator.h39
-rw-r--r--media/cast/logging/receiver_time_offset_estimator_impl.cc125
-rw-r--r--media/cast/logging/receiver_time_offset_estimator_impl.h64
-rw-r--r--media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc234
-rw-r--r--media/cast/logging/stats_event_subscriber.cc397
-rw-r--r--media/cast/logging/stats_event_subscriber.h145
-rw-r--r--media/cast/logging/stats_event_subscriber_unittest.cc389
-rw-r--r--media/cast/logging/stats_util.cc72
-rw-r--r--media/cast/logging/stats_util.h27
-rw-r--r--media/cast/test/fake_receiver_time_offset_estimator.cc37
-rw-r--r--media/cast/test/fake_receiver_time_offset_estimator.h42
-rw-r--r--media/cast/test/sender.cc62
18 files changed, 1614 insertions, 249 deletions
diff --git a/media/cast/cast.gyp b/media/cast/cast.gyp
index d24b14e..d489a6a 100644
--- a/media/cast/cast.gyp
+++ b/media/cast/cast.gyp
@@ -46,12 +46,15 @@
'logging/logging_raw.cc',
'logging/logging_raw.h',
'logging/raw_event_subscriber.h',
+ 'logging/raw_event_subscriber_bundle.cc',
+ 'logging/raw_event_subscriber_bundle.h',
+ 'logging/receiver_time_offset_estimator.h',
+ 'logging/receiver_time_offset_estimator_impl.cc',
+ 'logging/receiver_time_offset_estimator_impl.h',
'logging/simple_event_subscriber.cc',
'logging/simple_event_subscriber.h',
'logging/stats_event_subscriber.cc',
'logging/stats_event_subscriber.h',
- 'logging/stats_util.cc',
- 'logging/stats_util.h',
'transport/cast_transport_config.cc',
'transport/cast_transport_config.h',
'transport/cast_transport_defines.h',
diff --git a/media/cast/cast_testing.gypi b/media/cast/cast_testing.gypi
index cd5e929..f8c2553 100644
--- a/media/cast/cast_testing.gypi
+++ b/media/cast/cast_testing.gypi
@@ -73,6 +73,7 @@
'logging/serialize_deserialize_test.cc',
'logging/logging_impl_unittest.cc',
'logging/logging_raw_unittest.cc',
+ 'logging/receiver_time_offset_estimator_impl_unittest.cc',
'logging/simple_event_subscriber_unittest.cc',
'logging/stats_event_subscriber_unittest.cc',
'rtcp/mock_rtcp_receiver_feedback.cc',
@@ -94,6 +95,8 @@
'rtp_receiver/rtp_parser/test/rtp_packet_builder.cc',
'rtp_receiver/rtp_parser/rtp_parser_unittest.cc',
'test/end2end_unittest.cc',
+ 'test/fake_receiver_time_offset_estimator.cc',
+ 'test/fake_receiver_time_offset_estimator.h',
'test/fake_single_thread_task_runner.cc',
'test/fake_single_thread_task_runner.h',
'test/fake_video_encode_accelerator.cc',
diff --git a/media/cast/logging/logging_defines.cc b/media/cast/logging/logging_defines.cc
index 894b059..e86f02b 100644
--- a/media/cast/logging/logging_defines.cc
+++ b/media/cast/logging/logging_defines.cc
@@ -104,15 +104,5 @@ PacketEvent::PacketEvent()
type(kUnknown) {}
PacketEvent::~PacketEvent() {}
-FrameLogStats::FrameLogStats()
- : event_counter(0),
- sum_size(0) {}
-FrameLogStats::~FrameLogStats() {}
-
-PacketLogStats::PacketLogStats()
- : event_counter(0),
- sum_size(0) {}
-PacketLogStats::~PacketLogStats() {}
-
} // namespace cast
} // namespace media
diff --git a/media/cast/logging/logging_defines.h b/media/cast/logging/logging_defines.h
index 9b9ed51..a87d2d5 100644
--- a/media/cast/logging/logging_defines.h
+++ b/media/cast/logging/logging_defines.h
@@ -107,33 +107,6 @@ struct PacketEvent {
CastLoggingEvent type;
};
-// Generic statistics given the raw data. More specific data (e.g. frame rate
-// and bit rate) can be computed given the basic metrics.
-// Some of the metrics will only be set when applicable, e.g. delay and size.
-struct FrameLogStats {
- FrameLogStats();
- ~FrameLogStats();
- base::TimeTicks first_event_time;
- base::TimeTicks last_event_time;
- int event_counter;
- size_t sum_size;
- base::TimeDelta min_delay;
- base::TimeDelta max_delay;
- base::TimeDelta sum_delay;
-};
-
-struct PacketLogStats {
- PacketLogStats();
- ~PacketLogStats();
- base::TimeTicks first_event_time;
- base::TimeTicks last_event_time;
- int event_counter;
- size_t sum_size;
-};
-
-typedef std::map<CastLoggingEvent, FrameLogStats> FrameStatsMap;
-typedef std::map<CastLoggingEvent, PacketLogStats> PacketStatsMap;
-
} // namespace cast
} // namespace media
diff --git a/media/cast/logging/raw_event_subscriber_bundle.cc b/media/cast/logging/raw_event_subscriber_bundle.cc
new file mode 100644
index 0000000..1946b6c
--- /dev/null
+++ b/media/cast/logging/raw_event_subscriber_bundle.cc
@@ -0,0 +1,99 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "media/cast/logging/raw_event_subscriber_bundle.h"
+
+#include "media/cast/cast_environment.h"
+#include "media/cast/logging/receiver_time_offset_estimator_impl.h"
+
+namespace media {
+namespace cast {
+
+RawEventSubscriberBundleForStream::RawEventSubscriberBundleForStream(
+ const scoped_refptr<CastEnvironment>& cast_environment,
+ bool is_audio,
+ ReceiverTimeOffsetEstimator* offset_estimator)
+ : cast_environment_(cast_environment),
+ event_subscriber_(
+ is_audio ? AUDIO_EVENT : VIDEO_EVENT,
+ is_audio ? kMaxAudioEventEntries : kMaxVideoEventEntries),
+ stats_subscriber_(
+ is_audio ? AUDIO_EVENT : VIDEO_EVENT,
+ cast_environment->Clock(), offset_estimator) {
+ cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_);
+ cast_environment_->Logging()->AddRawEventSubscriber(&stats_subscriber_);
+}
+
+RawEventSubscriberBundleForStream::~RawEventSubscriberBundleForStream() {
+ cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_);
+ cast_environment_->Logging()->RemoveRawEventSubscriber(&stats_subscriber_);
+}
+
+EncodingEventSubscriber*
+RawEventSubscriberBundleForStream::GetEncodingEventSubscriber() {
+ return &event_subscriber_;
+}
+
+StatsEventSubscriber*
+RawEventSubscriberBundleForStream::GetStatsEventSubscriber() {
+ return &stats_subscriber_;
+}
+
+RawEventSubscriberBundle::RawEventSubscriberBundle(
+ const scoped_refptr<CastEnvironment>& cast_environment)
+ : cast_environment_(cast_environment) {}
+
+RawEventSubscriberBundle::~RawEventSubscriberBundle() {
+ if (receiver_offset_estimator_.get()) {
+ cast_environment_->Logging()->RemoveRawEventSubscriber(
+ receiver_offset_estimator_.get());
+ }
+}
+
+void RawEventSubscriberBundle::AddEventSubscribers(bool is_audio) {
+ if (!receiver_offset_estimator_.get()) {
+ receiver_offset_estimator_.reset(
+ new ReceiverTimeOffsetEstimatorImpl);
+ cast_environment_->Logging()->AddRawEventSubscriber(
+ receiver_offset_estimator_.get());
+ }
+ SubscribersMapByStream::iterator it = subscribers_.find(is_audio);
+ if (it != subscribers_.end())
+ return;
+
+ subscribers_.insert(std::make_pair(
+ is_audio,
+ make_linked_ptr(new RawEventSubscriberBundleForStream(
+ cast_environment_, is_audio, receiver_offset_estimator_.get()))));
+}
+
+void RawEventSubscriberBundle::RemoveEventSubscribers(bool is_audio) {
+ SubscribersMapByStream::iterator it = subscribers_.find(is_audio);
+ if (it == subscribers_.end())
+ return;
+
+ subscribers_.erase(it);
+ if (subscribers_.empty()) {
+ cast_environment_->Logging()->RemoveRawEventSubscriber(
+ receiver_offset_estimator_.get());
+ receiver_offset_estimator_.reset();
+ }
+}
+
+EncodingEventSubscriber*
+RawEventSubscriberBundle::GetEncodingEventSubscriber(bool is_audio) {
+ SubscribersMapByStream::iterator it = subscribers_.find(is_audio);
+ return it == subscribers_.end() ?
+ NULL : it->second->GetEncodingEventSubscriber();
+}
+
+StatsEventSubscriber*
+RawEventSubscriberBundle::GetStatsEventSubscriber(bool is_audio) {
+ SubscribersMapByStream::iterator it = subscribers_.find(is_audio);
+ return it == subscribers_.end() ?
+ NULL : it->second->GetStatsEventSubscriber();
+}
+
+} // namespace cast
+} // namespace media
diff --git a/media/cast/logging/raw_event_subscriber_bundle.h b/media/cast/logging/raw_event_subscriber_bundle.h
new file mode 100644
index 0000000..58ab21e
--- /dev/null
+++ b/media/cast/logging/raw_event_subscriber_bundle.h
@@ -0,0 +1,84 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef MEDIA_CAST_LOGGING_RAW_EVENT_SUBSCRIBER_BUNDLE_H_
+#define MEDIA_CAST_LOGGING_RAW_EVENT_SUBSCRIBER_BUNDLE_H_
+
+#include "base/macros.h"
+#include "base/memory/ref_counted.h"
+#include "media/cast/logging/encoding_event_subscriber.h"
+#include "media/cast/logging/stats_event_subscriber.h"
+
+namespace media {
+namespace cast {
+
+class CastEnvironment;
+class ReceiverTimeOffsetEstimator;
+
+// Allow 9MB for serialized video / audio event logs.
+const int kMaxSerializedBytes = 9000000;
+
+// Assume serialized log data for each frame will take up to 150 bytes.
+const int kMaxVideoEventEntries = kMaxSerializedBytes / 150;
+
+// Assume serialized log data for each frame will take up to 75 bytes.
+const int kMaxAudioEventEntries = kMaxSerializedBytes / 75;
+
+// A bundle for raw event subscribers for a single stream.
+// It contains an EncodingEventSubscriber and a StatsSubscriber.
+class RawEventSubscriberBundleForStream {
+ public:
+ RawEventSubscriberBundleForStream(
+ const scoped_refptr<CastEnvironment>& cast_environment,
+ bool is_audio,
+ ReceiverTimeOffsetEstimator* offset_estimator);
+ ~RawEventSubscriberBundleForStream();
+
+ EncodingEventSubscriber* GetEncodingEventSubscriber();
+ StatsEventSubscriber* GetStatsEventSubscriber();
+
+ private:
+ const scoped_refptr<CastEnvironment> cast_environment_;
+ EncodingEventSubscriber event_subscriber_;
+ StatsEventSubscriber stats_subscriber_;
+
+ DISALLOW_COPY_AND_ASSIGN(RawEventSubscriberBundleForStream);
+};
+
+// A bundle of subscribers for all streams. An instance of this object
+// is associated with a CastEnvironment.
+// This class can be used for managing event subscribers
+// in a session where they could be multiple streams (i.e. CastSessionDelegate).
+// It also contains a ReceiverTimeOffsetEstimator that is shared by subscribers
+// of different streams.
+class RawEventSubscriberBundle {
+ public:
+ explicit RawEventSubscriberBundle(
+ const scoped_refptr<CastEnvironment>& cast_environment);
+ ~RawEventSubscriberBundle();
+
+ void AddEventSubscribers(bool is_audio);
+ void RemoveEventSubscribers(bool is_audio);
+ EncodingEventSubscriber* GetEncodingEventSubscriber(
+ bool is_audio);
+ StatsEventSubscriber* GetStatsEventSubscriber(bool is_audio);
+
+ private:
+ // Map from (is_audio) -> RawEventSubscriberBundleForStream.
+ // TODO(imcheng): This works because we only have 1 audio and 1 video stream.
+ // This needs to scale better.
+ typedef std::map<bool, linked_ptr<RawEventSubscriberBundleForStream> >
+ SubscribersMapByStream;
+ const scoped_refptr<CastEnvironment> cast_environment_;
+ SubscribersMapByStream subscribers_;
+ scoped_ptr<ReceiverTimeOffsetEstimator> receiver_offset_estimator_;
+
+ DISALLOW_COPY_AND_ASSIGN(RawEventSubscriberBundle);
+};
+
+} // namespace cast
+} // namespace media
+
+#endif // MEDIA_CAST_LOGGING_RAW_EVENT_SUBSCRIBER_BUNDLE_H_
+
diff --git a/media/cast/logging/receiver_time_offset_estimator.h b/media/cast/logging/receiver_time_offset_estimator.h
new file mode 100644
index 0000000..5880a8d
--- /dev/null
+++ b/media/cast/logging/receiver_time_offset_estimator.h
@@ -0,0 +1,39 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef MEDIA_CAST_LOGGING_RECEIVER_TIME_OFFSET_ESTIMATOR_H_
+#define MEDIA_CAST_LOGGING_RECEIVER_TIME_OFFSET_ESTIMATOR_H_
+
+#include "base/time/time.h"
+#include "media/cast/logging/raw_event_subscriber.h"
+
+namespace media {
+namespace cast {
+
+// Estimates receiver time offset based on raw events received.
+// In most cases, the sender and receiver run on different time lines.
+// In order to convert receiver time back to sender time (or vice versa)
+// a certain time offset has to be applied.
+// An implementation of this interface listens to raw events to figure out
+// the bounds for the offset value (assuming the true offset value is constant
+// over the lifetime of a cast session).
+// The offset values provided here should be used as follows:
+// - Convert from sender to receiver time: add offset value to sender timestamp.
+// - Convert from receiver to sender time: subtract offset value from receiver
+// timestamp.
+class ReceiverTimeOffsetEstimator : public RawEventSubscriber {
+ public:
+ virtual ~ReceiverTimeOffsetEstimator() {}
+
+ // If bounds are known, assigns |lower_bound| and |upper_bound| with the
+ // lower bound and upper bound for the offset value, respectively.
+ // Returns true if bounds are known.
+ virtual bool GetReceiverOffsetBounds(base::TimeDelta* lower_bound,
+ base::TimeDelta* upper_bound) = 0;
+};
+
+} // namespace cast
+} // namespace media
+
+#endif // MEDIA_CAST_LOGGING_RECEIVER_TIME_OFFSET_ESTIMATOR_H_
diff --git a/media/cast/logging/receiver_time_offset_estimator_impl.cc b/media/cast/logging/receiver_time_offset_estimator_impl.cc
new file mode 100644
index 0000000..897c7e1
--- /dev/null
+++ b/media/cast/logging/receiver_time_offset_estimator_impl.cc
@@ -0,0 +1,125 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include <algorithm>
+#include <utility>
+
+#include "base/logging.h"
+#include "media/cast/logging/receiver_time_offset_estimator_impl.h"
+
+namespace media {
+namespace cast {
+
+// This should be large enough so that we can collect all 3 events before
+// the entry gets removed from the map.
+const size_t kMaxEventTimesMapSize = 100;
+
+ReceiverTimeOffsetEstimatorImpl::ReceiverTimeOffsetEstimatorImpl()
+ : bounded_(false) {}
+
+ReceiverTimeOffsetEstimatorImpl::~ReceiverTimeOffsetEstimatorImpl() {
+ DCHECK(thread_checker_.CalledOnValidThread());
+}
+
+void ReceiverTimeOffsetEstimatorImpl::OnReceiveFrameEvent(
+ const FrameEvent& frame_event) {
+ DCHECK(thread_checker_.CalledOnValidThread());
+ CastLoggingEvent event = frame_event.type;
+ if (event != kVideoFrameEncoded && event != kVideoAckSent &&
+ event != kVideoAckReceived)
+ return;
+
+ EventTimesMap::iterator it = event_times_map_.find(frame_event.rtp_timestamp);
+ if (it == event_times_map_.end()) {
+ EventTimes event_times;
+ it = event_times_map_.insert(std::make_pair(frame_event.rtp_timestamp,
+ event_times)).first;
+ }
+ switch (event) {
+ case kVideoFrameEncoded:
+ // Encode is supposed to happen only once. If we see duplicate event,
+ // throw away the entry.
+ if (it->second.event_a_time.is_null()) {
+ it->second.event_a_time = frame_event.timestamp;
+ } else {
+ event_times_map_.erase(it);
+ return;
+ }
+ break;
+ case kVideoAckSent:
+ if (it->second.event_b_time.is_null()) {
+ it->second.event_b_time = frame_event.timestamp;
+ } else if (it->second.event_b_time != frame_event.timestamp) {
+ // Duplicate ack sent events are normal due to RTCP redundancy,
+ // but they must have the same event timestamp.
+ event_times_map_.erase(it);
+ return;
+ }
+ break;
+ case kVideoAckReceived:
+ // If there are duplicate ack received events, pick the one with the
+ // smallest event timestamp so we can get a better bound.
+ if (it->second.event_c_time.is_null()) {
+ it->second.event_c_time = frame_event.timestamp;
+ } else {
+ it->second.event_c_time =
+ std::min(frame_event.timestamp, it->second.event_c_time);
+ }
+ break;
+ default:
+ NOTREACHED();
+ }
+
+ if (!it->second.event_a_time.is_null() &&
+ !it->second.event_b_time.is_null() &&
+ !it->second.event_c_time.is_null()) {
+ UpdateOffsetBounds(it->second);
+ event_times_map_.erase(it);
+ }
+
+ // Keep the map size at most |kMaxEventTimesMapSize|.
+ if (event_times_map_.size() > kMaxEventTimesMapSize)
+ event_times_map_.erase(event_times_map_.begin());
+}
+
+bool ReceiverTimeOffsetEstimatorImpl::GetReceiverOffsetBounds(
+ base::TimeDelta* lower_bound,
+ base::TimeDelta* upper_bound) {
+ if (!bounded_)
+ return false;
+
+ *lower_bound = offset_lower_bound_;
+ *upper_bound = offset_upper_bound_;
+ return true;
+}
+
+void ReceiverTimeOffsetEstimatorImpl::OnReceivePacketEvent(
+ const PacketEvent& packet_event) {
+ // Not interested in packet events.
+ DCHECK(thread_checker_.CalledOnValidThread());
+}
+
+void ReceiverTimeOffsetEstimatorImpl::UpdateOffsetBounds(
+ const EventTimes& event) {
+ base::TimeDelta lower_bound = event.event_b_time - event.event_c_time;
+ base::TimeDelta upper_bound = event.event_b_time - event.event_a_time;
+
+ if (bounded_) {
+ lower_bound = std::max(lower_bound, offset_lower_bound_);
+ upper_bound = std::min(upper_bound, offset_upper_bound_);
+ }
+
+ if (lower_bound > upper_bound) {
+ VLOG(2) << "Got bogus offset bound values [" << lower_bound.InMilliseconds()
+ << ", " << upper_bound.InMilliseconds() << "].";
+ return;
+ }
+
+ offset_lower_bound_ = lower_bound;
+ offset_upper_bound_ = upper_bound;
+ bounded_ = true;
+}
+
+} // namespace cast
+} // namespace media
diff --git a/media/cast/logging/receiver_time_offset_estimator_impl.h b/media/cast/logging/receiver_time_offset_estimator_impl.h
new file mode 100644
index 0000000..0968bed
--- /dev/null
+++ b/media/cast/logging/receiver_time_offset_estimator_impl.h
@@ -0,0 +1,64 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef MEDIA_CAST_LOGGING_RECEIVER_TIME_OFFSET_ESTIMATOR_IMPL_H_
+#define MEDIA_CAST_LOGGING_RECEIVER_TIME_OFFSET_ESTIMATOR_IMPL_H_
+
+#include "base/time/time.h"
+#include "base/threading/thread_checker.h"
+#include "media/cast/logging/logging_defines.h"
+#include "media/cast/logging/receiver_time_offset_estimator.h"
+
+namespace media {
+namespace cast {
+
+// This implementation listens to three types of events:
+// 1. kVideoFrameEncoded (sender side)
+// 2. kVideoAckSent (receiver side)
+// 3. kVideoAckReceived (sender side)
+// There is a causal relationship between these events in that these events
+// must happen in order. This class obtains the lower and upper bounds for
+// the offset by taking the difference of timestamps (2) - (1) and (2) - (3),
+// respectively.
+// The bound will become better as the latency between the events decreases.
+class ReceiverTimeOffsetEstimatorImpl : public ReceiverTimeOffsetEstimator {
+ public:
+ ReceiverTimeOffsetEstimatorImpl();
+
+ virtual ~ReceiverTimeOffsetEstimatorImpl();
+
+ // RawEventSubscriber implementations.
+ virtual void OnReceiveFrameEvent(const FrameEvent& frame_event) OVERRIDE;
+ virtual void OnReceivePacketEvent(const PacketEvent& packet_event) OVERRIDE;
+
+ // ReceiverTimeOffsetEstimator implementation.
+ virtual bool GetReceiverOffsetBounds(base::TimeDelta* lower_bound,
+ base::TimeDelta* upper_bound) OVERRIDE;
+
+ private:
+ struct EventTimes {
+ base::TimeTicks event_a_time;
+ base::TimeTicks event_b_time;
+ base::TimeTicks event_c_time;
+ };
+
+ typedef std::map<RtpTimestamp, EventTimes> EventTimesMap;
+
+ void UpdateOffsetBounds(const EventTimes& event);
+
+ // Fixed size storage to store event times for recent frames.
+ EventTimesMap event_times_map_;
+
+ bool bounded_;
+ base::TimeDelta offset_lower_bound_;
+ base::TimeDelta offset_upper_bound_;
+
+ base::ThreadChecker thread_checker_;
+ DISALLOW_COPY_AND_ASSIGN(ReceiverTimeOffsetEstimatorImpl);
+};
+
+} // namespace cast
+} // namespace media
+
+#endif // MEDIA_CAST_LOGGING_RECEIVER_TIME_OFFSET_ESTIMATOR_IMPL_H_
diff --git a/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc b/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc
new file mode 100644
index 0000000..36985b6
--- /dev/null
+++ b/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc
@@ -0,0 +1,234 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "base/memory/ref_counted.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/test/simple_test_tick_clock.h"
+#include "base/time/tick_clock.h"
+#include "media/cast/cast_environment.h"
+#include "media/cast/logging/logging_defines.h"
+#include "media/cast/logging/receiver_time_offset_estimator_impl.h"
+#include "media/cast/test/fake_single_thread_task_runner.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace media {
+namespace cast {
+
+class ReceiverTimeOffsetEstimatorImplTest : public ::testing::Test {
+ protected:
+ ReceiverTimeOffsetEstimatorImplTest()
+ : sender_clock_(new base::SimpleTestTickClock()),
+ task_runner_(new test::FakeSingleThreadTaskRunner(sender_clock_)),
+ cast_environment_(new CastEnvironment(
+ scoped_ptr<base::TickClock>(sender_clock_).Pass(),
+ task_runner_,
+ task_runner_,
+ task_runner_)) {
+ cast_environment_->Logging()->AddRawEventSubscriber(&estimator_);
+ }
+
+ virtual ~ReceiverTimeOffsetEstimatorImplTest() {
+ cast_environment_->Logging()->RemoveRawEventSubscriber(&estimator_);
+ }
+
+ void AdvanceClocks(base::TimeDelta time) {
+ sender_clock_->Advance(time);
+ receiver_clock_.Advance(time);
+ }
+
+ base::SimpleTestTickClock* sender_clock_; // Owned by CastEnvironment.
+ scoped_refptr<test::FakeSingleThreadTaskRunner> task_runner_;
+ scoped_refptr<CastEnvironment> cast_environment_;
+ base::SimpleTestTickClock receiver_clock_;
+ ReceiverTimeOffsetEstimatorImpl estimator_;
+};
+
+// Suppose the true offset is 100ms.
+// Event A occurred at sender time 20ms.
+// Event B occurred at receiver time 130ms. (sender time 30ms)
+// Event C occurred at sender time 60ms.
+// Then the bound after all 3 events have arrived is [130-60=70, 130-20=110].
+TEST_F(ReceiverTimeOffsetEstimatorImplTest, EstimateOffset) {
+ int64 true_offset_ms = 100;
+ receiver_clock_.Advance(base::TimeDelta::FromMilliseconds(true_offset_ms));
+
+ base::TimeDelta lower_bound;
+ base::TimeDelta upper_bound;
+
+ EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
+
+ RtpTimestamp rtp_timestamp = 0;
+ uint32 frame_id = 0;
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(20));
+
+ cast_environment_->Logging()->InsertEncodedFrameEvent(
+ sender_clock_->NowTicks(),
+ kVideoFrameEncoded,
+ rtp_timestamp,
+ frame_id,
+ 1234,
+ true,
+ 5678);
+
+ EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(10));
+ cast_environment_->Logging()->InsertFrameEvent(
+ receiver_clock_.NowTicks(), kVideoAckSent, rtp_timestamp, frame_id);
+
+ EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(30));
+ cast_environment_->Logging()->InsertFrameEvent(
+ sender_clock_->NowTicks(), kVideoAckReceived, rtp_timestamp, frame_id);
+
+ EXPECT_TRUE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
+
+ int64 lower_bound_ms = lower_bound.InMilliseconds();
+ int64 upper_bound_ms = upper_bound.InMilliseconds();
+ EXPECT_EQ(70, lower_bound_ms);
+ EXPECT_EQ(110, upper_bound_ms);
+ EXPECT_GE(true_offset_ms, lower_bound_ms);
+ EXPECT_LE(true_offset_ms, upper_bound_ms);
+}
+
+// Same scenario as above, but event C arrives before event B. It doens't mean
+// event C occurred before event B.
+TEST_F(ReceiverTimeOffsetEstimatorImplTest, EventCArrivesBeforeEventB) {
+ int64 true_offset_ms = 100;
+ receiver_clock_.Advance(base::TimeDelta::FromMilliseconds(true_offset_ms));
+
+ base::TimeDelta lower_bound;
+ base::TimeDelta upper_bound;
+
+ EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
+
+ RtpTimestamp rtp_timestamp = 0;
+ uint32 frame_id = 0;
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(20));
+
+ cast_environment_->Logging()->InsertEncodedFrameEvent(
+ sender_clock_->NowTicks(),
+ kVideoFrameEncoded,
+ rtp_timestamp,
+ frame_id,
+ 1234,
+ true,
+ 5678);
+
+ EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(10));
+ base::TimeTicks event_b_time = receiver_clock_.NowTicks();
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(30));
+ base::TimeTicks event_c_time = sender_clock_->NowTicks();
+
+ cast_environment_->Logging()->InsertFrameEvent(
+ event_c_time, kVideoAckReceived, rtp_timestamp, frame_id);
+
+ EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
+
+ cast_environment_->Logging()->InsertFrameEvent(
+ event_b_time, kVideoAckSent, rtp_timestamp, frame_id);
+
+ EXPECT_TRUE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
+
+ int64 lower_bound_ms = lower_bound.InMilliseconds();
+ int64 upper_bound_ms = upper_bound.InMilliseconds();
+ EXPECT_EQ(70, lower_bound_ms);
+ EXPECT_EQ(110, upper_bound_ms);
+ EXPECT_GE(true_offset_ms, lower_bound_ms);
+ EXPECT_LE(true_offset_ms, upper_bound_ms);
+}
+
+TEST_F(ReceiverTimeOffsetEstimatorImplTest, MultipleIterations) {
+ int64 true_offset_ms = 100;
+ receiver_clock_.Advance(base::TimeDelta::FromMilliseconds(true_offset_ms));
+
+ base::TimeDelta lower_bound;
+ base::TimeDelta upper_bound;
+
+ RtpTimestamp rtp_timestamp_a = 0;
+ int frame_id_a = 0;
+ RtpTimestamp rtp_timestamp_b = 90;
+ int frame_id_b = 1;
+ RtpTimestamp rtp_timestamp_c = 180;
+ int frame_id_c = 2;
+
+ // Frame 1 times: [20, 30+100, 60]
+ // Frame 2 times: [30, 50+100, 55]
+ // Frame 3 times: [77, 80+100, 110]
+ // Bound should end up at [95, 103]
+ // Events times in chronological order: 20, 30 x2, 50, 55, 60, 77, 80, 110
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(20));
+ cast_environment_->Logging()->InsertEncodedFrameEvent(
+ sender_clock_->NowTicks(),
+ kVideoFrameEncoded,
+ rtp_timestamp_a,
+ frame_id_a,
+ 1234,
+ true,
+ 5678);
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(10));
+ cast_environment_->Logging()->InsertEncodedFrameEvent(
+ sender_clock_->NowTicks(),
+ kVideoFrameEncoded,
+ rtp_timestamp_b,
+ frame_id_b,
+ 1234,
+ true,
+ 5678);
+ cast_environment_->Logging()->InsertFrameEvent(
+ receiver_clock_.NowTicks(), kVideoAckSent, rtp_timestamp_a, frame_id_a);
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(20));
+ cast_environment_->Logging()->InsertFrameEvent(
+ receiver_clock_.NowTicks(), kVideoAckSent, rtp_timestamp_b, frame_id_b);
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(5));
+ cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
+ kVideoAckReceived,
+ rtp_timestamp_b,
+ frame_id_b);
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(5));
+ cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
+ kVideoAckReceived,
+ rtp_timestamp_a,
+ frame_id_a);
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(17));
+ cast_environment_->Logging()->InsertEncodedFrameEvent(
+ sender_clock_->NowTicks(),
+ kVideoFrameEncoded,
+ rtp_timestamp_c,
+ frame_id_c,
+ 1234,
+ true,
+ 5678);
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(3));
+ cast_environment_->Logging()->InsertFrameEvent(
+ receiver_clock_.NowTicks(), kVideoAckSent, rtp_timestamp_c, frame_id_c);
+
+ AdvanceClocks(base::TimeDelta::FromMilliseconds(30));
+ cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
+ kVideoAckReceived,
+ rtp_timestamp_c,
+ frame_id_c);
+
+ EXPECT_TRUE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound));
+ int64 lower_bound_ms = lower_bound.InMilliseconds();
+ int64 upper_bound_ms = upper_bound.InMilliseconds();
+ EXPECT_EQ(95, lower_bound_ms);
+ EXPECT_EQ(103, upper_bound_ms);
+ EXPECT_GE(true_offset_ms, lower_bound_ms);
+ EXPECT_LE(true_offset_ms, upper_bound_ms);
+}
+
+} // namespace cast
+} // namespace media
diff --git a/media/cast/logging/stats_event_subscriber.cc b/media/cast/logging/stats_event_subscriber.cc
index 2b40c99..008add1 100644
--- a/media/cast/logging/stats_event_subscriber.cc
+++ b/media/cast/logging/stats_event_subscriber.cc
@@ -5,12 +5,83 @@
#include "media/cast/logging/stats_event_subscriber.h"
#include "base/logging.h"
+#include "base/values.h"
+
+#define STAT_ENUM_TO_STRING(enum) \
+ case enum: \
+ return #enum
namespace media {
namespace cast {
-StatsEventSubscriber::StatsEventSubscriber(EventMediaType event_media_type)
- : event_media_type_(event_media_type) {}
+namespace {
+
+using media::cast::CastLoggingEvent;
+using media::cast::EventMediaType;
+
+const size_t kMaxFrameEventTimeMapSize = 100;
+const size_t kMaxPacketEventTimeMapSize = 1000;
+
+CastLoggingEvent GetCapturedEvent(EventMediaType media_type) {
+ return media_type == AUDIO_EVENT ? kAudioFrameCaptured : kVideoFrameCaptured;
+}
+
+CastLoggingEvent GetEncodedEvent(EventMediaType media_type) {
+ return media_type == AUDIO_EVENT ? kAudioFrameEncoded : kVideoFrameEncoded;
+}
+
+CastLoggingEvent GetDecodedEvent(EventMediaType media_type) {
+ return media_type == AUDIO_EVENT ? kAudioFrameDecoded : kVideoFrameDecoded;
+}
+
+CastLoggingEvent GetPlayoutEvent(EventMediaType media_type) {
+ return media_type == AUDIO_EVENT ? kAudioPlayoutDelay : kVideoRenderDelay;
+}
+
+CastLoggingEvent GetPacketSentEvent(EventMediaType media_type) {
+ return media_type == AUDIO_EVENT ? kAudioPacketSentToNetwork :
+ kVideoPacketSentToNetwork;
+}
+
+CastLoggingEvent GetPacketReceivedEvent(EventMediaType media_type) {
+ return media_type == AUDIO_EVENT ? kAudioPacketReceived :
+ kVideoPacketReceived;
+}
+
+CastLoggingEvent GetPacketRetransmittedEvent(EventMediaType media_type) {
+ return media_type == AUDIO_EVENT ? kAudioPacketRetransmitted :
+ kVideoPacketRetransmitted;
+}
+
+bool IsReceiverEvent(CastLoggingEvent event) {
+ return event == kAudioFrameDecoded
+ || event == kVideoFrameDecoded
+ || event == kAudioPlayoutDelay
+ || event == kVideoRenderDelay
+ || event == kAudioAckSent
+ || event == kVideoAckSent
+ || event == kAudioPacketReceived
+ || event == kVideoPacketReceived
+ || event == kDuplicateAudioPacketReceived
+ || event == kDuplicateVideoPacketReceived;
+}
+
+} // namespace
+
+StatsEventSubscriber::StatsEventSubscriber(
+ EventMediaType event_media_type,
+ base::TickClock* clock,
+ ReceiverTimeOffsetEstimator* offset_estimator)
+ : event_media_type_(event_media_type),
+ clock_(clock),
+ offset_estimator_(offset_estimator),
+ network_latency_datapoints_(0),
+ e2e_latency_datapoints_(0) {
+ DCHECK(event_media_type == AUDIO_EVENT || event_media_type == VIDEO_EVENT);
+ base::TimeTicks now = clock_->NowTicks();
+ start_time_ = now;
+ last_response_received_time_ = base::TimeTicks();
+}
StatsEventSubscriber::~StatsEventSubscriber() {
DCHECK(thread_checker_.CalledOnValidThread());
@@ -26,24 +97,24 @@ void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
FrameStatsMap::iterator it = frame_stats_.find(type);
if (it == frame_stats_.end()) {
FrameLogStats stats;
- stats.first_event_time = frame_event.timestamp;
- stats.last_event_time = frame_event.timestamp;
stats.event_counter = 1;
stats.sum_size = frame_event.size;
- stats.min_delay = frame_event.delay_delta;
- stats.max_delay = frame_event.delay_delta;
stats.sum_delay = frame_event.delay_delta;
frame_stats_.insert(std::make_pair(type, stats));
} else {
++(it->second.event_counter);
- it->second.last_event_time = frame_event.timestamp;
it->second.sum_size += frame_event.size;
it->second.sum_delay += frame_event.delay_delta;
- if (frame_event.delay_delta > it->second.max_delay)
- it->second.max_delay = frame_event.delay_delta;
- if (frame_event.delay_delta < it->second.min_delay)
- it->second.min_delay = frame_event.delay_delta;
}
+
+ if (type == GetCapturedEvent(event_media_type_)) {
+ RecordFrameCapturedTime(frame_event);
+ } else if (type == GetPlayoutEvent(event_media_type_)) {
+ RecordE2ELatency(frame_event);
+ }
+
+ if (IsReceiverEvent(type))
+ UpdateLastResponseTime(frame_event.timestamp);
}
void StatsEventSubscriber::OnReceivePacketEvent(
@@ -57,33 +128,42 @@ void StatsEventSubscriber::OnReceivePacketEvent(
PacketStatsMap::iterator it = packet_stats_.find(type);
if (it == packet_stats_.end()) {
PacketLogStats stats;
- stats.first_event_time = packet_event.timestamp;
- stats.last_event_time = packet_event.timestamp;
stats.event_counter = 1;
stats.sum_size = packet_event.size;
packet_stats_.insert(std::make_pair(type, stats));
} else {
- it->second.last_event_time = packet_event.timestamp;
++(it->second.event_counter);
it->second.sum_size += packet_event.size;
}
-}
-void StatsEventSubscriber::GetFrameStats(FrameStatsMap* frame_stats_map) const {
- DCHECK(thread_checker_.CalledOnValidThread());
- DCHECK(frame_stats_map);
+ if (type == GetPacketSentEvent(event_media_type_) ||
+ type == GetPacketReceivedEvent(event_media_type_)) {
+ RecordNetworkLatency(packet_event);
+ } else if (type == GetPacketRetransmittedEvent(event_media_type_)) {
+ // We only measure network latency using packets that doesn't have to be
+ // retransmitted as there is precisely one sent-receive timestamp pairs.
+ ErasePacketSentTime(packet_event);
+ }
- frame_stats_map->clear();
- frame_stats_map->insert(frame_stats_.begin(), frame_stats_.end());
+ if (IsReceiverEvent(type))
+ UpdateLastResponseTime(packet_event.timestamp);
}
-void StatsEventSubscriber::GetPacketStats(
- PacketStatsMap* packet_stats_map) const {
- DCHECK(thread_checker_.CalledOnValidThread());
- DCHECK(packet_stats_map);
+scoped_ptr<base::DictionaryValue> StatsEventSubscriber::GetStats() const {
+ StatsMap stats_map;
+ GetStatsInternal(&stats_map);
+ scoped_ptr<base::DictionaryValue> ret(new base::DictionaryValue);
- packet_stats_map->clear();
- packet_stats_map->insert(packet_stats_.begin(), packet_stats_.end());
+ scoped_ptr<base::DictionaryValue> stats(new base::DictionaryValue);
+ for (StatsMap::const_iterator it = stats_map.begin(); it != stats_map.end();
+ ++it) {
+ stats->SetDouble(CastStatToString(it->first), it->second);
+ }
+
+ ret->Set(event_media_type_ == AUDIO_EVENT ? "audio" : "video",
+ stats.release());
+
+ return ret.Pass();
}
void StatsEventSubscriber::Reset() {
@@ -91,7 +171,272 @@ void StatsEventSubscriber::Reset() {
frame_stats_.clear();
packet_stats_.clear();
+ total_network_latency_ = base::TimeDelta();
+ network_latency_datapoints_ = 0;
+ total_e2e_latency_ = base::TimeDelta();
+ e2e_latency_datapoints_ = 0;
+ frame_captured_times_.clear();
+ packet_sent_times_.clear();
+ start_time_ = clock_->NowTicks();
+ last_response_received_time_ = base::TimeTicks();
+}
+
+// static
+const char* StatsEventSubscriber::CastStatToString(CastStat stat) {
+ switch (stat) {
+ STAT_ENUM_TO_STRING(CAPTURE_FPS);
+ STAT_ENUM_TO_STRING(ENCODE_FPS);
+ STAT_ENUM_TO_STRING(DECODE_FPS);
+ STAT_ENUM_TO_STRING(AVG_ENCODE_TIME_MS);
+ STAT_ENUM_TO_STRING(AVG_PLAYOUT_DELAY_MS);
+ STAT_ENUM_TO_STRING(AVG_NETWORK_LATENCY_MS);
+ STAT_ENUM_TO_STRING(AVG_E2E_LATENCY_MS);
+ STAT_ENUM_TO_STRING(ENCODE_KBPS);
+ STAT_ENUM_TO_STRING(TRANSMISSION_KBPS);
+ STAT_ENUM_TO_STRING(RETRANSMISSION_KBPS);
+ STAT_ENUM_TO_STRING(PACKET_LOSS_FRACTION);
+ STAT_ENUM_TO_STRING(MS_SINCE_LAST_RECEIVER_RESPONSE);
+ }
+ NOTREACHED();
+ return "";
+}
+
+void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
+ DCHECK(thread_checker_.CalledOnValidThread());
+
+ stats_map->clear();
+
+ base::TimeTicks end_time = clock_->NowTicks();
+
+ PopulateFpsStat(
+ end_time, GetCapturedEvent(event_media_type_), CAPTURE_FPS, stats_map);
+ PopulateFpsStat(
+ end_time, GetEncodedEvent(event_media_type_), ENCODE_FPS, stats_map);
+ PopulateFpsStat(
+ end_time, GetDecodedEvent(event_media_type_), DECODE_FPS, stats_map);
+ PopulatePlayoutDelayStat(stats_map);
+ PopulateFrameBitrateStat(end_time, stats_map);
+ PopulatePacketBitrateStat(end_time,
+ GetPacketSentEvent(event_media_type_),
+ TRANSMISSION_KBPS,
+ stats_map);
+ PopulatePacketBitrateStat(end_time,
+ GetPacketRetransmittedEvent(event_media_type_),
+ RETRANSMISSION_KBPS,
+ stats_map);
+ PopulatePacketLossPercentageStat(stats_map);
+
+ if (network_latency_datapoints_ > 0) {
+ double avg_network_latency_ms =
+ total_network_latency_.InMillisecondsF() /
+ network_latency_datapoints_;
+ stats_map->insert(
+ std::make_pair(AVG_NETWORK_LATENCY_MS, avg_network_latency_ms));
+ }
+
+ if (e2e_latency_datapoints_ > 0) {
+ double avg_e2e_latency_ms =
+ total_e2e_latency_.InMillisecondsF() / e2e_latency_datapoints_;
+ stats_map->insert(std::make_pair(AVG_E2E_LATENCY_MS, avg_e2e_latency_ms));
+ }
+
+ if (!last_response_received_time_.is_null()) {
+ stats_map->insert(
+ std::make_pair(MS_SINCE_LAST_RECEIVER_RESPONSE,
+ (end_time - last_response_received_time_).InMillisecondsF()));
+ }
+}
+
+bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
+ base::TimeDelta receiver_offset_lower_bound;
+ base::TimeDelta receiver_offset_upper_bound;
+ if (!offset_estimator_->GetReceiverOffsetBounds(
+ &receiver_offset_lower_bound, &receiver_offset_upper_bound)) {
+ return false;
+ }
+
+ *offset = (receiver_offset_lower_bound + receiver_offset_upper_bound) / 2;
+ return true;
+}
+
+void StatsEventSubscriber::RecordFrameCapturedTime(
+ const FrameEvent& frame_event) {
+ frame_captured_times_.insert(
+ std::make_pair(frame_event.rtp_timestamp, frame_event.timestamp));
+ if (frame_captured_times_.size() > kMaxFrameEventTimeMapSize)
+ frame_captured_times_.erase(frame_captured_times_.begin());
+}
+
+void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
+ base::TimeDelta receiver_offset;
+ if (!GetReceiverOffset(&receiver_offset))
+ return;
+
+ FrameEventTimeMap::iterator it =
+ frame_captured_times_.find(frame_event.rtp_timestamp);
+ if (it == frame_captured_times_.end())
+ return;
+
+ // Playout time is event time + playout delay.
+ base::TimeTicks playout_time =
+ frame_event.timestamp + frame_event.delay_delta - receiver_offset;
+ total_e2e_latency_ += playout_time - it->second;
+ e2e_latency_datapoints_++;
+}
+
+void StatsEventSubscriber::UpdateLastResponseTime(
+ base::TimeTicks receiver_time) {
+ base::TimeDelta receiver_offset;
+ if (!GetReceiverOffset(&receiver_offset))
+ return;
+ base::TimeTicks sender_time = receiver_time - receiver_offset;
+ last_response_received_time_ = sender_time;
+}
+
+void StatsEventSubscriber::ErasePacketSentTime(
+ const PacketEvent& packet_event) {
+ std::pair<RtpTimestamp, uint16> key(
+ std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
+ packet_sent_times_.erase(key);
+}
+
+void StatsEventSubscriber::RecordNetworkLatency(
+ const PacketEvent& packet_event) {
+ base::TimeDelta receiver_offset;
+ if (!GetReceiverOffset(&receiver_offset))
+ return;
+
+ std::pair<RtpTimestamp, uint16> key(
+ std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
+ PacketEventTimeMap::iterator it = packet_sent_times_.find(key);
+ if (it == packet_sent_times_.end()) {
+ std::pair<RtpTimestamp, uint16> key(
+ std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
+ std::pair<base::TimeTicks, CastLoggingEvent> value =
+ std::make_pair(packet_event.timestamp, packet_event.type);
+ packet_sent_times_.insert(std::make_pair(key, value));
+ if (packet_sent_times_.size() > kMaxPacketEventTimeMapSize)
+ packet_sent_times_.erase(packet_sent_times_.begin());
+ } else {
+ std::pair<base::TimeTicks, CastLoggingEvent> value = it->second;
+ CastLoggingEvent recorded_type = value.second;
+ bool match = false;
+ base::TimeTicks packet_sent_time;
+ base::TimeTicks packet_received_time;
+ if (recorded_type == GetPacketSentEvent(event_media_type_) &&
+ packet_event.type == GetPacketReceivedEvent(event_media_type_)) {
+ packet_sent_time = value.first;
+ packet_received_time = packet_event.timestamp;
+ match = true;
+ } else if (recorded_type == GetPacketReceivedEvent(event_media_type_) &&
+ packet_event.type == GetPacketSentEvent(event_media_type_)) {
+ packet_sent_time = packet_event.timestamp;
+ packet_received_time = value.first;
+ match = true;
+ }
+ if (match) {
+ // Subtract by offset.
+ packet_received_time -= receiver_offset;
+
+ total_network_latency_ += packet_received_time - packet_sent_time;
+ network_latency_datapoints_++;
+ packet_sent_times_.erase(it);
+ }
+ }
+}
+
+void StatsEventSubscriber::PopulateFpsStat(base::TimeTicks end_time,
+ CastLoggingEvent event,
+ CastStat stat,
+ StatsMap* stats_map) const {
+ FrameStatsMap::const_iterator it = frame_stats_.find(event);
+ if (it != frame_stats_.end()) {
+ double fps = 0.0;
+ base::TimeDelta duration = (end_time - start_time_);
+ int count = it->second.event_counter;
+ if (duration > base::TimeDelta())
+ fps = count / duration.InSecondsF();
+ stats_map->insert(std::make_pair(stat, fps));
+ }
+}
+
+void StatsEventSubscriber::PopulatePlayoutDelayStat(StatsMap* stats_map) const {
+ CastLoggingEvent event = GetPlayoutEvent(event_media_type_);
+ FrameStatsMap::const_iterator it = frame_stats_.find(event);
+ if (it != frame_stats_.end()) {
+ double avg_delay_ms = 0.0;
+ base::TimeDelta sum_delay = it->second.sum_delay;
+ int count = it->second.event_counter;
+ if (count != 0)
+ avg_delay_ms = sum_delay.InMillisecondsF() / count;
+ stats_map->insert(std::make_pair(AVG_PLAYOUT_DELAY_MS, avg_delay_ms));
+ }
}
+void StatsEventSubscriber::PopulateFrameBitrateStat(base::TimeTicks end_time,
+ StatsMap* stats_map) const {
+ CastLoggingEvent event = GetEncodedEvent(event_media_type_);
+ FrameStatsMap::const_iterator it = frame_stats_.find(event);
+ if (it != frame_stats_.end()) {
+ double kbps = 0.0;
+ base::TimeDelta duration = end_time - start_time_;
+ if (duration > base::TimeDelta()) {
+ kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
+ }
+
+ stats_map->insert(std::make_pair(ENCODE_KBPS, kbps));
+ }
+}
+
+void StatsEventSubscriber::PopulatePacketBitrateStat(
+ base::TimeTicks end_time,
+ CastLoggingEvent event,
+ CastStat stat,
+ StatsMap* stats_map) const {
+ PacketStatsMap::const_iterator it = packet_stats_.find(event);
+ if (it != packet_stats_.end()) {
+ double kbps = 0;
+ base::TimeDelta duration = end_time - start_time_;
+ if (duration > base::TimeDelta()) {
+ kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
+ }
+
+ stats_map->insert(std::make_pair(stat, kbps));
+ }
+}
+
+void StatsEventSubscriber::PopulatePacketLossPercentageStat(
+ StatsMap* stats_map) const {
+ // We assume that retransmission means that the packet's previous
+ // (re)transmission was lost.
+ // This means the percentage of packet loss is
+ // (# of retransmit events) / (# of transmit + retransmit events).
+ CastLoggingEvent packet_sent_event = GetPacketSentEvent(event_media_type_);
+ CastLoggingEvent packet_retransmitted_event =
+ GetPacketRetransmittedEvent(event_media_type_);
+ PacketStatsMap::const_iterator sent_it =
+ packet_stats_.find(packet_sent_event);
+ if (sent_it == packet_stats_.end())
+ return;
+ PacketStatsMap::const_iterator retransmitted_it =
+ packet_stats_.find(packet_retransmitted_event);
+ int sent_count = sent_it->second.event_counter;
+ int retransmitted_count = 0;
+ if (retransmitted_it != packet_stats_.end())
+ retransmitted_count = retransmitted_it->second.event_counter;
+ double packet_loss_fraction = static_cast<double>(retransmitted_count) /
+ (sent_count + retransmitted_count);
+ stats_map->insert(
+ std::make_pair(PACKET_LOSS_FRACTION, packet_loss_fraction));
+}
+
+StatsEventSubscriber::FrameLogStats::FrameLogStats()
+ : event_counter(0), sum_size(0) {}
+StatsEventSubscriber::FrameLogStats::~FrameLogStats() {}
+
+StatsEventSubscriber::PacketLogStats::PacketLogStats()
+ : event_counter(0), sum_size(0) {}
+StatsEventSubscriber::PacketLogStats::~PacketLogStats() {}
+
} // namespace cast
} // namespace media
diff --git a/media/cast/logging/stats_event_subscriber.h b/media/cast/logging/stats_event_subscriber.h
index 176ced8..4e198da 100644
--- a/media/cast/logging/stats_event_subscriber.h
+++ b/media/cast/logging/stats_event_subscriber.h
@@ -5,18 +5,30 @@
#ifndef MEDIA_CAST_LOGGING_STATS_EVENT_SUBSCRIBER_H_
#define MEDIA_CAST_LOGGING_STATS_EVENT_SUBSCRIBER_H_
+#include "base/gtest_prod_util.h"
+#include "base/memory/scoped_ptr.h"
#include "base/threading/thread_checker.h"
+#include "base/time/tick_clock.h"
#include "media/cast/logging/logging_defines.h"
#include "media/cast/logging/raw_event_subscriber.h"
+#include "media/cast/logging/receiver_time_offset_estimator.h"
+
+namespace base {
+class DictionaryValue;
+}
namespace media {
namespace cast {
+class StatsEventSubscriberTest;
+
// A RawEventSubscriber implementation that subscribes to events,
// and aggregates them into stats.
class StatsEventSubscriber : public RawEventSubscriber {
public:
- StatsEventSubscriber(EventMediaType media_type);
+ StatsEventSubscriber(EventMediaType event_media_type,
+ base::TickClock* clock,
+ ReceiverTimeOffsetEstimator* offset_estimator);
virtual ~StatsEventSubscriber();
@@ -24,19 +36,136 @@ class StatsEventSubscriber : public RawEventSubscriber {
virtual void OnReceiveFrameEvent(const FrameEvent& frame_event) OVERRIDE;
virtual void OnReceivePacketEvent(const PacketEvent& packet_event) OVERRIDE;
- // Assigns |frame_stats_map| with frame stats.
- void GetFrameStats(FrameStatsMap* frame_stats_map) const;
-
- // Assigns |packet_stats_map| with packet stats.
- void GetPacketStats(PacketStatsMap* packet_stats_map) const;
+ // Returns stats as a DictionaryValue. The dictionary contains one entry -
+ // "audio" or "video" pointing to an inner dictionary.
+ // The inner dictionary consists of string - double entries, where the string
+ // describes the name of the stat, and the double describes
+ // the value of the stat. See CastStat and StatsMap below.
+ scoped_ptr<base::DictionaryValue> GetStats() const;
- // Resets all stats maps in this object.
+ // Resets stats in this object.
void Reset();
private:
- EventMediaType event_media_type_;
+ friend class StatsEventSubscriberTest;
+ FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, EmptyStats);
+ FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, Capture);
+ FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, Encode);
+ FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, Decode);
+ FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, PlayoutDelay);
+ FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, E2ELatency);
+ FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, Packets);
+
+ // Generic statistics given the raw data. More specific data (e.g. frame rate
+ // and bit rate) can be computed given the basic metrics.
+ // Some of the metrics will only be set when applicable, e.g. delay and size.
+ struct FrameLogStats {
+ FrameLogStats();
+ ~FrameLogStats();
+ int event_counter;
+ size_t sum_size;
+ base::TimeDelta sum_delay;
+ };
+
+ struct PacketLogStats {
+ PacketLogStats();
+ ~PacketLogStats();
+ int event_counter;
+ size_t sum_size;
+ };
+
+ enum CastStat {
+ // Capture frame rate.
+ CAPTURE_FPS,
+ // Encode frame rate.
+ ENCODE_FPS,
+ // Decode frame rate.
+ DECODE_FPS,
+ // Average encode duration in milliseconds.
+ // TODO(imcheng): This stat is not populated yet because we do not have
+ // the time when encode started. Record it in kVideoFrameEncoded event.
+ AVG_ENCODE_TIME_MS,
+ // Average playout delay in milliseconds, with target delay already
+ // accounted for. Ideally, every frame should have a playout delay of 0.
+ AVG_PLAYOUT_DELAY_MS,
+ // Duration from when a packet is transmitted to when it is received.
+ // This measures latency from sender to receiver.
+ AVG_NETWORK_LATENCY_MS,
+ // Duration from when a frame is captured to when it should be played out.
+ AVG_E2E_LATENCY_MS,
+ // Encode bitrate in kbps.
+ ENCODE_KBPS,
+ // Packet transmission bitrate in kbps.
+ TRANSMISSION_KBPS,
+ // Packet retransmission bitrate in kbps.
+ RETRANSMISSION_KBPS,
+ // Fraction of packet loss.
+ PACKET_LOSS_FRACTION,
+ // Duration in milliseconds since last receiver response.
+ MS_SINCE_LAST_RECEIVER_RESPONSE
+ };
+
+ typedef std::map<CastStat, double> StatsMap;
+ typedef std::map<RtpTimestamp, base::TimeTicks> FrameEventTimeMap;
+ typedef std::map<
+ std::pair<RtpTimestamp, uint16>,
+ std::pair<base::TimeTicks, CastLoggingEvent> >
+ PacketEventTimeMap;
+ typedef std::map<CastLoggingEvent, FrameLogStats> FrameStatsMap;
+ typedef std::map<CastLoggingEvent, PacketLogStats> PacketStatsMap;
+
+ static const char* CastStatToString(CastStat stat);
+
+ // Assigns |stats_map| with stats data. Used for testing.
+ void GetStatsInternal(StatsMap* stats_map) const;
+
+ bool GetReceiverOffset(base::TimeDelta* offset);
+ void RecordFrameCapturedTime(const FrameEvent& frame_event);
+ void RecordE2ELatency(const FrameEvent& frame_event);
+ void RecordPacketSentTime(const PacketEvent& packet_event);
+ void ErasePacketSentTime(const PacketEvent& packet_event);
+ void RecordNetworkLatency(const PacketEvent& packet_event);
+ void UpdateLastResponseTime(base::TimeTicks receiver_time);
+
+ void PopulateFpsStat(base::TimeTicks now,
+ CastLoggingEvent event,
+ CastStat stat,
+ StatsMap* stats_map) const;
+ void PopulatePlayoutDelayStat(StatsMap* stats_map) const;
+ void PopulateFrameBitrateStat(base::TimeTicks now, StatsMap* stats_map) const;
+ void PopulatePacketBitrateStat(base::TimeTicks now,
+ CastLoggingEvent event,
+ CastStat stat,
+ StatsMap* stats_map) const;
+ void PopulatePacketLossPercentageStat(StatsMap* stats_map) const;
+
+ const EventMediaType event_media_type_;
+
+ // Not owned by this class.
+ base::TickClock* const clock_;
+
+ // Not owned by this class.
+ ReceiverTimeOffsetEstimator* const offset_estimator_;
+
FrameStatsMap frame_stats_;
PacketStatsMap packet_stats_;
+
+ base::TimeDelta total_network_latency_;
+ int network_latency_datapoints_;
+ base::TimeDelta total_e2e_latency_;
+ int e2e_latency_datapoints_;
+
+ base::TimeTicks last_response_received_time_;
+
+ // Fixed size map to record when recent frames were captured.
+ FrameEventTimeMap frame_captured_times_;
+
+ // Fixed size map to record when recent packets were sent.
+ PacketEventTimeMap packet_sent_times_;
+
+ // Sender time assigned on creation and |Reset()|.
+ base::TimeTicks start_time_;
+
base::ThreadChecker thread_checker_;
DISALLOW_COPY_AND_ASSIGN(StatsEventSubscriber);
};
diff --git a/media/cast/logging/stats_event_subscriber_unittest.cc b/media/cast/logging/stats_event_subscriber_unittest.cc
index a532580f..7d6b5c8 100644
--- a/media/cast/logging/stats_event_subscriber_unittest.cc
+++ b/media/cast/logging/stats_event_subscriber_unittest.cc
@@ -4,147 +4,388 @@
#include "base/memory/ref_counted.h"
#include "base/memory/scoped_ptr.h"
+#include "base/rand_util.h"
#include "base/test/simple_test_tick_clock.h"
#include "base/time/tick_clock.h"
#include "media/cast/cast_environment.h"
#include "media/cast/logging/logging_defines.h"
#include "media/cast/logging/stats_event_subscriber.h"
+#include "media/cast/test/fake_receiver_time_offset_estimator.h"
#include "media/cast/test/fake_single_thread_task_runner.h"
#include "testing/gtest/include/gtest/gtest.h"
+namespace {
+const int kReceiverOffsetSecs = 100;
+}
+
namespace media {
namespace cast {
class StatsEventSubscriberTest : public ::testing::Test {
protected:
StatsEventSubscriberTest()
- : testing_clock_(new base::SimpleTestTickClock()),
- task_runner_(new test::FakeSingleThreadTaskRunner(testing_clock_)),
+ : sender_clock_(new base::SimpleTestTickClock()),
+ task_runner_(new test::FakeSingleThreadTaskRunner(sender_clock_)),
cast_environment_(new CastEnvironment(
- scoped_ptr<base::TickClock>(testing_clock_).Pass(),
+ scoped_ptr<base::TickClock>(sender_clock_).Pass(),
task_runner_,
task_runner_,
- task_runner_)) {}
+ task_runner_)),
+ fake_offset_estimator_(
+ base::TimeDelta::FromSeconds(kReceiverOffsetSecs)) {
+ receiver_clock_.Advance(base::TimeDelta::FromSeconds(kReceiverOffsetSecs));
+ cast_environment_->Logging()->AddRawEventSubscriber(
+ &fake_offset_estimator_);
+ }
virtual ~StatsEventSubscriberTest() {
if (subscriber_.get())
cast_environment_->Logging()->RemoveRawEventSubscriber(subscriber_.get());
+ cast_environment_->Logging()->RemoveRawEventSubscriber(
+ &fake_offset_estimator_);
+ }
+
+ void AdvanceClocks(base::TimeDelta delta) {
+ sender_clock_->Advance(delta);
+ receiver_clock_.Advance(delta);
}
void Init(EventMediaType event_media_type) {
DCHECK(!subscriber_.get());
- subscriber_.reset(new StatsEventSubscriber(event_media_type));
+ subscriber_.reset(new StatsEventSubscriber(
+ event_media_type, cast_environment_->Clock(), &fake_offset_estimator_));
cast_environment_->Logging()->AddRawEventSubscriber(subscriber_.get());
}
- base::SimpleTestTickClock* testing_clock_; // Owned by CastEnvironment.
+ base::SimpleTestTickClock* sender_clock_; // Owned by CastEnvironment.
+ base::SimpleTestTickClock receiver_clock_;
scoped_refptr<test::FakeSingleThreadTaskRunner> task_runner_;
scoped_refptr<CastEnvironment> cast_environment_;
+ test::FakeReceiverTimeOffsetEstimator fake_offset_estimator_;
scoped_ptr<StatsEventSubscriber> subscriber_;
};
-TEST_F(StatsEventSubscriberTest, FrameStats) {
+TEST_F(StatsEventSubscriberTest, Capture) {
Init(VIDEO_EVENT);
+
uint32 rtp_timestamp = 0;
uint32 frame_id = 0;
int num_frames = 10;
- int frame_size = 123;
- int delay_base_ms = 10;
- int target_bitrate = 1234;
- base::TimeTicks now;
+ base::TimeTicks start_time = sender_clock_->NowTicks();
for (int i = 0; i < num_frames; i++) {
- now = testing_clock_->NowTicks();
- cast_environment_->Logging()->InsertFrameEvent(
- now, kVideoFrameReceived, rtp_timestamp, frame_id);
- testing_clock_->Advance(base::TimeDelta::FromMilliseconds(30));
+ cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
+ kVideoFrameCaptured,
+ rtp_timestamp,
+ frame_id);
+
+ AdvanceClocks(base::TimeDelta::FromMicroseconds(34567));
+ rtp_timestamp += 90;
+ frame_id++;
+ }
+
+ base::TimeTicks end_time = sender_clock_->NowTicks();
+
+ StatsEventSubscriber::StatsMap stats_map;
+ subscriber_->GetStatsInternal(&stats_map);
+ StatsEventSubscriber::StatsMap::iterator it =
+ stats_map.find(StatsEventSubscriber::CAPTURE_FPS);
+ ASSERT_NE(it, stats_map.end());
+
+ base::TimeDelta duration = end_time - start_time;
+ EXPECT_DOUBLE_EQ(
+ it->second,
+ static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
+}
+
+TEST_F(StatsEventSubscriberTest, Encode) {
+ Init(VIDEO_EVENT);
+
+ uint32 rtp_timestamp = 0;
+ uint32 frame_id = 0;
+ int num_frames = 10;
+ base::TimeTicks start_time = sender_clock_->NowTicks();
+ int total_size = 0;
+ for (int i = 0; i < num_frames; i++) {
+ int size = 1000 + base::RandInt(-100, 100);
+ total_size += size;
cast_environment_->Logging()->InsertEncodedFrameEvent(
- now, kVideoFrameEncoded, rtp_timestamp, i, frame_size, true,
- target_bitrate);
- testing_clock_->Advance(base::TimeDelta::FromMilliseconds(30));
+ sender_clock_->NowTicks(),
+ kVideoFrameEncoded,
+ rtp_timestamp,
+ frame_id,
+ size,
+ true,
+ 5678);
+
+ AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
+ rtp_timestamp += 90;
+ frame_id++;
+ }
+
+ base::TimeTicks end_time = sender_clock_->NowTicks();
+
+ StatsEventSubscriber::StatsMap stats_map;
+ subscriber_->GetStatsInternal(&stats_map);
+
+ StatsEventSubscriber::StatsMap::iterator it =
+ stats_map.find(StatsEventSubscriber::ENCODE_FPS);
+ ASSERT_NE(it, stats_map.end());
+
+ base::TimeDelta duration = end_time - start_time;
+ EXPECT_DOUBLE_EQ(
+ it->second,
+ static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
+
+ it = stats_map.find(StatsEventSubscriber::ENCODE_KBPS);
+ ASSERT_NE(it, stats_map.end());
+
+ EXPECT_DOUBLE_EQ(it->second,
+ static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
+}
+
+TEST_F(StatsEventSubscriberTest, Decode) {
+ Init(VIDEO_EVENT);
+
+ uint32 rtp_timestamp = 0;
+ uint32 frame_id = 0;
+ int num_frames = 10;
+ base::TimeTicks start_time = sender_clock_->NowTicks();
+ for (int i = 0; i < num_frames; i++) {
+ cast_environment_->Logging()->InsertFrameEvent(receiver_clock_.NowTicks(),
+ kVideoFrameDecoded,
+ rtp_timestamp,
+ frame_id);
+
+ AdvanceClocks(base::TimeDelta::FromMicroseconds(36789));
+ rtp_timestamp += 90;
+ frame_id++;
+ }
+
+ base::TimeTicks end_time = sender_clock_->NowTicks();
+
+ StatsEventSubscriber::StatsMap stats_map;
+ subscriber_->GetStatsInternal(&stats_map);
+
+ StatsEventSubscriber::StatsMap::iterator it =
+ stats_map.find(StatsEventSubscriber::DECODE_FPS);
+ ASSERT_NE(it, stats_map.end());
+ base::TimeDelta duration = end_time - start_time;
+ EXPECT_DOUBLE_EQ(
+ it->second,
+ static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
+}
+
+TEST_F(StatsEventSubscriberTest, PlayoutDelay) {
+ Init(VIDEO_EVENT);
+
+ uint32 rtp_timestamp = 0;
+ uint32 frame_id = 0;
+ int num_frames = 10;
+ int total_delay_ms = 0;
+ for (int i = 0; i < num_frames; i++) {
+ int delay_ms = base::RandInt(-50, 50);
+ base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms);
+ total_delay_ms += delay_ms;
cast_environment_->Logging()->InsertFrameEventWithDelay(
- now,
+ receiver_clock_.NowTicks(),
kVideoRenderDelay,
rtp_timestamp,
- i,
- base::TimeDelta::FromMilliseconds(i * delay_base_ms));
- testing_clock_->Advance(base::TimeDelta::FromMilliseconds(30));
+ frame_id,
+ delay);
+ AdvanceClocks(base::TimeDelta::FromMicroseconds(37890));
rtp_timestamp += 90;
+ frame_id++;
}
- // Verify stats.
- FrameStatsMap frame_stats;
- subscriber_->GetFrameStats(&frame_stats);
+ StatsEventSubscriber::StatsMap stats_map;
+ subscriber_->GetStatsInternal(&stats_map);
+
+ StatsEventSubscriber::StatsMap::iterator it =
+ stats_map.find(StatsEventSubscriber::AVG_PLAYOUT_DELAY_MS);
+ ASSERT_NE(it, stats_map.end());
+
+ EXPECT_DOUBLE_EQ(
+ it->second, static_cast<double>(total_delay_ms) / num_frames);
+}
+
+TEST_F(StatsEventSubscriberTest, E2ELatency) {
+ Init(VIDEO_EVENT);
- // Size of stats equals the number of events.
- EXPECT_EQ(3u, frame_stats.size());
- FrameStatsMap::const_iterator it = frame_stats.find(kVideoFrameReceived);
- ASSERT_TRUE(it != frame_stats.end());
- EXPECT_EQ(num_frames, it->second.event_counter);
+ uint32 rtp_timestamp = 0;
+ uint32 frame_id = 0;
+ int num_frames = 10;
+ base::TimeDelta total_latency;
+ for (int i = 0; i < num_frames; i++) {
+ cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
+ kVideoFrameCaptured,
+ rtp_timestamp,
+ frame_id);
+
+ int latency_micros = 100000 + base::RandInt(-5000, 50000);
+ base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
+ AdvanceClocks(latency);
+
+ int delay_micros = base::RandInt(-50000, 50000);
+ base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_micros);
+ total_latency += latency + delay;
+
+ cast_environment_->Logging()->InsertFrameEventWithDelay(
+ receiver_clock_.NowTicks(),
+ kVideoRenderDelay,
+ rtp_timestamp,
+ frame_id,
+ delay);
- it = frame_stats.find(kVideoFrameEncoded);
- ASSERT_TRUE(it != frame_stats.end());
+ rtp_timestamp += 90;
+ frame_id++;
+ }
- EXPECT_EQ(num_frames * frame_size, static_cast<int>(it->second.sum_size));
+ StatsEventSubscriber::StatsMap stats_map;
+ subscriber_->GetStatsInternal(&stats_map);
- it = frame_stats.find(kVideoRenderDelay);
- ASSERT_TRUE(it != frame_stats.end());
+ StatsEventSubscriber::StatsMap::iterator it =
+ stats_map.find(StatsEventSubscriber::AVG_E2E_LATENCY_MS);
+ ASSERT_NE(it, stats_map.end());
- EXPECT_EQ(0, it->second.min_delay.InMilliseconds());
- EXPECT_EQ((num_frames - 1) * delay_base_ms,
- it->second.max_delay.InMilliseconds());
- EXPECT_EQ((num_frames - 1) * num_frames / 2 * delay_base_ms,
- it->second.sum_delay.InMilliseconds());
+ EXPECT_DOUBLE_EQ(
+ it->second, total_latency.InMillisecondsF() / num_frames);
}
-TEST_F(StatsEventSubscriberTest, PacketStats) {
- Init(AUDIO_EVENT);
+TEST_F(StatsEventSubscriberTest, Packets) {
+ Init(VIDEO_EVENT);
+
uint32 rtp_timestamp = 0;
- uint32 frame_id = 0;
int num_packets = 10;
- int packet_size = 123;
- base::TimeTicks first_event_time = testing_clock_->NowTicks();
- base::TimeTicks now;
+ int num_latency_recorded_packets = 0;
+ base::TimeTicks start_time = sender_clock_->NowTicks();
+ int total_size = 0;
+ int retransmit_total_size = 0;
+ base::TimeDelta total_latency;
+ int num_packets_sent = 0;
+ int num_packets_retransmitted = 0;
+ // Every 2nd packet will be retransmitted once.
+ // Every 4th packet will be retransmitted twice.
+ // Every 8th packet will be retransmitted 3 times.
for (int i = 0; i < num_packets; i++) {
- now = testing_clock_->NowTicks();
- cast_environment_->Logging()->InsertPacketEvent(now,
- kAudioPacketSentToPacer,
+ int size = 1000 + base::RandInt(-100, 100);
+ total_size += size;
+
+ cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(),
+ kVideoPacketSentToNetwork,
+ rtp_timestamp,
+ 0,
+ i,
+ num_packets - 1,
+ size);
+ num_packets_sent++;
+
+ int latency_micros = 20000 + base::RandInt(-10000, 10000);
+ base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
+ // Latency is only recorded for packets that aren't retransmitted.
+ if (i % 2 != 0) {
+ total_latency += latency;
+ num_latency_recorded_packets++;
+ }
+
+ AdvanceClocks(latency);
+
+ base::TimeTicks received_time = receiver_clock_.NowTicks();
+
+ // Retransmission 1.
+ AdvanceClocks(base::TimeDelta::FromMicroseconds(12345));
+ if (i % 2 == 0) {
+ cast_environment_->Logging()->InsertPacketEvent(
+ receiver_clock_.NowTicks(),
+ kVideoPacketRetransmitted,
+ rtp_timestamp,
+ 0,
+ i,
+ num_packets - 1,
+ size);
+ retransmit_total_size += size;
+ num_packets_sent++;
+ num_packets_retransmitted++;
+ }
+
+ // Retransmission 2.
+ AdvanceClocks(base::TimeDelta::FromMicroseconds(13456));
+ if (i % 4 == 0) {
+ cast_environment_->Logging()->InsertPacketEvent(
+ receiver_clock_.NowTicks(),
+ kVideoPacketRetransmitted,
+ rtp_timestamp,
+ 0,
+ i,
+ num_packets - 1,
+ size);
+ retransmit_total_size += size;
+ num_packets_sent++;
+ num_packets_retransmitted++;
+ }
+
+ // Retransmission 3.
+ AdvanceClocks(base::TimeDelta::FromMicroseconds(14567));
+ if (i % 8 == 0) {
+ cast_environment_->Logging()->InsertPacketEvent(
+ receiver_clock_.NowTicks(),
+ kVideoPacketRetransmitted,
+ rtp_timestamp,
+ 0,
+ i,
+ num_packets - 1,
+ size);
+ retransmit_total_size += size;
+ num_packets_sent++;
+ num_packets_retransmitted++;
+ }
+
+ cast_environment_->Logging()->InsertPacketEvent(received_time,
+ kVideoPacketReceived,
rtp_timestamp,
- frame_id,
0,
- 10,
- packet_size);
- testing_clock_->Advance(base::TimeDelta::FromMilliseconds(30));
+ i,
+ num_packets - 1,
+ size);
}
- PacketStatsMap stats_map;
- subscriber_->GetPacketStats(&stats_map);
+ base::TimeTicks end_time = sender_clock_->NowTicks();
+ base::TimeDelta duration = end_time - start_time;
- // Size of stats equals the number of event types.
- EXPECT_EQ(1u, stats_map.size());
- PacketStatsMap::const_iterator it = stats_map.find(kAudioPacketSentToPacer);
- ASSERT_NE(stats_map.end(), it);
+ StatsEventSubscriber::StatsMap stats_map;
+ subscriber_->GetStatsInternal(&stats_map);
- EXPECT_EQ(first_event_time, it->second.first_event_time);
- EXPECT_EQ(now, it->second.last_event_time);
- EXPECT_EQ(num_packets, it->second.event_counter);
- EXPECT_EQ(num_packets * packet_size, static_cast<int>(it->second.sum_size));
-}
+ // Measure AVG_NETWORK_LATENCY_MS, TRANSMISSION_KBPS, RETRANSMISSION_KBPS,
+ // and PACKET_LOSS_FRACTION.
+ StatsEventSubscriber::StatsMap::iterator it =
+ stats_map.find(StatsEventSubscriber::AVG_NETWORK_LATENCY_MS);
+ ASSERT_NE(it, stats_map.end());
-TEST_F(StatsEventSubscriberTest, Reset) {
- Init(VIDEO_EVENT);
- cast_environment_->Logging()->InsertFrameEvent(
- testing_clock_->NowTicks(), kVideoFrameReceived, 0, 0);
+ EXPECT_DOUBLE_EQ(
+ it->second,
+ total_latency.InMillisecondsF() / num_latency_recorded_packets);
+
+ it = stats_map.find(StatsEventSubscriber::TRANSMISSION_KBPS);
+ ASSERT_NE(it, stats_map.end());
+
+ EXPECT_DOUBLE_EQ(it->second,
+ static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
+
+ it = stats_map.find(StatsEventSubscriber::RETRANSMISSION_KBPS);
+ ASSERT_NE(it, stats_map.end());
+
+ EXPECT_DOUBLE_EQ(it->second,
+ static_cast<double>(retransmit_total_size) /
+ duration.InMillisecondsF() * 8);
- FrameStatsMap frame_stats;
- subscriber_->GetFrameStats(&frame_stats);
- EXPECT_EQ(1u, frame_stats.size());
+ it = stats_map.find(StatsEventSubscriber::PACKET_LOSS_FRACTION);
+ ASSERT_NE(it, stats_map.end());
- subscriber_->Reset();
- subscriber_->GetFrameStats(&frame_stats);
- EXPECT_TRUE(frame_stats.empty());
+ EXPECT_DOUBLE_EQ(
+ it->second,
+ static_cast<double>(num_packets_retransmitted) / num_packets_sent);
}
} // namespace cast
diff --git a/media/cast/logging/stats_util.cc b/media/cast/logging/stats_util.cc
deleted file mode 100644
index 9b50b5d..0000000
--- a/media/cast/logging/stats_util.cc
+++ /dev/null
@@ -1,72 +0,0 @@
-// Copyright 2014 The Chromium Authors. All rights reserved.
-// Use of this source code is governed by a BSD-style license that can be
-// found in the LICENSE file.
-
-#include "media/cast/logging/stats_util.h"
-
-#include "base/logging.h"
-#include "base/memory/scoped_ptr.h"
-#include "base/values.h"
-
-namespace media {
-namespace cast {
-
-scoped_ptr<base::DictionaryValue> ConvertStats(
- const FrameStatsMap& frame_stats_map,
- const PacketStatsMap& packet_stats_map) {
- scoped_ptr<base::DictionaryValue> overall_stats(new base::DictionaryValue);
-
- scoped_ptr<base::DictionaryValue> overall_frame_stats(
- new base::DictionaryValue);
- for (FrameStatsMap::const_iterator it = frame_stats_map.begin();
- it != frame_stats_map.end();
- ++it) {
- scoped_ptr<base::DictionaryValue> frame_stats(new base::DictionaryValue);
-
- frame_stats->SetDouble("firstEventTime",
- it->second.first_event_time.ToInternalValue());
- frame_stats->SetDouble("lastEventTime",
- it->second.last_event_time.ToInternalValue());
- frame_stats->SetInteger("count", it->second.event_counter);
- frame_stats->SetInteger("sizeTotal", static_cast<int>(it->second.sum_size));
- frame_stats->SetInteger("minDelayMs",
- it->second.min_delay.InMilliseconds());
- frame_stats->SetInteger("maxDelayMs",
- it->second.max_delay.InMilliseconds());
- frame_stats->SetInteger("sumDelayMs",
- it->second.sum_delay.InMilliseconds());
-
- overall_frame_stats->Set(CastLoggingToString(it->first),
- frame_stats.release());
- }
-
- overall_stats->Set("frameStats", overall_frame_stats.release());
-
- scoped_ptr<base::DictionaryValue> overall_packet_stats(
- new base::DictionaryValue);
- for (PacketStatsMap::const_iterator it = packet_stats_map.begin();
- it != packet_stats_map.end();
- ++it) {
- scoped_ptr<base::DictionaryValue> packet_stats(new base::DictionaryValue);
-
- packet_stats->SetDouble("firstEventTime",
- it->second.first_event_time.ToInternalValue());
- packet_stats->SetDouble("lastEventTime",
- it->second.last_event_time.ToInternalValue());
- packet_stats->SetDouble("lastEventTime",
- it->second.last_event_time.ToInternalValue());
- packet_stats->SetInteger("count", it->second.event_counter);
- packet_stats->SetInteger("sizeTotal",
- static_cast<int>(it->second.sum_size));
-
- overall_packet_stats->Set(CastLoggingToString(it->first),
- packet_stats.release());
- }
-
- overall_stats->Set("packetStats", overall_packet_stats.release());
-
- return overall_stats.Pass();
-}
-
-} // namespace cast
-} // namespace media
diff --git a/media/cast/logging/stats_util.h b/media/cast/logging/stats_util.h
deleted file mode 100644
index bbac273..0000000
--- a/media/cast/logging/stats_util.h
+++ /dev/null
@@ -1,27 +0,0 @@
-// Copyright 2014 The Chromium Authors. All rights reserved.
-// Use of this source code is governed by a BSD-style license that can be
-// found in the LICENSE file.
-
-#ifndef MEDIA_CAST_LOGGING_STATS_UTIL_H_
-#define MEDIA_CAST_LOGGING_STATS_UTIL_H_
-
-#include "base/memory/scoped_ptr.h"
-#include "media/cast/logging/logging_defines.h"
-
-namespace base {
-class DictionaryValue;
-}
-
-namespace media {
-namespace cast {
-
-// Converts stats provided in |frame_stats_map| and |packet_stats_map| to
-// base::DictionaryValue format. See .cc file for the exact structure.
-scoped_ptr<base::DictionaryValue> ConvertStats(
- const FrameStatsMap& frame_stats_map,
- const PacketStatsMap& packet_stats_map);
-
-} // namespace cast
-} // namespace media
-
-#endif // MEDIA_CAST_LOGGING_STATS_UTIL_H_
diff --git a/media/cast/test/fake_receiver_time_offset_estimator.cc b/media/cast/test/fake_receiver_time_offset_estimator.cc
new file mode 100644
index 0000000..3cc5f72
--- /dev/null
+++ b/media/cast/test/fake_receiver_time_offset_estimator.cc
@@ -0,0 +1,37 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "media/cast/test/fake_receiver_time_offset_estimator.h"
+
+namespace media {
+namespace cast {
+namespace test {
+
+FakeReceiverTimeOffsetEstimator::FakeReceiverTimeOffsetEstimator(
+ base::TimeDelta offset)
+ : offset_(offset) {}
+
+FakeReceiverTimeOffsetEstimator::~FakeReceiverTimeOffsetEstimator() {}
+
+void FakeReceiverTimeOffsetEstimator::OnReceiveFrameEvent(
+ const FrameEvent& frame_event) {
+ // Do nothing.
+}
+
+void FakeReceiverTimeOffsetEstimator::OnReceivePacketEvent(
+ const PacketEvent& packet_event) {
+ // Do nothing.
+}
+
+bool FakeReceiverTimeOffsetEstimator::GetReceiverOffsetBounds(
+ base::TimeDelta* lower_bound,
+ base::TimeDelta* upper_bound) {
+ *lower_bound = offset_;
+ *upper_bound = offset_;
+ return true;
+}
+
+} // namespace test
+} // namespace cast
+} // namespace media
diff --git a/media/cast/test/fake_receiver_time_offset_estimator.h b/media/cast/test/fake_receiver_time_offset_estimator.h
new file mode 100644
index 0000000..2a4d3cd
--- /dev/null
+++ b/media/cast/test/fake_receiver_time_offset_estimator.h
@@ -0,0 +1,42 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef MEDIA_CAST_TEST_FAKE_RECEIVER_TIME_OFFSET_ESTIMATOR_H_
+#define MEDIA_CAST_TEST_FAKE_RECEIVER_TIME_OFFSET_ESTIMATOR_H_
+
+#include "base/time/time.h"
+#include "base/threading/thread_checker.h"
+#include "media/cast/logging/logging_defines.h"
+#include "media/cast/logging/receiver_time_offset_estimator.h"
+
+namespace media {
+namespace cast {
+namespace test {
+
+// This class is used for testing. It will always return the |offset| value
+// provided during construction as offset bounds.
+class FakeReceiverTimeOffsetEstimator : public ReceiverTimeOffsetEstimator {
+ public:
+ FakeReceiverTimeOffsetEstimator(base::TimeDelta offset);
+
+ virtual ~FakeReceiverTimeOffsetEstimator();
+
+ // RawReventSubscriber implementations.
+ virtual void OnReceiveFrameEvent(const FrameEvent& frame_event) OVERRIDE;
+ virtual void OnReceivePacketEvent(const PacketEvent& packet_event) OVERRIDE;
+
+ // ReceiverTimeOffsetEstimator
+ virtual bool GetReceiverOffsetBounds(base::TimeDelta* lower_bound,
+ base::TimeDelta* upper_bound) OVERRIDE;
+
+ private:
+ const base::TimeDelta offset_;
+ DISALLOW_COPY_AND_ASSIGN(FakeReceiverTimeOffsetEstimator);
+};
+
+} // namespace test
+} // namespace cast
+} // namespace media
+
+#endif // MEDIA_CAST_TEST_FAKE_RECEIVER_TIME_OFFSET_ESTIMATOR_H_
diff --git a/media/cast/test/sender.cc b/media/cast/test/sender.cc
index 628f6b7..4a30ea9 100644
--- a/media/cast/test/sender.cc
+++ b/media/cast/test/sender.cc
@@ -14,12 +14,14 @@
#include "base/files/file_path.h"
#include "base/files/memory_mapped_file.h"
#include "base/files/scoped_file.h"
+#include "base/json/json_writer.h"
#include "base/logging.h"
#include "base/memory/scoped_ptr.h"
#include "base/path_service.h"
#include "base/strings/string_number_conversions.h"
#include "base/threading/thread.h"
#include "base/time/default_tick_clock.h"
+#include "base/values.h"
#include "media/audio/audio_parameters.h"
#include "media/base/audio_buffer.h"
#include "media/base/audio_bus.h"
@@ -36,6 +38,8 @@
#include "media/cast/logging/log_serializer.h"
#include "media/cast/logging/logging_defines.h"
#include "media/cast/logging/proto/raw_events.pb.h"
+#include "media/cast/logging/receiver_time_offset_estimator_impl.h"
+#include "media/cast/logging/stats_event_subscriber.h"
#include "media/cast/test/utility/audio_utility.h"
#include "media/cast/test/utility/default_config.h"
#include "media/cast/test/utility/input_builder.h"
@@ -801,7 +805,7 @@ void DumpLoggingData(const media::cast::proto::LogMetadata& log_metadata,
VLOG(0) << "Failed to write logs to file.";
}
-void WriteLogsToFileAndStopSubscribing(
+void WriteLogsToFileAndDestroySubscribers(
const scoped_refptr<media::cast::CastEnvironment>& cast_environment,
scoped_ptr<media::cast::EncodingEventSubscriber> video_event_subscriber,
scoped_ptr<media::cast::EncodingEventSubscriber> audio_event_subscriber,
@@ -834,6 +838,30 @@ void WriteLogsToFileAndStopSubscribing(
audio_log_file.Pass());
}
+void WriteStatsAndDestroySubscribers(
+ const scoped_refptr<media::cast::CastEnvironment>& cast_environment,
+ scoped_ptr<media::cast::StatsEventSubscriber> video_event_subscriber,
+ scoped_ptr<media::cast::StatsEventSubscriber> audio_event_subscriber,
+ scoped_ptr<media::cast::ReceiverTimeOffsetEstimatorImpl> estimator) {
+ cast_environment->Logging()->RemoveRawEventSubscriber(
+ video_event_subscriber.get());
+ cast_environment->Logging()->RemoveRawEventSubscriber(
+ audio_event_subscriber.get());
+ cast_environment->Logging()->RemoveRawEventSubscriber(estimator.get());
+
+ scoped_ptr<base::DictionaryValue> stats = video_event_subscriber->GetStats();
+ std::string json;
+ base::JSONWriter::WriteWithOptions(
+ stats.get(), base::JSONWriter::OPTIONS_PRETTY_PRINT, &json);
+ VLOG(0) << "Video stats: " << json;
+
+ stats = audio_event_subscriber->GetStats();
+ json.clear();
+ base::JSONWriter::WriteWithOptions(
+ stats.get(), base::JSONWriter::OPTIONS_PRETTY_PRINT, &json);
+ VLOG(0) << "Audio stats: " << json;
+}
+
} // namespace
int main(int argc, char** argv) {
@@ -942,6 +970,23 @@ int main(int argc, char** argv) {
cast_environment->Logging()->AddRawEventSubscriber(
audio_event_subscriber.get());
+ // Subscribers for stats.
+ scoped_ptr<media::cast::ReceiverTimeOffsetEstimatorImpl> offset_estimator(
+ new media::cast::ReceiverTimeOffsetEstimatorImpl);
+ cast_environment->Logging()->AddRawEventSubscriber(offset_estimator.get());
+ scoped_ptr<media::cast::StatsEventSubscriber> video_stats_subscriber(
+ new media::cast::StatsEventSubscriber(media::cast::VIDEO_EVENT,
+ cast_environment->Clock(),
+ offset_estimator.get()));
+ scoped_ptr<media::cast::StatsEventSubscriber> audio_stats_subscriber(
+ new media::cast::StatsEventSubscriber(media::cast::AUDIO_EVENT,
+ cast_environment->Clock(),
+ offset_estimator.get()));
+ cast_environment->Logging()->AddRawEventSubscriber(
+ video_stats_subscriber.get());
+ cast_environment->Logging()->AddRawEventSubscriber(
+ audio_stats_subscriber.get());
+
base::ScopedFILE video_log_file(fopen(video_log_file_name.c_str(), "w"));
if (!video_log_file) {
VLOG(1) << "Failed to open video log file for writing.";
@@ -954,18 +999,29 @@ int main(int argc, char** argv) {
exit(-1);
}
- const int logging_duration_seconds = 300;
+ const int logging_duration_seconds = 10;
io_message_loop.message_loop_proxy()->PostDelayedTask(
FROM_HERE,
- base::Bind(&WriteLogsToFileAndStopSubscribing,
+ base::Bind(&WriteLogsToFileAndDestroySubscribers,
cast_environment,
base::Passed(&video_event_subscriber),
base::Passed(&audio_event_subscriber),
base::Passed(&video_log_file),
base::Passed(&audio_log_file)),
base::TimeDelta::FromSeconds(logging_duration_seconds));
+
+ io_message_loop.message_loop_proxy()->PostDelayedTask(
+ FROM_HERE,
+ base::Bind(&WriteStatsAndDestroySubscribers,
+ cast_environment,
+ base::Passed(&video_stats_subscriber),
+ base::Passed(&audio_stats_subscriber),
+ base::Passed(&offset_estimator)),
+ base::TimeDelta::FromSeconds(logging_duration_seconds));
+
send_process->Start(cast_sender->audio_frame_input(),
cast_sender->video_frame_input());
+
io_message_loop.Run();
return 0;
}