diff options
52 files changed, 1430 insertions, 1968 deletions
diff --git a/chrome/browser/media/cast_transport_host_filter.cc b/chrome/browser/media/cast_transport_host_filter.cc index cb3e42d..3f140734 100644 --- a/chrome/browser/media/cast_transport_host_filter.cc +++ b/chrome/browser/media/cast_transport_host_filter.cc @@ -63,12 +63,11 @@ void CastTransportHostFilter::NotifyStatusChange( void CastTransportHostFilter::SendRawEvents( int32 channel_id, - const std::vector<media::cast::PacketEvent>& packet_events, - const std::vector<media::cast::FrameEvent>& frame_events) { - if (!packet_events.empty()) - Send(new CastMsg_RawEvents(channel_id, - packet_events, - frame_events)); + scoped_ptr<std::vector<media::cast::FrameEvent>> frame_events, + scoped_ptr<std::vector<media::cast::PacketEvent>> packet_events) { + if (frame_events->empty() && packet_events->empty()) + return; + Send(new CastMsg_RawEvents(channel_id, *packet_events, *frame_events)); } void CastTransportHostFilter::SendRtt(int32 channel_id, diff --git a/chrome/browser/media/cast_transport_host_filter.h b/chrome/browser/media/cast_transport_host_filter.h index b30e08b..094d7e7 100644 --- a/chrome/browser/media/cast_transport_host_filter.h +++ b/chrome/browser/media/cast_transport_host_filter.h @@ -32,8 +32,8 @@ class CastTransportHostFilter : public content::BrowserMessageFilter { media::cast::CastTransportStatus result); void SendRawEvents( int32 channel_id, - const std::vector<media::cast::PacketEvent>& packet_events, - const std::vector<media::cast::FrameEvent>& frame_events); + scoped_ptr<std::vector<media::cast::FrameEvent>> frame_events, + scoped_ptr<std::vector<media::cast::PacketEvent>> packet_events); void SendRtt(int32 channel_id, uint32 ssrc, base::TimeDelta rtt); void SendCastMessage(int32 channel_id, uint32 ssrc, diff --git a/chrome/renderer/media/cast_receiver_session_delegate.cc b/chrome/renderer/media/cast_receiver_session_delegate.cc index e7930fa..06ea93d 100644 --- a/chrome/renderer/media/cast_receiver_session_delegate.cc +++ b/chrome/renderer/media/cast_receiver_session_delegate.cc @@ -13,12 +13,6 @@ CastReceiverSessionDelegate::CastReceiverSessionDelegate() } CastReceiverSessionDelegate::~CastReceiverSessionDelegate() {} -void CastReceiverSessionDelegate::LogRawEvents( - const std::vector<media::cast::PacketEvent>& packet_events, - const std::vector<media::cast::FrameEvent>& frame_events) { - NOTREACHED(); -} - void CastReceiverSessionDelegate::Start( const media::cast::FrameReceiverConfig& audio_config, const media::cast::FrameReceiverConfig& video_config, diff --git a/chrome/renderer/media/cast_receiver_session_delegate.h b/chrome/renderer/media/cast_receiver_session_delegate.h index 98de8fd..7f6b963 100644 --- a/chrome/renderer/media/cast_receiver_session_delegate.h +++ b/chrome/renderer/media/cast_receiver_session_delegate.h @@ -19,9 +19,6 @@ class CastReceiverSessionDelegate : public CastSessionDelegateBase { ~CastReceiverSessionDelegate() override; void ReceivePacket(scoped_ptr<media::cast::Packet> packet) override; - void LogRawEvents( - const std::vector<media::cast::PacketEvent>& packet_events, - const std::vector<media::cast::FrameEvent>& frame_events) override; void Start(const media::cast::FrameReceiverConfig& audio_config, const media::cast::FrameReceiverConfig& video_config, diff --git a/chrome/renderer/media/cast_session_delegate.cc b/chrome/renderer/media/cast_session_delegate.cc index 5cca597..f39154d 100644 --- a/chrome/renderer/media/cast_session_delegate.cc +++ b/chrome/renderer/media/cast_session_delegate.cc @@ -79,8 +79,8 @@ void CastSessionDelegateBase::StartUDP( base::Unretained(this)), base::Bind(&CastSessionDelegateBase::StatusNotificationCB, base::Unretained(this), error_callback), - base::Bind(&CastSessionDelegateBase::LogRawEvents, - base::Unretained(this)))); + base::Bind(&media::cast::LogEventDispatcher::DispatchBatchOfEvents, + base::Unretained(cast_environment_->logger())))); } void CastSessionDelegateBase::StatusNotificationCB( @@ -313,44 +313,3 @@ void CastSessionDelegate::ReceivePacket( scoped_ptr<media::cast::Packet> packet) { // Do nothing (frees packet) } - -void CastSessionDelegate::LogRawEvents( - const std::vector<media::cast::PacketEvent>& packet_events, - const std::vector<media::cast::FrameEvent>& frame_events) { - DCHECK(io_task_runner_->BelongsToCurrentThread()); - - for (std::vector<media::cast::PacketEvent>::const_iterator it = - packet_events.begin(); - it != packet_events.end(); - ++it) { - cast_environment_->Logging()->InsertPacketEvent(it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id, - it->packet_id, - it->max_packet_id, - it->size); - } - for (std::vector<media::cast::FrameEvent>::const_iterator it = - frame_events.begin(); - it != frame_events.end(); - ++it) { - if (it->type == media::cast::FRAME_PLAYOUT) { - cast_environment_->Logging()->InsertFrameEventWithDelay( - it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id, - it->delay_delta); - } else { - cast_environment_->Logging()->InsertFrameEvent( - it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id); - } - } -} diff --git a/chrome/renderer/media/cast_session_delegate.h b/chrome/renderer/media/cast_session_delegate.h index 378c50e..cd4e63a2f 100644 --- a/chrome/renderer/media/cast_session_delegate.h +++ b/chrome/renderer/media/cast_session_delegate.h @@ -62,9 +62,6 @@ class CastSessionDelegateBase { media::cast::CastTransportStatus status); virtual void ReceivePacket(scoped_ptr<media::cast::Packet> packet) = 0; - virtual void LogRawEvents( - const std::vector<media::cast::PacketEvent>& packet_events, - const std::vector<media::cast::FrameEvent>& frame_events) = 0; base::ThreadChecker thread_checker_; scoped_refptr<media::cast::CastEnvironment> cast_environment_; @@ -136,10 +133,6 @@ class CastSessionDelegate : public CastSessionDelegateBase { private: void ReceivePacket(scoped_ptr<media::cast::Packet> packet) override; - // Adds logs collected from transport on browser side. - void LogRawEvents(const std::vector<media::cast::PacketEvent>& packet_events, - const std::vector<media::cast::FrameEvent>& frame_events) - override; scoped_ptr<media::cast::CastSender> cast_sender_; diff --git a/chrome/renderer/media/cast_transport_sender_ipc.cc b/chrome/renderer/media/cast_transport_sender_ipc.cc index e814dc2..afa858a 100644 --- a/chrome/renderer/media/cast_transport_sender_ipc.cc +++ b/chrome/renderer/media/cast_transport_sender_ipc.cc @@ -142,7 +142,19 @@ void CastTransportSenderIPC::OnNotifyStatusChange( void CastTransportSenderIPC::OnRawEvents( const std::vector<media::cast::PacketEvent>& packet_events, const std::vector<media::cast::FrameEvent>& frame_events) { - raw_events_callback_.Run(packet_events, frame_events); + // Note: Casting away const to avoid having to copy all the data elements. As + // the only consumer of this data in the IPC message, mutating the inputs + // should be acceptable. Just nod and blame the interface we were given here. + scoped_ptr<std::vector<media::cast::FrameEvent>> taken_frame_events( + new std::vector<media::cast::FrameEvent>()); + taken_frame_events->swap( + const_cast<std::vector<media::cast::FrameEvent>&>(frame_events)); + scoped_ptr<std::vector<media::cast::PacketEvent>> taken_packet_events( + new std::vector<media::cast::PacketEvent>()); + taken_packet_events->swap( + const_cast<std::vector<media::cast::PacketEvent>&>(packet_events)); + raw_events_callback_.Run(taken_frame_events.Pass(), + taken_packet_events.Pass()); } void CastTransportSenderIPC::OnRtt(uint32 ssrc, base::TimeDelta rtt) { diff --git a/media/cast/BUILD.gn b/media/cast/BUILD.gn index 6b87e13..c9c8fc5 100644 --- a/media/cast/BUILD.gn +++ b/media/cast/BUILD.gn @@ -27,14 +27,12 @@ source_set("common") { "logging/encoding_event_subscriber.h", "logging/log_deserializer.cc", "logging/log_deserializer.h", + "logging/log_event_dispatcher.cc", + "logging/log_event_dispatcher.h", "logging/log_serializer.cc", "logging/log_serializer.h", "logging/logging_defines.cc", "logging/logging_defines.h", - "logging/logging_impl.cc", - "logging/logging_impl.h", - "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", @@ -282,8 +280,6 @@ group("cast_unittests_run") { test("cast_unittests") { sources = [ "logging/encoding_event_subscriber_unittest.cc", - "logging/logging_impl_unittest.cc", - "logging/logging_raw_unittest.cc", "logging/receiver_time_offset_estimator_impl_unittest.cc", "logging/serialize_deserialize_test.cc", "logging/simple_event_subscriber_unittest.cc", diff --git a/media/cast/cast.gyp b/media/cast/cast.gyp index 3e8310d..1ef6cda 100644 --- a/media/cast/cast.gyp +++ b/media/cast/cast.gyp @@ -43,14 +43,12 @@ 'logging/encoding_event_subscriber.h', 'logging/log_deserializer.cc', 'logging/log_deserializer.h', + 'logging/log_event_dispatcher.cc', + 'logging/log_event_dispatcher.h', 'logging/log_serializer.cc', 'logging/log_serializer.h', 'logging/logging_defines.cc', 'logging/logging_defines.h', - 'logging/logging_impl.cc', - 'logging/logging_impl.h', - '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', diff --git a/media/cast/cast_environment.cc b/media/cast/cast_environment.cc index f22f0a4..e3def4f 100644 --- a/media/cast/cast_environment.cc +++ b/media/cast/cast_environment.cc @@ -10,14 +10,6 @@ using base::SingleThreadTaskRunner; -namespace { - -void DeleteLoggingOnMainThread(scoped_ptr<media::cast::LoggingImpl> logging) { - logging.reset(); -} - -} // namespace - namespace media { namespace cast { @@ -30,17 +22,9 @@ CastEnvironment::CastEnvironment( audio_thread_proxy_(audio_thread_proxy), video_thread_proxy_(video_thread_proxy), clock_(clock.Pass()), - logging_(new LoggingImpl) {} + logger_(this) {} -CastEnvironment::~CastEnvironment() { - // Logging must be deleted on the main thread. - if (main_thread_proxy_.get() && - !main_thread_proxy_->RunsTasksOnCurrentThread()) { - main_thread_proxy_->PostTask( - FROM_HERE, - base::Bind(&DeleteLoggingOnMainThread, base::Passed(&logging_))); - } -} +CastEnvironment::~CastEnvironment() {} bool CastEnvironment::PostTask(ThreadId identifier, const tracked_objects::Location& from_here, diff --git a/media/cast/cast_environment.h b/media/cast/cast_environment.h index 83b5ce3..9b29d4a 100644 --- a/media/cast/cast_environment.h +++ b/media/cast/cast_environment.h @@ -11,8 +11,7 @@ #include "base/single_thread_task_runner.h" #include "base/time/tick_clock.h" #include "base/time/time.h" -#include "media/cast/logging/logging_defines.h" -#include "media/cast/logging/logging_impl.h" +#include "media/cast/logging/log_event_dispatcher.h" namespace media { namespace cast { @@ -56,10 +55,8 @@ class CastEnvironment : public base::RefCountedThreadSafe<CastEnvironment> { // All of the media::cast implementation must use this TickClock. base::TickClock* Clock() const { return clock_.get(); } - // Logging is not thread safe. Its methods should always be called from the - // main thread. - // TODO(hubbe): Logging should be a thread-safe interface. - LoggingImpl* Logging() const { return logging_.get(); } + // Thread-safe log event dispatcher. + LogEventDispatcher* logger() { return &logger_; } scoped_refptr<base::SingleThreadTaskRunner> GetTaskRunner( ThreadId identifier) const; @@ -76,7 +73,7 @@ class CastEnvironment : public base::RefCountedThreadSafe<CastEnvironment> { scoped_refptr<base::SingleThreadTaskRunner> audio_thread_proxy_; scoped_refptr<base::SingleThreadTaskRunner> video_thread_proxy_; scoped_ptr<base::TickClock> clock_; - scoped_ptr<LoggingImpl> logging_; + LogEventDispatcher logger_; private: friend class base::RefCountedThreadSafe<CastEnvironment>; diff --git a/media/cast/cast_testing.gypi b/media/cast/cast_testing.gypi index 116727e..461bedd 100644 --- a/media/cast/cast_testing.gypi +++ b/media/cast/cast_testing.gypi @@ -76,8 +76,6 @@ 'sources': [ '<(DEPTH)/media/base/run_all_unittests.cc', 'logging/encoding_event_subscriber_unittest.cc', - 'logging/logging_impl_unittest.cc', - 'logging/logging_raw_unittest.cc', 'logging/receiver_time_offset_estimator_impl_unittest.cc', 'logging/serialize_deserialize_test.cc', 'logging/simple_event_subscriber_unittest.cc', diff --git a/media/cast/logging/encoding_event_subscriber_unittest.cc b/media/cast/logging/encoding_event_subscriber_unittest.cc index b052bbb..123a8fe 100644 --- a/media/cast/logging/encoding_event_subscriber_unittest.cc +++ b/media/cast/logging/encoding_event_subscriber_unittest.cc @@ -43,15 +43,12 @@ class EncodingEventSubscriberTest : public ::testing::Test { void Init(EventMediaType event_media_type) { DCHECK(!event_subscriber_); event_subscriber_.reset(new EncodingEventSubscriber(event_media_type, 10)); - cast_environment_->Logging()->AddRawEventSubscriber( - event_subscriber_.get()); + cast_environment_->logger()->Subscribe(event_subscriber_.get()); } ~EncodingEventSubscriberTest() override { - if (event_subscriber_) { - cast_environment_->Logging()->RemoveRawEventSubscriber( - event_subscriber_.get()); - } + if (event_subscriber_) + cast_environment_->logger()->Unsubscribe(event_subscriber_.get()); } void GetEventsAndReset() { @@ -79,20 +76,30 @@ TEST_F(EncodingEventSubscriberTest, FrameEventTruncating) { int width = 320; int height = 180; for (int i = 0; i < 11; i++) { - cast_environment_->Logging()->InsertFrameEvent(now, - FRAME_CAPTURE_BEGIN, - VIDEO_EVENT, - i * 100, - /*frame_id*/ 0); - cast_environment_->Logging()->InsertCapturedVideoFrameEvent(now, - i * 100, - width, - height); - cast_environment_->Logging()->InsertFrameEvent(now, - FRAME_DECODED, - VIDEO_EVENT, - i * 100, - /*frame_id*/ 0); + scoped_ptr<FrameEvent> capture_begin_event(new FrameEvent()); + capture_begin_event->timestamp = now; + capture_begin_event->type = FRAME_CAPTURE_BEGIN; + capture_begin_event->media_type = VIDEO_EVENT; + capture_begin_event->rtp_timestamp = i * 100; + cast_environment_->logger()->DispatchFrameEvent(capture_begin_event.Pass()); + + scoped_ptr<FrameEvent> capture_end_event(new FrameEvent()); + capture_end_event->timestamp = now; + capture_end_event->type = FRAME_CAPTURE_END; + capture_end_event->media_type = VIDEO_EVENT; + capture_end_event->rtp_timestamp = i * 100; + capture_end_event->width = width; + capture_end_event->height = height; + cast_environment_->logger()->DispatchFrameEvent(capture_end_event.Pass()); + + scoped_ptr<FrameEvent> decoded_event(new FrameEvent()); + decoded_event->timestamp = now; + decoded_event->type = FRAME_DECODED; + decoded_event->media_type = VIDEO_EVENT; + decoded_event->rtp_timestamp = i * 100; + decoded_event->frame_id = 0; + cast_environment_->logger()->DispatchFrameEvent(decoded_event.Pass()); + width += 160; height += 90; } @@ -119,14 +126,16 @@ TEST_F(EncodingEventSubscriberTest, PacketEventTruncating) { // Entry with RTP timestamp 0 should get dropped. for (int i = 0; i < 11; i++) { - cast_environment_->Logging()->InsertPacketEvent(now, - PACKET_RECEIVED, - AUDIO_EVENT, - /*rtp_timestamp*/ i * 100, - /*frame_id*/ 0, - /*packet_id*/ i, - /*max_packet_id*/ 10, - /*size*/ 123); + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = now; + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = AUDIO_EVENT; + receive_event->rtp_timestamp = i * 100; + receive_event->frame_id = 0; + receive_event->packet_id = i; + receive_event->max_packet_id = 10; + receive_event->size = 123; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); } GetEventsAndReset(); @@ -141,18 +150,22 @@ TEST_F(EncodingEventSubscriberTest, EventFiltering) { base::TimeTicks now(testing_clock_->NowTicks()); RtpTimestamp rtp_timestamp = 100; - cast_environment_->Logging()->InsertFrameEvent(now, - FRAME_DECODED, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0); + scoped_ptr<FrameEvent> video_event(new FrameEvent()); + video_event->timestamp = now; + video_event->type = FRAME_DECODED; + video_event->media_type = VIDEO_EVENT; + video_event->rtp_timestamp = rtp_timestamp; + video_event->frame_id = 0; + cast_environment_->logger()->DispatchFrameEvent(video_event.Pass()); // This is an AUDIO_EVENT and shouldn't be processed by the subscriber. - cast_environment_->Logging()->InsertFrameEvent(now, - FRAME_DECODED, - AUDIO_EVENT, - rtp_timestamp, - /*frame_id*/ 0); + scoped_ptr<FrameEvent> audio_event(new FrameEvent()); + audio_event->timestamp = now; + audio_event->type = FRAME_DECODED; + audio_event->media_type = AUDIO_EVENT; + audio_event->rtp_timestamp = rtp_timestamp; + audio_event->frame_id = 0; + cast_environment_->logger()->DispatchFrameEvent(audio_event.Pass()); GetEventsAndReset(); @@ -174,10 +187,13 @@ TEST_F(EncodingEventSubscriberTest, FrameEvent) { Init(VIDEO_EVENT); base::TimeTicks now(testing_clock_->NowTicks()); RtpTimestamp rtp_timestamp = 100; - cast_environment_->Logging()->InsertFrameEvent(now, FRAME_DECODED, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0); + scoped_ptr<FrameEvent> decode_event(new FrameEvent()); + decode_event->timestamp = now; + decode_event->type = FRAME_DECODED; + decode_event->media_type = VIDEO_EVENT; + decode_event->rtp_timestamp = rtp_timestamp; + decode_event->frame_id = 0; + cast_environment_->logger()->DispatchFrameEvent(decode_event.Pass()); GetEventsAndReset(); @@ -207,9 +223,14 @@ TEST_F(EncodingEventSubscriberTest, FrameEventDelay) { base::TimeTicks now(testing_clock_->NowTicks()); RtpTimestamp rtp_timestamp = 100; int delay_ms = 100; - cast_environment_->Logging()->InsertFrameEventWithDelay( - now, FRAME_PLAYOUT, AUDIO_EVENT, rtp_timestamp, - /*frame_id*/ 0, base::TimeDelta::FromMilliseconds(delay_ms)); + scoped_ptr<FrameEvent> playout_event(new FrameEvent()); + playout_event->timestamp = now; + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = AUDIO_EVENT; + playout_event->rtp_timestamp = rtp_timestamp; + playout_event->frame_id = 0; + playout_event->delay_delta = base::TimeDelta::FromMilliseconds(delay_ms); + cast_environment_->logger()->DispatchFrameEvent(playout_event.Pass()); GetEventsAndReset(); @@ -241,10 +262,18 @@ TEST_F(EncodingEventSubscriberTest, FrameEventSize) { int target_bitrate = 1024; double encoder_cpu_utilization = 0.90; double idealized_bitrate_utilization = 0.42; - cast_environment_->Logging()->InsertEncodedFrameEvent( - now, FRAME_ENCODED, VIDEO_EVENT, rtp_timestamp, - /*frame_id*/ 0, size, key_frame, target_bitrate, - encoder_cpu_utilization, idealized_bitrate_utilization); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = now; + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp; + encode_event->frame_id = 0; + encode_event->size = size; + encode_event->key_frame = key_frame; + encode_event->target_bitrate = target_bitrate; + encode_event->encoder_cpu_utilization = encoder_cpu_utilization; + encode_event->idealized_bitrate_utilization = idealized_bitrate_utilization; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); GetEventsAndReset(); @@ -276,22 +305,37 @@ TEST_F(EncodingEventSubscriberTest, MultipleFrameEvents) { RtpTimestamp rtp_timestamp1 = 100; RtpTimestamp rtp_timestamp2 = 200; base::TimeTicks now1(testing_clock_->NowTicks()); - cast_environment_->Logging()->InsertFrameEventWithDelay( - now1, FRAME_PLAYOUT, AUDIO_EVENT, rtp_timestamp1, - /*frame_id*/ 0, /*delay*/ base::TimeDelta::FromMilliseconds(100)); - - testing_clock_->Advance(base::TimeDelta::FromMilliseconds(20)); + scoped_ptr<FrameEvent> playout_event(new FrameEvent()); + playout_event->timestamp = now1; + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = AUDIO_EVENT; + playout_event->rtp_timestamp = rtp_timestamp1; + playout_event->frame_id = 0; + playout_event->delay_delta = base::TimeDelta::FromMilliseconds(100); + cast_environment_->logger()->DispatchFrameEvent(playout_event.Pass()); + + task_runner_->Sleep(base::TimeDelta::FromMilliseconds(20)); base::TimeTicks now2(testing_clock_->NowTicks()); - cast_environment_->Logging()->InsertEncodedFrameEvent( - now2, FRAME_ENCODED, AUDIO_EVENT, rtp_timestamp2, - /*frame_id*/ 0, /*size*/ 123, /* key_frame - unused */ false, - /*target_bitrate - unused*/ 0, - 0.44, 0.55); - - testing_clock_->Advance(base::TimeDelta::FromMilliseconds(20)); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = now2; + encode_event->type = FRAME_ENCODED; + encode_event->media_type = AUDIO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp2; + encode_event->frame_id = 0; + encode_event->size = 123; + encode_event->encoder_cpu_utilization = 0.44; + encode_event->idealized_bitrate_utilization = 0.55; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); + + task_runner_->Sleep(base::TimeDelta::FromMilliseconds(20)); base::TimeTicks now3(testing_clock_->NowTicks()); - cast_environment_->Logging()->InsertFrameEvent( - now3, FRAME_DECODED, AUDIO_EVENT, rtp_timestamp1, /*frame_id*/ 0); + scoped_ptr<FrameEvent> decode_event(new FrameEvent()); + decode_event->timestamp = now3; + decode_event->type = FRAME_DECODED; + decode_event->media_type = AUDIO_EVENT; + decode_event->rtp_timestamp = rtp_timestamp1; + decode_event->frame_id = 0; + cast_environment_->logger()->DispatchFrameEvent(decode_event.Pass()); GetEventsAndReset(); @@ -338,10 +382,16 @@ TEST_F(EncodingEventSubscriberTest, PacketEvent) { RtpTimestamp rtp_timestamp = 100; int packet_id = 2; int size = 100; - cast_environment_->Logging()->InsertPacketEvent( - now, PACKET_RECEIVED, AUDIO_EVENT, - rtp_timestamp, /*frame_id*/ 0, packet_id, - /*max_packet_id*/ 10, size); + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = now; + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = AUDIO_EVENT; + receive_event->rtp_timestamp = rtp_timestamp; + receive_event->frame_id = 0; + receive_event->packet_id = packet_id; + receive_event->max_packet_id = 10; + receive_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); GetEventsAndReset(); @@ -374,25 +424,29 @@ TEST_F(EncodingEventSubscriberTest, MultiplePacketEventsForPacket) { RtpTimestamp rtp_timestamp = 100; int packet_id = 2; int size = 100; - cast_environment_->Logging()->InsertPacketEvent(now1, - PACKET_SENT_TO_NETWORK, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0, - packet_id, - /*max_packet_id*/ 10, - size); - - testing_clock_->Advance(base::TimeDelta::FromMilliseconds(20)); + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = now1; + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp; + send_event->frame_id = 0; + send_event->packet_id = packet_id; + send_event->max_packet_id = 10; + send_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); + + task_runner_->Sleep(base::TimeDelta::FromMilliseconds(20)); base::TimeTicks now2(testing_clock_->NowTicks()); - cast_environment_->Logging()->InsertPacketEvent(now2, - PACKET_RETRANSMITTED, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0, - packet_id, - /*max_packet_id*/ 10, - size); + scoped_ptr<PacketEvent> retransmit_event(new PacketEvent()); + retransmit_event->timestamp = now2; + retransmit_event->type = PACKET_RETRANSMITTED; + retransmit_event->media_type = VIDEO_EVENT; + retransmit_event->rtp_timestamp = rtp_timestamp; + retransmit_event->frame_id = 0; + retransmit_event->packet_id = packet_id; + retransmit_event->max_packet_id = 10; + retransmit_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(retransmit_event.Pass()); GetEventsAndReset(); @@ -425,25 +479,29 @@ TEST_F(EncodingEventSubscriberTest, MultiplePacketEventsForFrame) { int packet_id_1 = 2; int packet_id_2 = 3; int size = 100; - cast_environment_->Logging()->InsertPacketEvent(now1, - PACKET_SENT_TO_NETWORK, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0, - packet_id_1, - /*max_packet_id*/ 10, - size); - - testing_clock_->Advance(base::TimeDelta::FromMilliseconds(20)); + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = now1; + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp; + send_event->frame_id = 0; + send_event->packet_id = packet_id_1; + send_event->max_packet_id = 10; + send_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); + + task_runner_->Sleep(base::TimeDelta::FromMilliseconds(20)); base::TimeTicks now2(testing_clock_->NowTicks()); - cast_environment_->Logging()->InsertPacketEvent(now2, - PACKET_RETRANSMITTED, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0, - packet_id_2, - /*max_packet_id*/ 10, - size); + scoped_ptr<PacketEvent> retransmit_event(new PacketEvent()); + retransmit_event->timestamp = now2; + retransmit_event->type = PACKET_RETRANSMITTED; + retransmit_event->media_type = VIDEO_EVENT; + retransmit_event->rtp_timestamp = rtp_timestamp; + retransmit_event->frame_id = 0; + retransmit_event->packet_id = packet_id_2; + retransmit_event->max_packet_id = 10; + retransmit_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(retransmit_event.Pass()); GetEventsAndReset(); @@ -482,25 +540,29 @@ TEST_F(EncodingEventSubscriberTest, MultiplePacketEvents) { int packet_id_1 = 2; int packet_id_2 = 3; int size = 100; - cast_environment_->Logging()->InsertPacketEvent(now1, - PACKET_SENT_TO_NETWORK, - VIDEO_EVENT, - rtp_timestamp_1, - /*frame_id*/ 0, - packet_id_1, - /*max_packet_id*/ 10, - size); - - testing_clock_->Advance(base::TimeDelta::FromMilliseconds(20)); + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = now1; + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp_1; + send_event->frame_id = 0; + send_event->packet_id = packet_id_1; + send_event->max_packet_id = 10; + send_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); + + task_runner_->Sleep(base::TimeDelta::FromMilliseconds(20)); base::TimeTicks now2(testing_clock_->NowTicks()); - cast_environment_->Logging()->InsertPacketEvent(now2, - PACKET_RETRANSMITTED, - VIDEO_EVENT, - rtp_timestamp_2, - /*frame_id*/ 0, - packet_id_2, - /*max_packet_id*/ 10, - size); + scoped_ptr<PacketEvent> retransmit_event(new PacketEvent()); + retransmit_event->timestamp = now2; + retransmit_event->type = PACKET_RETRANSMITTED; + retransmit_event->media_type = VIDEO_EVENT; + retransmit_event->rtp_timestamp = rtp_timestamp_2; + retransmit_event->frame_id = 0; + retransmit_event->packet_id = packet_id_2; + retransmit_event->max_packet_id = 10; + retransmit_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(retransmit_event.Pass()); GetEventsAndReset(); @@ -544,16 +606,21 @@ TEST_F(EncodingEventSubscriberTest, FirstRtpTimestamp) { RtpTimestamp rtp_timestamp = 12345; base::TimeTicks now(testing_clock_->NowTicks()); - cast_environment_->Logging()->InsertFrameEvent(now, - FRAME_CAPTURE_BEGIN, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0); - - cast_environment_->Logging()->InsertCapturedVideoFrameEvent( - now, - rtp_timestamp + 30, - 1280, 720); + scoped_ptr<FrameEvent> capture_begin_event(new FrameEvent()); + capture_begin_event->timestamp = now; + capture_begin_event->type = FRAME_CAPTURE_BEGIN; + capture_begin_event->media_type = VIDEO_EVENT; + capture_begin_event->rtp_timestamp = rtp_timestamp; + cast_environment_->logger()->DispatchFrameEvent(capture_begin_event.Pass()); + + scoped_ptr<FrameEvent> capture_end_event(new FrameEvent()); + capture_end_event->timestamp = now; + capture_end_event->type = FRAME_CAPTURE_END; + capture_end_event->media_type = VIDEO_EVENT; + capture_end_event->rtp_timestamp = rtp_timestamp + 30; + capture_end_event->width = 1280; + capture_end_event->height = 720; + cast_environment_->logger()->DispatchFrameEvent(capture_end_event.Pass()); GetEventsAndReset(); @@ -570,11 +637,13 @@ TEST_F(EncodingEventSubscriberTest, FirstRtpTimestamp) { rtp_timestamp = 67890; - cast_environment_->Logging()->InsertFrameEvent(now, - FRAME_CAPTURE_BEGIN, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0); + capture_begin_event.reset(new FrameEvent()); + capture_begin_event->timestamp = now; + capture_begin_event->type = FRAME_CAPTURE_BEGIN; + capture_begin_event->media_type = VIDEO_EVENT; + capture_begin_event->rtp_timestamp = rtp_timestamp; + cast_environment_->logger()->DispatchFrameEvent(capture_begin_event.Pass()); + GetEventsAndReset(); EXPECT_EQ(rtp_timestamp, first_rtp_timestamp_); @@ -585,17 +654,22 @@ TEST_F(EncodingEventSubscriberTest, RelativeRtpTimestampWrapAround) { RtpTimestamp rtp_timestamp = 0xffffffff - 20; base::TimeTicks now(testing_clock_->NowTicks()); - cast_environment_->Logging()->InsertFrameEvent(now, - FRAME_CAPTURE_BEGIN, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0); + scoped_ptr<FrameEvent> capture_begin_event(new FrameEvent()); + capture_begin_event->timestamp = now; + capture_begin_event->type = FRAME_CAPTURE_BEGIN; + capture_begin_event->media_type = VIDEO_EVENT; + capture_begin_event->rtp_timestamp = rtp_timestamp; + cast_environment_->logger()->DispatchFrameEvent(capture_begin_event.Pass()); // RtpTimestamp has now wrapped around. - cast_environment_->Logging()->InsertCapturedVideoFrameEvent( - now, - rtp_timestamp + 30, - 1280, 720); + scoped_ptr<FrameEvent> capture_end_event(new FrameEvent()); + capture_end_event->timestamp = now; + capture_end_event->type = FRAME_CAPTURE_END; + capture_end_event->media_type = VIDEO_EVENT; + capture_end_event->rtp_timestamp = rtp_timestamp + 30; + capture_end_event->width = 1280; + capture_end_event->height = 720; + cast_environment_->logger()->DispatchFrameEvent(capture_end_event.Pass()); GetEventsAndReset(); @@ -614,12 +688,15 @@ TEST_F(EncodingEventSubscriberTest, MaxEventsPerProto) { Init(VIDEO_EVENT); RtpTimestamp rtp_timestamp = 100; for (int i = 0; i < kMaxEventsPerProto + 1; i++) { - cast_environment_->Logging()->InsertFrameEvent(testing_clock_->NowTicks(), - FRAME_ACK_RECEIVED, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0); - testing_clock_->Advance(base::TimeDelta::FromMilliseconds(30)); + scoped_ptr<FrameEvent> ack_event(new FrameEvent()); + ack_event->timestamp = testing_clock_->NowTicks(); + ack_event->type = FRAME_ACK_RECEIVED; + ack_event->media_type = VIDEO_EVENT; + ack_event->rtp_timestamp = rtp_timestamp; + ack_event->frame_id = 0; + cast_environment_->logger()->DispatchFrameEvent(ack_event.Pass()); + + task_runner_->Sleep(base::TimeDelta::FromMilliseconds(30)); } GetEventsAndReset(); @@ -633,16 +710,18 @@ TEST_F(EncodingEventSubscriberTest, MaxEventsPerProto) { EXPECT_EQ(kMaxEventsPerProto, frame_event->event_type_size()); for (int i = 0; i < kMaxPacketsPerFrame + 1; i++) { - cast_environment_->Logging()->InsertPacketEvent( - testing_clock_->NowTicks(), - PACKET_SENT_TO_NETWORK, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0, - i, - kMaxPacketsPerFrame, - 123); - testing_clock_->Advance(base::TimeDelta::FromMilliseconds(30)); + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = testing_clock_->NowTicks(); + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp; + send_event->frame_id = 0; + send_event->packet_id = i; + send_event->max_packet_id = kMaxPacketsPerFrame; + send_event->size = 123; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); + + task_runner_->Sleep(base::TimeDelta::FromMilliseconds(30)); } GetEventsAndReset(); @@ -662,16 +741,18 @@ TEST_F(EncodingEventSubscriberTest, MaxEventsPerProto) { EXPECT_EQ(1, packet_event->base_packet_event_size()); for (int j = 0; j < kMaxEventsPerProto + 1; j++) { - cast_environment_->Logging()->InsertPacketEvent( - testing_clock_->NowTicks(), - PACKET_SENT_TO_NETWORK, - VIDEO_EVENT, - rtp_timestamp, - /*frame_id*/ 0, - 0, - 0, - 123); - testing_clock_->Advance(base::TimeDelta::FromMilliseconds(30)); + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = testing_clock_->NowTicks(); + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp; + send_event->frame_id = 0; + send_event->packet_id = 0; + send_event->max_packet_id = 0; + send_event->size = 123; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); + + task_runner_->Sleep(base::TimeDelta::FromMilliseconds(30)); } GetEventsAndReset(); diff --git a/media/cast/logging/log_event_dispatcher.cc b/media/cast/logging/log_event_dispatcher.cc new file mode 100644 index 0000000..ac0e9ab --- /dev/null +++ b/media/cast/logging/log_event_dispatcher.cc @@ -0,0 +1,137 @@ +// Copyright 2015 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/log_event_dispatcher.h" + +#include <algorithm> + +#include "base/bind.h" +#include "base/bind_helpers.h" +#include "base/location.h" +#include "base/synchronization/waitable_event.h" +#include "media/cast/cast_environment.h" + +namespace media { +namespace cast { + +LogEventDispatcher::LogEventDispatcher(CastEnvironment* env) + : env_(env), impl_(new Impl()) { + DCHECK(env_); +} + +LogEventDispatcher::~LogEventDispatcher() {} + +void LogEventDispatcher::DispatchFrameEvent( + scoped_ptr<FrameEvent> event) const { + if (env_->CurrentlyOn(CastEnvironment::MAIN)) { + impl_->DispatchFrameEvent(event.Pass()); + } else { + env_->PostTask(CastEnvironment::MAIN, FROM_HERE, + base::Bind(&LogEventDispatcher::Impl::DispatchFrameEvent, + impl_, base::Passed(&event))); + } +} + +void LogEventDispatcher::DispatchPacketEvent( + scoped_ptr<PacketEvent> event) const { + if (env_->CurrentlyOn(CastEnvironment::MAIN)) { + impl_->DispatchPacketEvent(event.Pass()); + } else { + env_->PostTask(CastEnvironment::MAIN, FROM_HERE, + base::Bind(&LogEventDispatcher::Impl::DispatchPacketEvent, + impl_, base::Passed(&event))); + } +} + +void LogEventDispatcher::DispatchBatchOfEvents( + scoped_ptr<std::vector<FrameEvent>> frame_events, + scoped_ptr<std::vector<PacketEvent>> packet_events) const { + if (env_->CurrentlyOn(CastEnvironment::MAIN)) { + impl_->DispatchBatchOfEvents(frame_events.Pass(), packet_events.Pass()); + } else { + env_->PostTask( + CastEnvironment::MAIN, FROM_HERE, + base::Bind(&LogEventDispatcher::Impl::DispatchBatchOfEvents, impl_, + base::Passed(&frame_events), base::Passed(&packet_events))); + } +} + +void LogEventDispatcher::Subscribe(RawEventSubscriber* subscriber) { + if (env_->CurrentlyOn(CastEnvironment::MAIN)) { + impl_->Subscribe(subscriber); + } else { + env_->PostTask( + CastEnvironment::MAIN, FROM_HERE, + base::Bind(&LogEventDispatcher::Impl::Subscribe, impl_, subscriber)); + } +} + +void LogEventDispatcher::Unsubscribe(RawEventSubscriber* subscriber) { + if (env_->CurrentlyOn(CastEnvironment::MAIN)) { + impl_->Unsubscribe(subscriber); + } else { + // This method, once it returns, guarantees |subscriber| will not receive + // any more events. Therefore, when called on a thread other than the + // CastEnvironment's MAIN thread, block until the unsubscribe task + // completes. + struct Helper { + static void UnsubscribeAndSignal(const scoped_refptr<Impl>& impl, + RawEventSubscriber* subscriber, + base::WaitableEvent* done) { + impl->Unsubscribe(subscriber); + done->Signal(); + } + }; + base::WaitableEvent done(true, false); + CHECK(env_->PostTask( + CastEnvironment::MAIN, FROM_HERE, + base::Bind(&Helper::UnsubscribeAndSignal, impl_, subscriber, &done))); + done.Wait(); + } +} + +LogEventDispatcher::Impl::Impl() {} + +LogEventDispatcher::Impl::~Impl() { + DCHECK(subscribers_.empty()); +} + +void LogEventDispatcher::Impl::DispatchFrameEvent( + scoped_ptr<FrameEvent> event) const { + for (RawEventSubscriber* s : subscribers_) + s->OnReceiveFrameEvent(*event); +} + +void LogEventDispatcher::Impl::DispatchPacketEvent( + scoped_ptr<PacketEvent> event) const { + for (RawEventSubscriber* s : subscribers_) + s->OnReceivePacketEvent(*event); +} + +void LogEventDispatcher::Impl::DispatchBatchOfEvents( + scoped_ptr<std::vector<FrameEvent>> frame_events, + scoped_ptr<std::vector<PacketEvent>> packet_events) const { + for (RawEventSubscriber* s : subscribers_) { + for (const FrameEvent& e : *frame_events) + s->OnReceiveFrameEvent(e); + for (const PacketEvent& e : *packet_events) + s->OnReceivePacketEvent(e); + } +} + +void LogEventDispatcher::Impl::Subscribe(RawEventSubscriber* subscriber) { + DCHECK(std::find(subscribers_.begin(), subscribers_.end(), subscriber) == + subscribers_.end()); + subscribers_.push_back(subscriber); +} + +void LogEventDispatcher::Impl::Unsubscribe(RawEventSubscriber* subscriber) { + const auto it = + std::find(subscribers_.begin(), subscribers_.end(), subscriber); + DCHECK(it != subscribers_.end()); + subscribers_.erase(it); +} + +} // namespace cast +} // namespace media diff --git a/media/cast/logging/log_event_dispatcher.h b/media/cast/logging/log_event_dispatcher.h new file mode 100644 index 0000000..d84e79b --- /dev/null +++ b/media/cast/logging/log_event_dispatcher.h @@ -0,0 +1,81 @@ +// Copyright 2015 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_LOG_EVENT_DISPATCHER_H_ +#define MEDIA_CAST_LOGGING_LOG_EVENT_DISPATCHER_H_ + +#include <vector> + +#include "base/macros.h" +#include "base/memory/ref_counted.h" +#include "base/memory/scoped_ptr.h" +#include "media/cast/logging/logging_defines.h" +#include "media/cast/logging/raw_event_subscriber.h" + +namespace media { +namespace cast { + +class CastEnvironment; + +// A thread-safe receiver of logging events that manages an active list of +// EventSubscribers and dispatches the logging events to them on the MAIN +// thread. All methods, constructor, and destructor can be invoked on any +// thread. +class LogEventDispatcher { + public: + // |env| outlives this instance (and generally owns this instance). + explicit LogEventDispatcher(CastEnvironment* env); + + ~LogEventDispatcher(); + + // Called on any thread to schedule the sending of event(s) to all + // EventSubscribers on the MAIN thread. + void DispatchFrameEvent(scoped_ptr<FrameEvent> event) const; + void DispatchPacketEvent(scoped_ptr<PacketEvent> event) const; + void DispatchBatchOfEvents( + scoped_ptr<std::vector<FrameEvent>> frame_events, + scoped_ptr<std::vector<PacketEvent>> packet_events) const; + + // Adds |subscriber| to the active list to begin receiving events on MAIN + // thread. Unsubscribe() must be called before |subscriber| is destroyed. + void Subscribe(RawEventSubscriber* subscriber); + + // Removes |subscriber| from the active list. Once this method returns, the + // |subscriber| is guaranteed not to receive any more events. + void Unsubscribe(RawEventSubscriber* subscriber); + + private: + // The part of the implementation that runs exclusively on the MAIN thread. + class Impl : public base::RefCountedThreadSafe<Impl> { + public: + Impl(); + + void DispatchFrameEvent(scoped_ptr<FrameEvent> event) const; + void DispatchPacketEvent(scoped_ptr<PacketEvent> event) const; + void DispatchBatchOfEvents( + scoped_ptr<std::vector<FrameEvent>> frame_events, + scoped_ptr<std::vector<PacketEvent>> packet_events) const; + void Subscribe(RawEventSubscriber* subscriber); + void Unsubscribe(RawEventSubscriber* subscriber); + + private: + friend class base::RefCountedThreadSafe<Impl>; + + ~Impl(); + + std::vector<RawEventSubscriber*> subscribers_; + + DISALLOW_COPY_AND_ASSIGN(Impl); + }; + + CastEnvironment* const env_; // Owner of this instance. + const scoped_refptr<Impl> impl_; + + DISALLOW_COPY_AND_ASSIGN(LogEventDispatcher); +}; + +} // namespace cast +} // namespace media + +#endif // MEDIA_CAST_LOGGING_LOG_EVENT_DISPATCHER_H_ diff --git a/media/cast/logging/logging_impl.cc b/media/cast/logging/logging_impl.cc deleted file mode 100644 index b64674f..0000000 --- a/media/cast/logging/logging_impl.cc +++ /dev/null @@ -1,131 +0,0 @@ -// Copyright 2013 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/big_endian.h" -#include "base/trace_event/trace_event.h" -#include "media/cast/logging/logging_impl.h" - -namespace media { -namespace cast { - -// TODO(imcheng): Collapse LoggingRaw onto LoggingImpl. -LoggingImpl::LoggingImpl() { - // LoggingImpl can be constructed on any thread, but its methods should all be - // called on the same thread. - thread_checker_.DetachFromThread(); -} - -LoggingImpl::~LoggingImpl() {} - -void LoggingImpl::InsertFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, - uint32 frame_id) { - DCHECK(thread_checker_.CalledOnValidThread()); - raw_.InsertFrameEvent(time_of_event, event, event_media_type, - rtp_timestamp, frame_id); -} - -void LoggingImpl::InsertCapturedVideoFrameEvent( - const base::TimeTicks& time_of_event, - uint32 rtp_timestamp, - int width, - int height) { - DCHECK(thread_checker_.CalledOnValidThread()); - raw_.InsertCapturedVideoFrameEvent( - time_of_event, rtp_timestamp, width, height); -} - - -void LoggingImpl::InsertEncodedFrameEvent( - const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, - uint32 frame_id, - int encoded_size, - bool key_frame, - int target_bitrate, - double encoder_cpu_utilization, - double idealized_bitrate_utilization) { - DCHECK(thread_checker_.CalledOnValidThread()); - raw_.InsertEncodedFrameEvent(time_of_event, event, event_media_type, - rtp_timestamp, frame_id, encoded_size, key_frame, target_bitrate, - encoder_cpu_utilization, idealized_bitrate_utilization); -} - -void LoggingImpl::InsertFrameEventWithDelay( - const base::TimeTicks& time_of_event, CastLoggingEvent event, - EventMediaType event_media_type, uint32 rtp_timestamp, uint32 frame_id, - base::TimeDelta delay) { - DCHECK(thread_checker_.CalledOnValidThread()); - raw_.InsertFrameEventWithDelay(time_of_event, event, event_media_type, - rtp_timestamp, frame_id, delay); -} - -void LoggingImpl::InsertSinglePacketEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - const Packet& packet) { - DCHECK(thread_checker_.CalledOnValidThread()); - - // Parse basic properties. - uint32 rtp_timestamp; - uint16 packet_id, max_packet_id; - const uint8* packet_data = &packet[0]; - base::BigEndianReader big_endian_reader( - reinterpret_cast<const char*>(packet_data + 4), 4); - big_endian_reader.ReadU32(&rtp_timestamp); - base::BigEndianReader cast_big_endian_reader( - reinterpret_cast<const char*>(packet_data + 12 + 2), 4); - cast_big_endian_reader.ReadU16(&packet_id); - cast_big_endian_reader.ReadU16(&max_packet_id); - - // rtp_timestamp is enough - no need for frame_id as well. - InsertPacketEvent(time_of_event, - event, - event_media_type, - rtp_timestamp, - kFrameIdUnknown, - packet_id, - max_packet_id, - packet.size()); -} - -void LoggingImpl::InsertPacketListEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - const PacketList& packets) { - DCHECK(thread_checker_.CalledOnValidThread()); - for (PacketList::const_iterator it = packets.begin(); it != packets.end(); - ++it) { - InsertSinglePacketEvent(time_of_event, event, event_media_type, - (*it)->data); - } -} - -void LoggingImpl::InsertPacketEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, uint32 frame_id, - uint16 packet_id, uint16 max_packet_id, - size_t size) { - DCHECK(thread_checker_.CalledOnValidThread()); - raw_.InsertPacketEvent(time_of_event, event, event_media_type, - rtp_timestamp, frame_id, packet_id, max_packet_id, size); -} - -void LoggingImpl::AddRawEventSubscriber(RawEventSubscriber* subscriber) { - DCHECK(thread_checker_.CalledOnValidThread()); - raw_.AddSubscriber(subscriber); -} - -void LoggingImpl::RemoveRawEventSubscriber(RawEventSubscriber* subscriber) { - DCHECK(thread_checker_.CalledOnValidThread()); - raw_.RemoveSubscriber(subscriber); -} - -} // namespace cast -} // namespace media diff --git a/media/cast/logging/logging_impl.h b/media/cast/logging/logging_impl.h deleted file mode 100644 index 1fc3e76..0000000 --- a/media/cast/logging/logging_impl.h +++ /dev/null @@ -1,86 +0,0 @@ -// Copyright 2013 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_LOGGING_IMPL_H_ -#define MEDIA_CAST_LOGGING_LOGGING_IMPL_H_ - -// Generic class that handles event logging for the cast library. -// Logging has three possible optional forms: -// 1. Raw data and stats accessible by the application. -// 2. Tracing of raw events. - -#include "base/memory/ref_counted.h" -#include "base/threading/thread_checker.h" -#include "media/cast/cast_config.h" -#include "media/cast/logging/logging_defines.h" -#include "media/cast/logging/logging_raw.h" - -namespace media { -namespace cast { - -class LoggingImpl { - public: - LoggingImpl(); - ~LoggingImpl(); - - // Note: All methods below should be called from the same thread. - - void InsertFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, EventMediaType event_media_type, - uint32 rtp_timestamp, uint32 frame_id); - - void InsertCapturedVideoFrameEvent(const base::TimeTicks& time_of_event, - uint32 rtp_timestamp, - int width, - int height); - - void InsertEncodedFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, - uint32 frame_id, - int encoded_size, - bool key_frame, - int target_bitrate, - double encoder_cpu_utilization, - double idealized_bitrate_utilization); - - void InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, uint32 frame_id, - base::TimeDelta delay); - - void InsertSinglePacketEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - const Packet& packet); - - void InsertPacketListEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - const PacketList& packets); - - void InsertPacketEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, uint32 rtp_timestamp, - uint32 frame_id, uint16 packet_id, - uint16 max_packet_id, size_t size); - - // Delegates to |LoggingRaw::AddRawEventSubscriber()|. - void AddRawEventSubscriber(RawEventSubscriber* subscriber); - - // Delegates to |LoggingRaw::RemoveRawEventSubscriber()|. - void RemoveRawEventSubscriber(RawEventSubscriber* subscriber); - - private: - base::ThreadChecker thread_checker_; - LoggingRaw raw_; - - DISALLOW_COPY_AND_ASSIGN(LoggingImpl); -}; - -} // namespace cast -} // namespace media - -#endif // MEDIA_CAST_LOGGING_LOGGING_IMPL_H_ diff --git a/media/cast/logging/logging_impl_unittest.cc b/media/cast/logging/logging_impl_unittest.cc deleted file mode 100644 index fb2779c..0000000 --- a/media/cast/logging/logging_impl_unittest.cc +++ /dev/null @@ -1,235 +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 <stdint.h> - -#include <vector> - -#include "base/rand_util.h" -#include "base/test/simple_test_tick_clock.h" -#include "base/time/tick_clock.h" -#include "base/time/time.h" -#include "media/cast/logging/logging_defines.h" -#include "media/cast/logging/logging_impl.h" -#include "media/cast/logging/simple_event_subscriber.h" -#include "testing/gtest/include/gtest/gtest.h" - -namespace media { -namespace cast { - -// Insert frame duration- one second. -const int64 kIntervalTime1S = 1; -// Test frame rate goal - 30fps. -const int kFrameIntervalMs = 33; - -static const int64 kStartMillisecond = INT64_C(12345678900000); - -class LoggingImplTest : public ::testing::Test { - protected: - LoggingImplTest() { - testing_clock_.Advance( - base::TimeDelta::FromMilliseconds(kStartMillisecond)); - logging_.AddRawEventSubscriber(&event_subscriber_); - } - - ~LoggingImplTest() override { - logging_.RemoveRawEventSubscriber(&event_subscriber_); - } - - LoggingImpl logging_; - base::SimpleTestTickClock testing_clock_; - SimpleEventSubscriber event_subscriber_; - - DISALLOW_COPY_AND_ASSIGN(LoggingImplTest); -}; - -TEST_F(LoggingImplTest, BasicFrameLogging) { - base::TimeTicks start_time = testing_clock_.NowTicks(); - base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time; - uint32 rtp_timestamp = 0; - uint32 frame_id = 0; - base::TimeTicks now; - do { - now = testing_clock_.NowTicks(); - logging_.InsertFrameEvent( - now, FRAME_CAPTURE_BEGIN, VIDEO_EVENT, rtp_timestamp, frame_id); - testing_clock_.Advance( - base::TimeDelta::FromMilliseconds(kFrameIntervalMs)); - rtp_timestamp += kFrameIntervalMs * 90; - ++frame_id; - time_interval = now - start_time; - } while (time_interval.InSeconds() < kIntervalTime1S); - - // Get logging data. - std::vector<FrameEvent> frame_events; - event_subscriber_.GetFrameEventsAndReset(&frame_events); - // Size of vector should be equal to the number of events logged, - // which equals to number of frames in this case. - EXPECT_EQ(frame_id, frame_events.size()); -} - -TEST_F(LoggingImplTest, FrameLoggingWithSize) { - // Average packet size. - const int kBaseFrameSizeBytes = 25000; - const int kRandomSizeInterval = 100; - base::TimeTicks start_time = testing_clock_.NowTicks(); - base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time; - uint32 rtp_timestamp = 0; - uint32 frame_id = 0; - size_t sum_size = 0; - int target_bitrate = 1234; - do { - int size = kBaseFrameSizeBytes + - base::RandInt(-kRandomSizeInterval, kRandomSizeInterval); - sum_size += static_cast<size_t>(size); - logging_.InsertEncodedFrameEvent(testing_clock_.NowTicks(), - FRAME_ENCODED, VIDEO_EVENT, rtp_timestamp, - frame_id, size, true, target_bitrate, - 0.1, 2.3); - testing_clock_.Advance(base::TimeDelta::FromMilliseconds(kFrameIntervalMs)); - rtp_timestamp += kFrameIntervalMs * 90; - ++frame_id; - time_interval = testing_clock_.NowTicks() - start_time; - } while (time_interval.InSeconds() < kIntervalTime1S); - // Get logging data. - std::vector<FrameEvent> frame_events; - event_subscriber_.GetFrameEventsAndReset(&frame_events); - // Size of vector should be equal to the number of events logged, which - // equals to number of frames in this case. - EXPECT_EQ(frame_id, frame_events.size()); -} - -TEST_F(LoggingImplTest, FrameLoggingWithDelay) { - // Average packet size. - const int kPlayoutDelayMs = 50; - const int kRandomSizeInterval = 20; - base::TimeTicks start_time = testing_clock_.NowTicks(); - base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time; - uint32 rtp_timestamp = 0; - uint32 frame_id = 0; - do { - int delay = kPlayoutDelayMs + - base::RandInt(-kRandomSizeInterval, kRandomSizeInterval); - logging_.InsertFrameEventWithDelay( - testing_clock_.NowTicks(), - FRAME_CAPTURE_BEGIN, - VIDEO_EVENT, - rtp_timestamp, - frame_id, - base::TimeDelta::FromMilliseconds(delay)); - testing_clock_.Advance(base::TimeDelta::FromMilliseconds(kFrameIntervalMs)); - rtp_timestamp += kFrameIntervalMs * 90; - ++frame_id; - time_interval = testing_clock_.NowTicks() - start_time; - } while (time_interval.InSeconds() < kIntervalTime1S); - // Get logging data. - std::vector<FrameEvent> frame_events; - event_subscriber_.GetFrameEventsAndReset(&frame_events); - // Size of vector should be equal to the number of frames logged. - EXPECT_EQ(frame_id, frame_events.size()); -} - -TEST_F(LoggingImplTest, MultipleEventFrameLogging) { - base::TimeTicks start_time = testing_clock_.NowTicks(); - base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time; - uint32 rtp_timestamp = 0u; - uint32 frame_id = 0u; - uint32 num_events = 0u; - do { - logging_.InsertFrameEvent(testing_clock_.NowTicks(), - FRAME_CAPTURE_END, - VIDEO_EVENT, - rtp_timestamp, - frame_id); - ++num_events; - if (frame_id % 2) { - logging_.InsertEncodedFrameEvent(testing_clock_.NowTicks(), - FRAME_ENCODED, AUDIO_EVENT, - rtp_timestamp, - frame_id, 1500, true, 0, 4.5, 6.7); - } else if (frame_id % 3) { - logging_.InsertFrameEvent(testing_clock_.NowTicks(), FRAME_DECODED, - VIDEO_EVENT, rtp_timestamp, frame_id); - } else { - logging_.InsertFrameEventWithDelay( - testing_clock_.NowTicks(), FRAME_PLAYOUT, VIDEO_EVENT, - rtp_timestamp, frame_id, base::TimeDelta::FromMilliseconds(20)); - } - ++num_events; - - testing_clock_.Advance(base::TimeDelta::FromMilliseconds(kFrameIntervalMs)); - rtp_timestamp += kFrameIntervalMs * 90; - ++frame_id; - time_interval = testing_clock_.NowTicks() - start_time; - } while (time_interval.InSeconds() < kIntervalTime1S); - // Get logging data. - std::vector<FrameEvent> frame_events; - event_subscriber_.GetFrameEventsAndReset(&frame_events); - // Size of vector should be equal to the number of frames logged. - EXPECT_EQ(num_events, frame_events.size()); - // Multiple events captured per frame. -} - -TEST_F(LoggingImplTest, PacketLogging) { - const int kNumPacketsPerFrame = 10; - const int kBaseSize = 2500; - const int kSizeInterval = 100; - base::TimeTicks start_time = testing_clock_.NowTicks(); - base::TimeTicks latest_time; - base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time; - RtpTimestamp rtp_timestamp = 0; - int frame_id = 0; - int num_packets = 0; - int sum_size = 0u; - do { - for (int i = 0; i < kNumPacketsPerFrame; ++i) { - int size = kBaseSize + base::RandInt(-kSizeInterval, kSizeInterval); - sum_size += size; - latest_time = testing_clock_.NowTicks(); - ++num_packets; - logging_.InsertPacketEvent(latest_time, - PACKET_RECEIVED, - VIDEO_EVENT, - rtp_timestamp, - frame_id, - i, - kNumPacketsPerFrame, - size); - } - testing_clock_.Advance(base::TimeDelta::FromMilliseconds(kFrameIntervalMs)); - rtp_timestamp += kFrameIntervalMs * 90; - ++frame_id; - time_interval = testing_clock_.NowTicks() - start_time; - } while (time_interval.InSeconds() < kIntervalTime1S); - // Get logging data. - std::vector<PacketEvent> packet_events; - event_subscriber_.GetPacketEventsAndReset(&packet_events); - // Size of vector should be equal to the number of packets logged. - EXPECT_EQ(num_packets, static_cast<int>(packet_events.size())); -} - -TEST_F(LoggingImplTest, MultipleRawEventSubscribers) { - SimpleEventSubscriber event_subscriber_2; - - // Now logging_ has two subscribers. - logging_.AddRawEventSubscriber(&event_subscriber_2); - - logging_.InsertFrameEvent(testing_clock_.NowTicks(), - FRAME_CAPTURE_BEGIN, - VIDEO_EVENT, - /*rtp_timestamp*/ 0u, - /*frame_id*/ 0u); - - std::vector<FrameEvent> frame_events; - event_subscriber_.GetFrameEventsAndReset(&frame_events); - EXPECT_EQ(1u, frame_events.size()); - frame_events.clear(); - event_subscriber_2.GetFrameEventsAndReset(&frame_events); - EXPECT_EQ(1u, frame_events.size()); - - logging_.RemoveRawEventSubscriber(&event_subscriber_2); -} - -} // namespace cast -} // namespace media diff --git a/media/cast/logging/logging_raw.cc b/media/cast/logging/logging_raw.cc deleted file mode 100644 index b80c05e..0000000 --- a/media/cast/logging/logging_raw.cc +++ /dev/null @@ -1,140 +0,0 @@ -// Copyright 2013 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/logging_raw.h" - -#include <algorithm> - -#include "base/logging.h" -#include "base/time/time.h" - -namespace media { -namespace cast { - -LoggingRaw::LoggingRaw() {} - -LoggingRaw::~LoggingRaw() {} - -void LoggingRaw::InsertFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, - uint32 frame_id) { - InsertBaseFrameEvent(time_of_event, event, event_media_type, frame_id, - rtp_timestamp, base::TimeDelta(), 0, 0, 0, false, 0, - -1.0, -1.0); -} - -void LoggingRaw::InsertCapturedVideoFrameEvent( - const base::TimeTicks& time_of_event, - uint32 rtp_timestamp, - int width, - int height) { - InsertBaseFrameEvent(time_of_event, FRAME_CAPTURE_END, VIDEO_EVENT, - kFrameIdUnknown, rtp_timestamp, base::TimeDelta(), width, - height, 0, false, 0, -1.0, -1.0); -} - -void LoggingRaw::InsertEncodedFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, - uint32 frame_id, - int encoded_size, - bool key_frame, - int target_bitrate, - double encoder_cpu_utilization, - double idealized_bitrate_utilization) { - InsertBaseFrameEvent(time_of_event, event, event_media_type, - frame_id, rtp_timestamp, base::TimeDelta(), - 0, 0, encoded_size, key_frame, target_bitrate, - encoder_cpu_utilization, idealized_bitrate_utilization); -} - -void LoggingRaw::InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, - uint32 frame_id, - base::TimeDelta delay) { - InsertBaseFrameEvent(time_of_event, event, event_media_type, frame_id, - rtp_timestamp, delay, 0, 0, 0, false, 0, -1.0, -1.0); -} - -void LoggingRaw::InsertBaseFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 frame_id, - uint32 rtp_timestamp, - base::TimeDelta delay, - int width, - int height, - int encoded_size, - bool key_frame, - int target_bitrate, - double encoder_cpu_utilization, - double idealized_bitrate_utilization) { - FrameEvent frame_event; - frame_event.rtp_timestamp = rtp_timestamp; - frame_event.frame_id = frame_id; - frame_event.width = width; - frame_event.height = height; - frame_event.size = encoded_size; - frame_event.timestamp = time_of_event; - frame_event.type = event; - frame_event.media_type = event_media_type; - frame_event.delay_delta = delay; - frame_event.key_frame = key_frame; - frame_event.target_bitrate = target_bitrate; - frame_event.encoder_cpu_utilization = encoder_cpu_utilization; - frame_event.idealized_bitrate_utilization = idealized_bitrate_utilization; - for (std::vector<RawEventSubscriber*>::const_iterator it = - subscribers_.begin(); - it != subscribers_.end(); ++it) { - (*it)->OnReceiveFrameEvent(frame_event); - } -} - -void LoggingRaw::InsertPacketEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, - uint32 frame_id, uint16 packet_id, - uint16 max_packet_id, size_t size) { - PacketEvent packet_event; - packet_event.rtp_timestamp = rtp_timestamp; - packet_event.frame_id = frame_id; - packet_event.max_packet_id = max_packet_id; - packet_event.packet_id = packet_id; - packet_event.size = size; - packet_event.timestamp = time_of_event; - packet_event.type = event; - packet_event.media_type = event_media_type; - for (std::vector<RawEventSubscriber*>::const_iterator it = - subscribers_.begin(); - it != subscribers_.end(); ++it) { - (*it)->OnReceivePacketEvent(packet_event); - } -} - -void LoggingRaw::AddSubscriber(RawEventSubscriber* subscriber) { - DCHECK(subscriber); - DCHECK(std::find(subscribers_.begin(), subscribers_.end(), subscriber) == - subscribers_.end()); - - subscribers_.push_back(subscriber); -} - -void LoggingRaw::RemoveSubscriber(RawEventSubscriber* subscriber) { - DCHECK(subscriber); - DCHECK(std::find(subscribers_.begin(), subscribers_.end(), subscriber) != - subscribers_.end()); - - subscribers_.erase( - std::remove(subscribers_.begin(), subscribers_.end(), subscriber), - subscribers_.end()); -} - -} // namespace cast -} // namespace media diff --git a/media/cast/logging/logging_raw.h b/media/cast/logging/logging_raw.h deleted file mode 100644 index 49ec985..0000000 --- a/media/cast/logging/logging_raw.h +++ /dev/null @@ -1,106 +0,0 @@ -// Copyright 2013 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_LOGGING_RAW_H_ -#define MEDIA_CAST_LOGGING_LOGGING_RAW_H_ - -#include <vector> - -#include "base/basictypes.h" -#include "base/memory/linked_ptr.h" -#include "base/threading/non_thread_safe.h" -#include "base/time/tick_clock.h" -#include "media/cast/logging/logging_defines.h" -#include "media/cast/logging/raw_event_subscriber.h" - -namespace media { -namespace cast { - -// This class is not thread safe, and should only be called from the main -// thread. -class LoggingRaw : public base::NonThreadSafe { - public: - LoggingRaw(); - ~LoggingRaw(); - - // Inform of new event: two types of events: frame and packet. - // Frame events can be inserted with different parameters. - void InsertFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, EventMediaType event_media_type, - uint32 rtp_timestamp, uint32 frame_id); - - // Inserts a FRAME_CAPTURE_END event with the VIDEO_EVENT media type. - void InsertCapturedVideoFrameEvent(const base::TimeTicks& time_of_event, - uint32 rtp_timestamp, - int width, - int height); - - // This function is only applicable for FRAME_ENCODED event. - // |encoded_size| - Size of encoded frame in bytes. - // |key_frame| - Whether the frame is a key frame. This field is only - // applicable for video event. - // |target_bitrate| - The target bitrate of the encoder the time the frame - // was encoded. Only applicable for video event. - void InsertEncodedFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, - uint32 frame_id, - int encoded_size, - bool key_frame, - int target_bitrate, - double encoder_cpu_utilization, - double idealized_bitrate_utilization); - - // Render/playout delay - // This function is only applicable for FRAME_PLAYOUT event. - void InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 rtp_timestamp, - uint32 frame_id, base::TimeDelta delay); - - // Insert a packet event. - void InsertPacketEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, uint32 rtp_timestamp, - uint32 frame_id, uint16 packet_id, - uint16 max_packet_id, size_t size); - - // Adds |subscriber| so that it will start receiving events on main thread. - // Note that this class does not own |subscriber|. - // It is a no-op to add a subscriber that already exists. - void AddSubscriber(RawEventSubscriber* subscriber); - - // Removes |subscriber| so that it will stop receiving events. - // Note that this class does NOT own the subscribers. This function MUST be - // called before |subscriber| is destroyed if it was previously added. - // It is a no-op to remove a subscriber that doesn't exist. - void RemoveSubscriber(RawEventSubscriber* subscriber); - - private: - void InsertBaseFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - EventMediaType event_media_type, - uint32 frame_id, - uint32 rtp_timestamp, - base::TimeDelta delay, - int width, - int height, - int encoded_size, - bool key_frame, - int target_bitrate, - double encoder_cpu_utilization, - double idealized_bitrate_utilization); - - // List of subscriber pointers. This class does not own the subscribers. - std::vector<RawEventSubscriber*> subscribers_; - - DISALLOW_COPY_AND_ASSIGN(LoggingRaw); -}; - -} // namespace cast -} // namespace media - -#endif // MEDIA_CAST_LOGGING_LOGGING_RAW_H_ diff --git a/media/cast/logging/logging_raw_unittest.cc b/media/cast/logging/logging_raw_unittest.cc deleted file mode 100644 index 0ecfbbf..0000000 --- a/media/cast/logging/logging_raw_unittest.cc +++ /dev/null @@ -1,202 +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/logging_defines.h" -#include "media/cast/logging/logging_raw.h" -#include "media/cast/logging/simple_event_subscriber.h" -#include "testing/gtest/include/gtest/gtest.h" - -namespace media { -namespace cast { - -class LoggingRawTest : public ::testing::Test { - protected: - LoggingRawTest() { - raw_.AddSubscriber(&event_subscriber_); - } - - ~LoggingRawTest() override { raw_.RemoveSubscriber(&event_subscriber_); } - - LoggingRaw raw_; - SimpleEventSubscriber event_subscriber_; - std::vector<FrameEvent> frame_events_; - std::vector<PacketEvent> packet_events_; -}; - -TEST_F(LoggingRawTest, FrameEvent) { - CastLoggingEvent event_type = FRAME_DECODED; - EventMediaType media_type = VIDEO_EVENT; - uint32 frame_id = 456u; - RtpTimestamp rtp_timestamp = 123u; - base::TimeTicks timestamp = base::TimeTicks(); - raw_.InsertFrameEvent(timestamp, event_type, media_type, - rtp_timestamp, frame_id); - - event_subscriber_.GetPacketEventsAndReset(&packet_events_); - EXPECT_TRUE(packet_events_.empty()); - - event_subscriber_.GetFrameEventsAndReset(&frame_events_); - ASSERT_EQ(1u, frame_events_.size()); - EXPECT_EQ(rtp_timestamp, frame_events_[0].rtp_timestamp); - EXPECT_EQ(frame_id, frame_events_[0].frame_id); - EXPECT_EQ(0u, frame_events_[0].size); - EXPECT_EQ(timestamp, frame_events_[0].timestamp); - EXPECT_EQ(event_type, frame_events_[0].type); - EXPECT_EQ(media_type, frame_events_[0].media_type); - EXPECT_EQ(base::TimeDelta(), frame_events_[0].delay_delta); -} - -TEST_F(LoggingRawTest, EncodedFrameEvent) { - CastLoggingEvent event_type = FRAME_ENCODED; - EventMediaType media_type = VIDEO_EVENT; - uint32 frame_id = 456u; - RtpTimestamp rtp_timestamp = 123u; - base::TimeTicks timestamp = base::TimeTicks(); - int size = 1024; - bool key_frame = true; - int target_bitrate = 4096; - double encoder_cpu_utilization = 0.11; - double idealized_bitrate_utilization = 0.98; - raw_.InsertEncodedFrameEvent(timestamp, event_type, media_type, - rtp_timestamp, frame_id, size, key_frame, target_bitrate, - encoder_cpu_utilization, idealized_bitrate_utilization); - - event_subscriber_.GetPacketEventsAndReset(&packet_events_); - EXPECT_TRUE(packet_events_.empty()); - - event_subscriber_.GetFrameEventsAndReset(&frame_events_); - ASSERT_EQ(1u, frame_events_.size()); - EXPECT_EQ(rtp_timestamp, frame_events_[0].rtp_timestamp); - EXPECT_EQ(frame_id, frame_events_[0].frame_id); - EXPECT_EQ(size, static_cast<int>(frame_events_[0].size)); - EXPECT_EQ(timestamp, frame_events_[0].timestamp); - EXPECT_EQ(event_type, frame_events_[0].type); - EXPECT_EQ(media_type, frame_events_[0].media_type); - EXPECT_EQ(base::TimeDelta(), frame_events_[0].delay_delta); - EXPECT_EQ(key_frame, frame_events_[0].key_frame); - EXPECT_EQ(target_bitrate, frame_events_[0].target_bitrate); - EXPECT_EQ(encoder_cpu_utilization, frame_events_[0].encoder_cpu_utilization); - EXPECT_EQ(idealized_bitrate_utilization, - frame_events_[0].idealized_bitrate_utilization); -} - -TEST_F(LoggingRawTest, FrameEventWithDelay) { - CastLoggingEvent event_type = FRAME_PLAYOUT; - EventMediaType media_type = VIDEO_EVENT; - uint32 frame_id = 456u; - RtpTimestamp rtp_timestamp = 123u; - base::TimeTicks timestamp = base::TimeTicks(); - base::TimeDelta delay = base::TimeDelta::FromMilliseconds(20); - raw_.InsertFrameEventWithDelay(timestamp, event_type, media_type, - rtp_timestamp, frame_id, delay); - - event_subscriber_.GetPacketEventsAndReset(&packet_events_); - EXPECT_TRUE(packet_events_.empty()); - - event_subscriber_.GetFrameEventsAndReset(&frame_events_); - ASSERT_EQ(1u, frame_events_.size()); - EXPECT_EQ(rtp_timestamp, frame_events_[0].rtp_timestamp); - EXPECT_EQ(frame_id, frame_events_[0].frame_id); - EXPECT_EQ(0u, frame_events_[0].size); - EXPECT_EQ(timestamp, frame_events_[0].timestamp); - EXPECT_EQ(event_type, frame_events_[0].type); - EXPECT_EQ(media_type, frame_events_[0].media_type); - EXPECT_EQ(delay, frame_events_[0].delay_delta); -} - -TEST_F(LoggingRawTest, PacketEvent) { - CastLoggingEvent event_type = PACKET_RECEIVED; - EventMediaType media_type = VIDEO_EVENT; - uint32 frame_id = 456u; - uint16 packet_id = 1u; - uint16 max_packet_id = 10u; - RtpTimestamp rtp_timestamp = 123u; - base::TimeTicks timestamp = base::TimeTicks(); - size_t size = 1024u; - raw_.InsertPacketEvent(timestamp, event_type, media_type, - rtp_timestamp, frame_id, packet_id, max_packet_id, size); - - event_subscriber_.GetFrameEventsAndReset(&frame_events_); - EXPECT_TRUE(frame_events_.empty()); - - event_subscriber_.GetPacketEventsAndReset(&packet_events_); - ASSERT_EQ(1u, packet_events_.size()); - - EXPECT_EQ(rtp_timestamp, packet_events_[0].rtp_timestamp); - EXPECT_EQ(frame_id, packet_events_[0].frame_id); - EXPECT_EQ(max_packet_id, packet_events_[0].max_packet_id); - EXPECT_EQ(packet_id, packet_events_[0].packet_id); - EXPECT_EQ(size, packet_events_[0].size); - EXPECT_EQ(timestamp, packet_events_[0].timestamp); - EXPECT_EQ(event_type, packet_events_[0].type); - EXPECT_EQ(media_type, packet_events_[0].media_type); -} - -TEST_F(LoggingRawTest, MultipleSubscribers) { - SimpleEventSubscriber event_subscriber_2; - - // Now raw_ has two subscribers. - raw_.AddSubscriber(&event_subscriber_2); - - CastLoggingEvent event_type = FRAME_DECODED; - EventMediaType media_type = VIDEO_EVENT; - uint32 frame_id = 456u; - RtpTimestamp rtp_timestamp = 123u; - base::TimeTicks timestamp = base::TimeTicks(); - raw_.InsertFrameEvent(timestamp, event_type, media_type, - rtp_timestamp, frame_id); - - event_subscriber_.GetPacketEventsAndReset(&packet_events_); - EXPECT_TRUE(packet_events_.empty()); - - event_subscriber_.GetFrameEventsAndReset(&frame_events_); - ASSERT_EQ(1u, frame_events_.size()); - EXPECT_EQ(rtp_timestamp, frame_events_[0].rtp_timestamp); - EXPECT_EQ(frame_id, frame_events_[0].frame_id); - EXPECT_EQ(0u, frame_events_[0].size); - EXPECT_EQ(timestamp, frame_events_[0].timestamp); - EXPECT_EQ(event_type, frame_events_[0].type); - EXPECT_EQ(media_type, frame_events_[0].media_type); - EXPECT_EQ(base::TimeDelta(), frame_events_[0].delay_delta); - - event_subscriber_2.GetPacketEventsAndReset(&packet_events_); - EXPECT_TRUE(packet_events_.empty()); - - event_subscriber_2.GetFrameEventsAndReset(&frame_events_); - ASSERT_EQ(1u, frame_events_.size()); - EXPECT_EQ(rtp_timestamp, frame_events_[0].rtp_timestamp); - EXPECT_EQ(frame_id, frame_events_[0].frame_id); - EXPECT_EQ(0u, frame_events_[0].size); - EXPECT_EQ(timestamp, frame_events_[0].timestamp); - EXPECT_EQ(event_type, frame_events_[0].type); - EXPECT_EQ(media_type, frame_events_[0].media_type); - EXPECT_EQ(base::TimeDelta(), frame_events_[0].delay_delta); - - // Remove event_subscriber_2, so it shouldn't receive events after this. - raw_.RemoveSubscriber(&event_subscriber_2); - - media_type = AUDIO_EVENT; - frame_id = 789; - rtp_timestamp = 456; - timestamp = base::TimeTicks(); - raw_.InsertFrameEvent(timestamp, event_type, media_type, - rtp_timestamp, frame_id); - - // |event_subscriber_| should still receive events. - event_subscriber_.GetFrameEventsAndReset(&frame_events_); - ASSERT_EQ(1u, frame_events_.size()); - EXPECT_EQ(rtp_timestamp, frame_events_[0].rtp_timestamp); - EXPECT_EQ(frame_id, frame_events_[0].frame_id); - EXPECT_EQ(0u, frame_events_[0].size); - EXPECT_EQ(timestamp, frame_events_[0].timestamp); - EXPECT_EQ(event_type, frame_events_[0].type); - EXPECT_EQ(media_type, frame_events_[0].media_type); - EXPECT_EQ(base::TimeDelta(), frame_events_[0].delay_delta); - - event_subscriber_2.GetFrameEventsAndReset(&frame_events_); - EXPECT_TRUE(frame_events_.empty()); -} - -} // namespace cast -} // namespace media diff --git a/media/cast/logging/raw_event_subscriber_bundle.cc b/media/cast/logging/raw_event_subscriber_bundle.cc index 5dc5f79..ecfe10d 100644 --- a/media/cast/logging/raw_event_subscriber_bundle.cc +++ b/media/cast/logging/raw_event_subscriber_bundle.cc @@ -21,13 +21,13 @@ RawEventSubscriberBundleForStream::RawEventSubscriberBundleForStream( 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_); + cast_environment_->logger()->Subscribe(&event_subscriber_); + cast_environment_->logger()->Subscribe(&stats_subscriber_); } RawEventSubscriberBundleForStream::~RawEventSubscriberBundleForStream() { - cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); - cast_environment_->Logging()->RemoveRawEventSubscriber(&stats_subscriber_); + cast_environment_->logger()->Unsubscribe(&event_subscriber_); + cast_environment_->logger()->Unsubscribe(&stats_subscriber_); } EncodingEventSubscriber* @@ -45,17 +45,14 @@ RawEventSubscriberBundle::RawEventSubscriberBundle( : cast_environment_(cast_environment) {} RawEventSubscriberBundle::~RawEventSubscriberBundle() { - if (receiver_offset_estimator_.get()) { - cast_environment_->Logging()->RemoveRawEventSubscriber( - receiver_offset_estimator_.get()); - } + if (receiver_offset_estimator_.get()) + cast_environment_->logger()->Unsubscribe(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()); + cast_environment_->logger()->Subscribe(receiver_offset_estimator_.get()); } SubscribersMapByStream::iterator it = subscribers_.find(is_audio); if (it != subscribers_.end()) @@ -74,8 +71,7 @@ void RawEventSubscriberBundle::RemoveEventSubscribers(bool is_audio) { subscribers_.erase(it); if (subscribers_.empty()) { - cast_environment_->Logging()->RemoveRawEventSubscriber( - receiver_offset_estimator_.get()); + cast_environment_->logger()->Unsubscribe(receiver_offset_estimator_.get()); receiver_offset_estimator_.reset(); } } diff --git a/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc b/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc index ca791d4..2cbaafd 100644 --- a/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc +++ b/media/cast/logging/receiver_time_offset_estimator_impl_unittest.cc @@ -25,15 +25,15 @@ class ReceiverTimeOffsetEstimatorImplTest : public ::testing::Test { task_runner_, task_runner_, task_runner_)) { - cast_environment_->Logging()->AddRawEventSubscriber(&estimator_); + cast_environment_->logger()->Subscribe(&estimator_); } ~ReceiverTimeOffsetEstimatorImplTest() override { - cast_environment_->Logging()->RemoveRawEventSubscriber(&estimator_); + cast_environment_->logger()->Unsubscribe(&estimator_); } void AdvanceClocks(base::TimeDelta time) { - sender_clock_->Advance(time); + task_runner_->Sleep(time); receiver_clock_.Advance(time); } @@ -63,44 +63,62 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EstimateOffset) { AdvanceClocks(base::TimeDelta::FromMilliseconds(20)); - cast_environment_->Logging()->InsertEncodedFrameEvent( - sender_clock_->NowTicks(), - FRAME_ENCODED, VIDEO_EVENT, - rtp_timestamp, - frame_id, - 1234, - true, - 5678, - 9.10, - 11.12); - - cast_environment_->Logging()->InsertPacketEvent( - sender_clock_->NowTicks(), - PACKET_SENT_TO_NETWORK, VIDEO_EVENT, - rtp_timestamp, - frame_id, - 56, 78, 1500); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = sender_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp; + encode_event->frame_id = frame_id; + encode_event->size = 1234; + encode_event->key_frame = true; + encode_event->target_bitrate = 5678; + encode_event->encoder_cpu_utilization = 9.10; + encode_event->idealized_bitrate_utilization = 11.12; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); + + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = sender_clock_->NowTicks(); + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp; + send_event->frame_id = frame_id; + send_event->packet_id = 56; + send_event->max_packet_id = 78; + send_event->size = 1500; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); AdvanceClocks(base::TimeDelta::FromMilliseconds(10)); - cast_environment_->Logging()->InsertFrameEvent( - receiver_clock_.NowTicks(), FRAME_ACK_SENT, VIDEO_EVENT, - rtp_timestamp, frame_id); - - cast_environment_->Logging()->InsertPacketEvent( - receiver_clock_.NowTicks(), - PACKET_RECEIVED, VIDEO_EVENT, - rtp_timestamp, - frame_id, - 56, 78, 1500); + scoped_ptr<FrameEvent> ack_sent_event(new FrameEvent()); + ack_sent_event->timestamp = receiver_clock_.NowTicks(); + ack_sent_event->type = FRAME_ACK_SENT; + ack_sent_event->media_type = VIDEO_EVENT; + ack_sent_event->rtp_timestamp = rtp_timestamp; + ack_sent_event->frame_id = frame_id; + cast_environment_->logger()->DispatchFrameEvent(ack_sent_event.Pass()); + + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = receiver_clock_.NowTicks(); + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = VIDEO_EVENT; + receive_event->rtp_timestamp = rtp_timestamp; + receive_event->frame_id = frame_id; + receive_event->packet_id = 56; + receive_event->max_packet_id = 78; + receive_event->size = 1500; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); AdvanceClocks(base::TimeDelta::FromMilliseconds(30)); - cast_environment_->Logging()->InsertFrameEvent( - sender_clock_->NowTicks(), FRAME_ACK_RECEIVED, VIDEO_EVENT, - rtp_timestamp, frame_id); + scoped_ptr<FrameEvent> ack_event(new FrameEvent()); + ack_event->timestamp = sender_clock_->NowTicks(); + ack_event->type = FRAME_ACK_RECEIVED; + ack_event->media_type = VIDEO_EVENT; + ack_event->rtp_timestamp = rtp_timestamp; + ack_event->frame_id = frame_id; + cast_environment_->logger()->DispatchFrameEvent(ack_event.Pass()); EXPECT_TRUE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); @@ -112,7 +130,7 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EstimateOffset) { EXPECT_LE(true_offset_ms, upper_bound_ms); } -// Same scenario as above, but event C arrives before event B. It doens't mean +// Same scenario as above, but event C arrives before event B. It doesn't mean // event C occurred before event B. TEST_F(ReceiverTimeOffsetEstimatorImplTest, EventCArrivesBeforeEventB) { int64 true_offset_ms = 100; @@ -128,23 +146,29 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EventCArrivesBeforeEventB) { AdvanceClocks(base::TimeDelta::FromMilliseconds(20)); - cast_environment_->Logging()->InsertEncodedFrameEvent( - sender_clock_->NowTicks(), - FRAME_ENCODED, VIDEO_EVENT, - rtp_timestamp, - frame_id, - 1234, - true, - 5678, - 9.10, - 11.12); - - cast_environment_->Logging()->InsertPacketEvent( - sender_clock_->NowTicks(), - PACKET_SENT_TO_NETWORK, VIDEO_EVENT, - rtp_timestamp, - frame_id, - 56, 78, 1500); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = sender_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp; + encode_event->frame_id = frame_id; + encode_event->size = 1234; + encode_event->key_frame = true; + encode_event->target_bitrate = 5678; + encode_event->encoder_cpu_utilization = 9.10; + encode_event->idealized_bitrate_utilization = 11.12; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); + + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = sender_clock_->NowTicks(); + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp; + send_event->frame_id = frame_id; + send_event->packet_id = 56; + send_event->max_packet_id = 78; + send_event->size = 1500; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); @@ -153,20 +177,34 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EventCArrivesBeforeEventB) { AdvanceClocks(base::TimeDelta::FromMilliseconds(30)); base::TimeTicks event_c_time = sender_clock_->NowTicks(); - cast_environment_->Logging()->InsertFrameEvent( - event_c_time, FRAME_ACK_RECEIVED, VIDEO_EVENT, rtp_timestamp, frame_id); + scoped_ptr<FrameEvent> ack_event(new FrameEvent()); + ack_event->timestamp = event_c_time; + ack_event->type = FRAME_ACK_RECEIVED; + ack_event->media_type = VIDEO_EVENT; + ack_event->rtp_timestamp = rtp_timestamp; + ack_event->frame_id = frame_id; + cast_environment_->logger()->DispatchFrameEvent(ack_event.Pass()); EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); - cast_environment_->Logging()->InsertPacketEvent( - event_b_time, - PACKET_RECEIVED, VIDEO_EVENT, - rtp_timestamp, - frame_id, - 56, 78, 1500); - - cast_environment_->Logging()->InsertFrameEvent( - event_b_time, FRAME_ACK_SENT, VIDEO_EVENT, rtp_timestamp, frame_id); + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = event_b_time; + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = VIDEO_EVENT; + receive_event->rtp_timestamp = rtp_timestamp; + receive_event->frame_id = frame_id; + receive_event->packet_id = 56; + receive_event->max_packet_id = 78; + receive_event->size = 1500; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); + + scoped_ptr<FrameEvent> ack_sent_event(new FrameEvent()); + ack_sent_event->timestamp = event_b_time; + ack_sent_event->type = FRAME_ACK_SENT; + ack_sent_event->media_type = VIDEO_EVENT; + ack_sent_event->rtp_timestamp = rtp_timestamp; + ack_sent_event->frame_id = frame_id; + cast_environment_->logger()->DispatchFrameEvent(ack_sent_event.Pass()); EXPECT_TRUE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); @@ -198,111 +236,155 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, MultipleIterations) { // 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(), - FRAME_ENCODED, VIDEO_EVENT, - rtp_timestamp_a, - frame_id_a, - 1234, - true, - 5678, - 9.10, - 11.12); - - cast_environment_->Logging()->InsertPacketEvent( - sender_clock_->NowTicks(), - PACKET_SENT_TO_NETWORK, VIDEO_EVENT, - rtp_timestamp_a, - frame_id_a, - 56, 78, 1500); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = sender_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp_a; + encode_event->frame_id = frame_id_a; + encode_event->size = 1234; + encode_event->key_frame = true; + encode_event->target_bitrate = 5678; + encode_event->encoder_cpu_utilization = 9.10; + encode_event->idealized_bitrate_utilization = 11.12; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); + + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = sender_clock_->NowTicks(); + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp_a; + send_event->frame_id = frame_id_a; + send_event->packet_id = 56; + send_event->max_packet_id = 78; + send_event->size = 1500; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); AdvanceClocks(base::TimeDelta::FromMilliseconds(10)); - cast_environment_->Logging()->InsertEncodedFrameEvent( - sender_clock_->NowTicks(), - FRAME_ENCODED, VIDEO_EVENT, - rtp_timestamp_b, - frame_id_b, - 1234, - true, - 5678, - 9.10, - 11.12); - - cast_environment_->Logging()->InsertPacketEvent( - sender_clock_->NowTicks(), - PACKET_SENT_TO_NETWORK, VIDEO_EVENT, - rtp_timestamp_b, - frame_id_b, - 56, 78, 1500); - - cast_environment_->Logging()->InsertFrameEvent( - receiver_clock_.NowTicks(), FRAME_ACK_SENT, VIDEO_EVENT, - rtp_timestamp_a, frame_id_a); + encode_event.reset(new FrameEvent()); + encode_event->timestamp = sender_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp_b; + encode_event->frame_id = frame_id_b; + encode_event->size = 1234; + encode_event->key_frame = true; + encode_event->target_bitrate = 5678; + encode_event->encoder_cpu_utilization = 9.10; + encode_event->idealized_bitrate_utilization = 11.12; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); + + send_event.reset(new PacketEvent()); + send_event->timestamp = sender_clock_->NowTicks(); + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp_b; + send_event->frame_id = frame_id_b; + send_event->packet_id = 56; + send_event->max_packet_id = 78; + send_event->size = 1500; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); + + scoped_ptr<FrameEvent> ack_sent_event(new FrameEvent()); + ack_sent_event->timestamp = receiver_clock_.NowTicks(); + ack_sent_event->type = FRAME_ACK_SENT; + ack_sent_event->media_type = VIDEO_EVENT; + ack_sent_event->rtp_timestamp = rtp_timestamp_a; + ack_sent_event->frame_id = frame_id_a; + cast_environment_->logger()->DispatchFrameEvent(ack_sent_event.Pass()); AdvanceClocks(base::TimeDelta::FromMilliseconds(20)); - cast_environment_->Logging()->InsertPacketEvent( - receiver_clock_.NowTicks(), - PACKET_RECEIVED, VIDEO_EVENT, - rtp_timestamp_b, - frame_id_b, - 56, 78, 1500); - - cast_environment_->Logging()->InsertFrameEvent( - receiver_clock_.NowTicks(), FRAME_ACK_SENT, VIDEO_EVENT, - rtp_timestamp_b, frame_id_b); + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = receiver_clock_.NowTicks(); + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = VIDEO_EVENT; + receive_event->rtp_timestamp = rtp_timestamp_b; + receive_event->frame_id = frame_id_b; + receive_event->packet_id = 56; + receive_event->max_packet_id = 78; + receive_event->size = 1500; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); + + ack_sent_event.reset(new FrameEvent()); + ack_sent_event->timestamp = receiver_clock_.NowTicks(); + ack_sent_event->type = FRAME_ACK_SENT; + ack_sent_event->media_type = VIDEO_EVENT; + ack_sent_event->rtp_timestamp = rtp_timestamp_b; + ack_sent_event->frame_id = frame_id_b; + cast_environment_->logger()->DispatchFrameEvent(ack_sent_event.Pass()); AdvanceClocks(base::TimeDelta::FromMilliseconds(5)); - cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), - FRAME_ACK_RECEIVED, - VIDEO_EVENT, - rtp_timestamp_b, - frame_id_b); + scoped_ptr<FrameEvent> ack_event(new FrameEvent()); + ack_event->timestamp = sender_clock_->NowTicks(); + ack_event->type = FRAME_ACK_RECEIVED; + ack_event->media_type = VIDEO_EVENT; + ack_event->rtp_timestamp = rtp_timestamp_b; + ack_event->frame_id = frame_id_b; + cast_environment_->logger()->DispatchFrameEvent(ack_event.Pass()); AdvanceClocks(base::TimeDelta::FromMilliseconds(5)); - cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), - FRAME_ACK_RECEIVED, - VIDEO_EVENT, - rtp_timestamp_a, - frame_id_a); + ack_event.reset(new FrameEvent()); + ack_event->timestamp = sender_clock_->NowTicks(); + ack_event->type = FRAME_ACK_RECEIVED; + ack_event->media_type = VIDEO_EVENT; + ack_event->rtp_timestamp = rtp_timestamp_a; + ack_event->frame_id = frame_id_a; + cast_environment_->logger()->DispatchFrameEvent(ack_event.Pass()); AdvanceClocks(base::TimeDelta::FromMilliseconds(17)); - cast_environment_->Logging()->InsertEncodedFrameEvent( - sender_clock_->NowTicks(), - FRAME_ENCODED, VIDEO_EVENT, - rtp_timestamp_c, - frame_id_c, - 1234, - true, - 5678, - 9.10, - 11.12); - - cast_environment_->Logging()->InsertPacketEvent( - sender_clock_->NowTicks(), - PACKET_SENT_TO_NETWORK, VIDEO_EVENT, - rtp_timestamp_c, - frame_id_c, - 56, 78, 1500); + encode_event.reset(new FrameEvent()); + encode_event->timestamp = sender_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp_c; + encode_event->frame_id = frame_id_c; + encode_event->size = 1234; + encode_event->key_frame = true; + encode_event->target_bitrate = 5678; + encode_event->encoder_cpu_utilization = 9.10; + encode_event->idealized_bitrate_utilization = 11.12; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); + + send_event.reset(new PacketEvent()); + send_event->timestamp = sender_clock_->NowTicks(); + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp_c; + send_event->frame_id = frame_id_c; + send_event->packet_id = 56; + send_event->max_packet_id = 78; + send_event->size = 1500; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); AdvanceClocks(base::TimeDelta::FromMilliseconds(3)); - cast_environment_->Logging()->InsertPacketEvent( - receiver_clock_.NowTicks(), - PACKET_RECEIVED, VIDEO_EVENT, - rtp_timestamp_c, - frame_id_c, - 56, 78, 1500); - - cast_environment_->Logging()->InsertFrameEvent( - receiver_clock_.NowTicks(), FRAME_ACK_SENT, VIDEO_EVENT, - rtp_timestamp_c, frame_id_c); + receive_event.reset(new PacketEvent()); + receive_event->timestamp = receiver_clock_.NowTicks(); + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = VIDEO_EVENT; + receive_event->rtp_timestamp = rtp_timestamp_c; + receive_event->frame_id = frame_id_c; + receive_event->packet_id = 56; + receive_event->max_packet_id = 78; + receive_event->size = 1500; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); + + ack_sent_event.reset(new FrameEvent()); + ack_sent_event->timestamp = receiver_clock_.NowTicks(); + ack_sent_event->type = FRAME_ACK_SENT; + ack_sent_event->media_type = VIDEO_EVENT; + ack_sent_event->rtp_timestamp = rtp_timestamp_c; + ack_sent_event->frame_id = frame_id_c; + cast_environment_->logger()->DispatchFrameEvent(ack_sent_event.Pass()); AdvanceClocks(base::TimeDelta::FromMilliseconds(30)); - cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), - FRAME_ACK_RECEIVED, - VIDEO_EVENT, - rtp_timestamp_c, - frame_id_c); + ack_event.reset(new FrameEvent()); + ack_event->timestamp = sender_clock_->NowTicks(); + ack_event->type = FRAME_ACK_RECEIVED; + ack_event->media_type = VIDEO_EVENT; + ack_event->rtp_timestamp = rtp_timestamp_c; + ack_event->frame_id = frame_id_c; + cast_environment_->logger()->DispatchFrameEvent(ack_event.Pass()); EXPECT_TRUE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); int64 lower_bound_ms = lower_bound.InMilliseconds(); diff --git a/media/cast/logging/simple_event_subscriber_unittest.cc b/media/cast/logging/simple_event_subscriber_unittest.cc index bf2c210..92b6c6e 100644 --- a/media/cast/logging/simple_event_subscriber_unittest.cc +++ b/media/cast/logging/simple_event_subscriber_unittest.cc @@ -25,11 +25,11 @@ class SimpleEventSubscriberTest : public ::testing::Test { task_runner_, task_runner_, task_runner_)) { - cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_); + cast_environment_->logger()->Subscribe(&event_subscriber_); } ~SimpleEventSubscriberTest() override { - cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); + cast_environment_->logger()->Unsubscribe(&event_subscriber_); } base::SimpleTestTickClock* testing_clock_; // Owned by CastEnvironment. @@ -40,32 +40,58 @@ class SimpleEventSubscriberTest : public ::testing::Test { TEST_F(SimpleEventSubscriberTest, GetAndResetEvents) { // Log some frame events. - cast_environment_->Logging()->InsertEncodedFrameEvent( - testing_clock_->NowTicks(), FRAME_ENCODED, AUDIO_EVENT, - /*rtp_timestamp*/ 100u, /*frame_id*/ 0u, /*frame_size*/ 123, - /*key_frame*/ false, 0, 0.01, 0.02); - cast_environment_->Logging()->InsertFrameEventWithDelay( - testing_clock_->NowTicks(), FRAME_PLAYOUT, AUDIO_EVENT, - /*rtp_timestamp*/ 100u, - /*frame_id*/ 0u, /*delay*/ base::TimeDelta::FromMilliseconds(100)); - cast_environment_->Logging()->InsertFrameEvent( - testing_clock_->NowTicks(), FRAME_DECODED, AUDIO_EVENT, - /*rtp_timestamp*/ 200u, - /*frame_id*/ 0u); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = testing_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = AUDIO_EVENT; + encode_event->rtp_timestamp = 100u; + encode_event->frame_id = 0u; + encode_event->size = 1234; + encode_event->key_frame = true; + encode_event->target_bitrate = 128u; + encode_event->encoder_cpu_utilization = 0.01; + encode_event->idealized_bitrate_utilization = 0.02; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); + + scoped_ptr<FrameEvent> playout_event(new FrameEvent()); + playout_event->timestamp = testing_clock_->NowTicks(); + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = AUDIO_EVENT; + playout_event->rtp_timestamp = 100u; + playout_event->frame_id = 0u; + playout_event->delay_delta = base::TimeDelta::FromMilliseconds(100); + cast_environment_->logger()->DispatchFrameEvent(playout_event.Pass()); + + scoped_ptr<FrameEvent> decode_event(new FrameEvent()); + decode_event->timestamp = testing_clock_->NowTicks(); + decode_event->type = FRAME_DECODED; + decode_event->media_type = AUDIO_EVENT; + decode_event->rtp_timestamp = 200u; + decode_event->frame_id = 0u; + cast_environment_->logger()->DispatchFrameEvent(decode_event.Pass()); // Log some packet events. - cast_environment_->Logging()->InsertPacketEvent( - testing_clock_->NowTicks(), PACKET_RECEIVED, AUDIO_EVENT, - /*rtp_timestamp*/ 200u, - /*frame_id*/ 0u, /*packet_id*/ 1u, /*max_packet_id*/ 5u, /*size*/ 100u); - cast_environment_->Logging()->InsertPacketEvent( - testing_clock_->NowTicks(), FRAME_DECODED, VIDEO_EVENT, - /*rtp_timestamp*/ 200u, /*frame_id*/ 0u, /*packet_id*/ 1u, - /*max_packet_id*/ 5u, /*size*/ 100u); - cast_environment_->Logging()->InsertPacketEvent( - testing_clock_->NowTicks(), FRAME_DECODED, VIDEO_EVENT, - /*rtp_timestamp*/ 300u, /*frame_id*/ 0u, /*packet_id*/ 1u, - /*max_packet_id*/ 5u, /*size*/ 100u); + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = testing_clock_->NowTicks(); + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = AUDIO_EVENT; + receive_event->rtp_timestamp = 200u; + receive_event->frame_id = 0u; + receive_event->packet_id = 1u; + receive_event->max_packet_id = 5u; + receive_event->size = 100u; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); + + receive_event.reset(new PacketEvent()); + receive_event->timestamp = testing_clock_->NowTicks(); + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = VIDEO_EVENT; + receive_event->rtp_timestamp = 200u; + receive_event->frame_id = 0u; + receive_event->packet_id = 1u; + receive_event->max_packet_id = 10u; + receive_event->size = 1024u; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); std::vector<FrameEvent> frame_events; event_subscriber_.GetFrameEventsAndReset(&frame_events); @@ -73,7 +99,7 @@ TEST_F(SimpleEventSubscriberTest, GetAndResetEvents) { std::vector<PacketEvent> packet_events; event_subscriber_.GetPacketEventsAndReset(&packet_events); - EXPECT_EQ(3u, packet_events.size()); + EXPECT_EQ(2u, packet_events.size()); // Calling this function again should result in empty vector because no events // were logged since last call. diff --git a/media/cast/logging/stats_event_subscriber_unittest.cc b/media/cast/logging/stats_event_subscriber_unittest.cc index 09dc517..d649c89 100644 --- a/media/cast/logging/stats_event_subscriber_unittest.cc +++ b/media/cast/logging/stats_event_subscriber_unittest.cc @@ -35,19 +35,17 @@ class StatsEventSubscriberTest : public ::testing::Test { fake_offset_estimator_( base::TimeDelta::FromSeconds(kReceiverOffsetSecs)) { receiver_clock_.Advance(base::TimeDelta::FromSeconds(kReceiverOffsetSecs)); - cast_environment_->Logging()->AddRawEventSubscriber( - &fake_offset_estimator_); + cast_environment_->logger()->Subscribe(&fake_offset_estimator_); } ~StatsEventSubscriberTest() override { if (subscriber_.get()) - cast_environment_->Logging()->RemoveRawEventSubscriber(subscriber_.get()); - cast_environment_->Logging()->RemoveRawEventSubscriber( - &fake_offset_estimator_); + cast_environment_->logger()->Unsubscribe(subscriber_.get()); + cast_environment_->logger()->Unsubscribe(&fake_offset_estimator_); } void AdvanceClocks(base::TimeDelta delta) { - sender_clock_->Advance(delta); + task_runner_->Sleep(delta); receiver_clock_.Advance(delta); } @@ -55,7 +53,7 @@ class StatsEventSubscriberTest : public ::testing::Test { DCHECK(!subscriber_.get()); subscriber_.reset(new StatsEventSubscriber( event_media_type, cast_environment_->Clock(), &fake_offset_estimator_)); - cast_environment_->Logging()->AddRawEventSubscriber(subscriber_.get()); + cast_environment_->logger()->Subscribe(subscriber_.get()); } base::SimpleTestTickClock* sender_clock_; // Owned by CastEnvironment. @@ -79,30 +77,35 @@ TEST_F(StatsEventSubscriberTest, CaptureEncode) { base::TimeTicks start_time = sender_clock_->NowTicks(); // Drop half the frames during the encode step. for (int i = 0; i < num_frames; i++) { - cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), - FRAME_CAPTURE_BEGIN, - VIDEO_EVENT, - rtp_timestamp, - frame_id); + scoped_ptr<FrameEvent> capture_begin_event(new FrameEvent()); + capture_begin_event->timestamp = sender_clock_->NowTicks(); + capture_begin_event->type = FRAME_CAPTURE_BEGIN; + capture_begin_event->media_type = VIDEO_EVENT; + capture_begin_event->rtp_timestamp = rtp_timestamp; + cast_environment_->logger()->DispatchFrameEvent(capture_begin_event.Pass()); + AdvanceClocks(base::TimeDelta::FromMicroseconds(10)); - cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), - FRAME_CAPTURE_END, - VIDEO_EVENT, - rtp_timestamp, - frame_id); + scoped_ptr<FrameEvent> capture_end_event(new FrameEvent()); + capture_end_event->timestamp = sender_clock_->NowTicks(); + capture_end_event->type = FRAME_CAPTURE_END; + capture_end_event->media_type = VIDEO_EVENT; + capture_end_event->rtp_timestamp = rtp_timestamp; + cast_environment_->logger()->DispatchFrameEvent(capture_end_event.Pass()); + if (i % 2 == 0) { AdvanceClocks(base::TimeDelta::FromMicroseconds(10)); - cast_environment_->Logging()->InsertEncodedFrameEvent( - sender_clock_->NowTicks(), - FRAME_ENCODED, - VIDEO_EVENT, - rtp_timestamp, - frame_id, - 1024, - true, - 5678, - 9.10, - 11.12); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = sender_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp; + encode_event->frame_id = frame_id; + encode_event->size = 1024; + encode_event->key_frame = true; + encode_event->target_bitrate = 5678; + encode_event->encoder_cpu_utilization = 9.10; + encode_event->idealized_bitrate_utilization = 11.12; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); } else if (i < extra_frames) { dropped_frames++; } @@ -155,16 +158,18 @@ TEST_F(StatsEventSubscriberTest, Encode) { for (int i = 0; i < num_frames; i++) { int size = 1000 + base::RandInt(-100, 100); total_size += size; - cast_environment_->Logging()->InsertEncodedFrameEvent( - sender_clock_->NowTicks(), - FRAME_ENCODED, VIDEO_EVENT, - rtp_timestamp, - frame_id, - size, - true, - 5678, - 9.10, - 11.12); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = sender_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp; + encode_event->frame_id = frame_id; + encode_event->size = size; + encode_event->key_frame = true; + encode_event->target_bitrate = 5678; + encode_event->encoder_cpu_utilization = 9.10; + encode_event->idealized_bitrate_utilization = 11.12; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); last_event_time = sender_clock_->NowTicks(); AdvanceClocks(base::TimeDelta::FromMicroseconds(35678)); @@ -215,10 +220,13 @@ TEST_F(StatsEventSubscriberTest, Decode) { 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(), - FRAME_DECODED, VIDEO_EVENT, - rtp_timestamp, - frame_id); + scoped_ptr<FrameEvent> decode_event(new FrameEvent()); + decode_event->timestamp = receiver_clock_.NowTicks(); + decode_event->type = FRAME_DECODED; + decode_event->media_type = VIDEO_EVENT; + decode_event->rtp_timestamp = rtp_timestamp; + decode_event->frame_id = frame_id; + cast_environment_->logger()->DispatchFrameEvent(decode_event.Pass()); AdvanceClocks(base::TimeDelta::FromMicroseconds(36789)); rtp_timestamp += 90; @@ -251,13 +259,14 @@ TEST_F(StatsEventSubscriberTest, PlayoutDelay) { base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms); if (delay_ms > 0) late_frames++; - cast_environment_->Logging()->InsertFrameEventWithDelay( - receiver_clock_.NowTicks(), - FRAME_PLAYOUT, - VIDEO_EVENT, - rtp_timestamp, - frame_id, - delay); + scoped_ptr<FrameEvent> playout_event(new FrameEvent()); + playout_event->timestamp = receiver_clock_.NowTicks(); + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = VIDEO_EVENT; + playout_event->rtp_timestamp = rtp_timestamp; + playout_event->frame_id = frame_id; + playout_event->delay_delta = delay; + cast_environment_->logger()->DispatchFrameEvent(playout_event.Pass()); AdvanceClocks(base::TimeDelta::FromMicroseconds(37890)); rtp_timestamp += 90; @@ -282,11 +291,12 @@ TEST_F(StatsEventSubscriberTest, E2ELatency) { int num_frames = 10; base::TimeDelta total_latency; for (int i = 0; i < num_frames; i++) { - cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), - FRAME_CAPTURE_BEGIN, - VIDEO_EVENT, - rtp_timestamp, - frame_id); + scoped_ptr<FrameEvent> capture_begin_event(new FrameEvent()); + capture_begin_event->timestamp = sender_clock_->NowTicks(); + capture_begin_event->type = FRAME_CAPTURE_BEGIN; + capture_begin_event->media_type = VIDEO_EVENT; + capture_begin_event->rtp_timestamp = rtp_timestamp; + cast_environment_->logger()->DispatchFrameEvent(capture_begin_event.Pass()); int latency_micros = 100000 + base::RandInt(-5000, 50000); base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros); @@ -296,13 +306,14 @@ TEST_F(StatsEventSubscriberTest, E2ELatency) { base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_micros); total_latency += latency; - cast_environment_->Logging()->InsertFrameEventWithDelay( - receiver_clock_.NowTicks(), - FRAME_PLAYOUT, - VIDEO_EVENT, - rtp_timestamp, - frame_id, - delay); + scoped_ptr<FrameEvent> playout_event(new FrameEvent()); + playout_event->timestamp = receiver_clock_.NowTicks(); + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = VIDEO_EVENT; + playout_event->rtp_timestamp = rtp_timestamp; + playout_event->frame_id = frame_id; + playout_event->delay_delta = delay; + cast_environment_->logger()->DispatchFrameEvent(playout_event.Pass()); rtp_timestamp += 90; frame_id++; @@ -338,11 +349,13 @@ TEST_F(StatsEventSubscriberTest, Packets) { base::TimeTicks sender_encoded_time = sender_clock_->NowTicks(); base::TimeTicks receiver_encoded_time = receiver_clock_.NowTicks(); - cast_environment_->Logging()->InsertFrameEvent(sender_encoded_time, - FRAME_ENCODED, - VIDEO_EVENT, - rtp_timestamp, - 0); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = sender_encoded_time; + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp; + encode_event->frame_id = 0; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); // Every 2nd packet will be retransmitted once. // Every 4th packet will be retransmitted twice. @@ -351,14 +364,17 @@ TEST_F(StatsEventSubscriberTest, Packets) { int size = 1000 + base::RandInt(-100, 100); total_size += size; - cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(), - PACKET_SENT_TO_NETWORK, - VIDEO_EVENT, - rtp_timestamp, - 0, - i, - num_packets - 1, - size); + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = sender_clock_->NowTicks(); + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp; + send_event->frame_id = 0; + send_event->packet_id = i; + send_event->max_packet_id = num_packets - 1; + send_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); + num_packets_transmitted++; total_queueing_latency += sender_clock_->NowTicks() - sender_encoded_time; @@ -379,15 +395,17 @@ TEST_F(StatsEventSubscriberTest, Packets) { // Retransmission 1. AdvanceClocks(base::TimeDelta::FromMicroseconds(12345)); if (i % 2 == 0) { - cast_environment_->Logging()->InsertPacketEvent( - receiver_clock_.NowTicks(), - PACKET_RETRANSMITTED, - VIDEO_EVENT, - rtp_timestamp, - 0, - i, - num_packets - 1, - size); + scoped_ptr<PacketEvent> retransmit_event(new PacketEvent()); + retransmit_event->timestamp = receiver_clock_.NowTicks(); + retransmit_event->type = PACKET_RETRANSMITTED; + retransmit_event->media_type = VIDEO_EVENT; + retransmit_event->rtp_timestamp = rtp_timestamp; + retransmit_event->frame_id = 0; + retransmit_event->packet_id = i; + retransmit_event->max_packet_id = num_packets - 1; + retransmit_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(retransmit_event.Pass()); + retransmit_total_size += size; num_packets_transmitted++; num_packets_retransmitted++; @@ -396,15 +414,17 @@ TEST_F(StatsEventSubscriberTest, Packets) { // Retransmission 2. AdvanceClocks(base::TimeDelta::FromMicroseconds(13456)); if (i % 4 == 0) { - cast_environment_->Logging()->InsertPacketEvent( - receiver_clock_.NowTicks(), - PACKET_RETRANSMITTED, - VIDEO_EVENT, - rtp_timestamp, - 0, - i, - num_packets - 1, - size); + scoped_ptr<PacketEvent> retransmit_event(new PacketEvent()); + retransmit_event->timestamp = receiver_clock_.NowTicks(); + retransmit_event->type = PACKET_RETRANSMITTED; + retransmit_event->media_type = VIDEO_EVENT; + retransmit_event->rtp_timestamp = rtp_timestamp; + retransmit_event->frame_id = 0; + retransmit_event->packet_id = i; + retransmit_event->max_packet_id = num_packets - 1; + retransmit_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(retransmit_event.Pass()); + retransmit_total_size += size; num_packets_transmitted++; num_packets_retransmitted++; @@ -413,38 +433,45 @@ TEST_F(StatsEventSubscriberTest, Packets) { // Retransmission 3. AdvanceClocks(base::TimeDelta::FromMicroseconds(14567)); if (i % 8 == 0) { - cast_environment_->Logging()->InsertPacketEvent( - receiver_clock_.NowTicks(), - PACKET_RETRANSMITTED, - VIDEO_EVENT, - rtp_timestamp, - 0, - i, - num_packets - 1, - size); - cast_environment_->Logging()->InsertPacketEvent( - receiver_clock_.NowTicks(), - PACKET_RTX_REJECTED, - VIDEO_EVENT, - rtp_timestamp, - 0, - i, - num_packets - 1, - size); + scoped_ptr<PacketEvent> retransmit_event(new PacketEvent()); + retransmit_event->timestamp = receiver_clock_.NowTicks(); + retransmit_event->type = PACKET_RETRANSMITTED; + retransmit_event->media_type = VIDEO_EVENT; + retransmit_event->rtp_timestamp = rtp_timestamp; + retransmit_event->frame_id = 0; + retransmit_event->packet_id = i; + retransmit_event->max_packet_id = num_packets - 1; + retransmit_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(retransmit_event.Pass()); + + scoped_ptr<PacketEvent> reject_event(new PacketEvent()); + reject_event->timestamp = receiver_clock_.NowTicks(); + reject_event->type = PACKET_RTX_REJECTED; + reject_event->media_type = VIDEO_EVENT; + reject_event->rtp_timestamp = rtp_timestamp; + reject_event->frame_id = 0; + reject_event->packet_id = i; + reject_event->max_packet_id = num_packets - 1; + reject_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(reject_event.Pass()); + retransmit_total_size += size; num_packets_transmitted++; num_packets_retransmitted++; num_packets_rtx_rejected++; } - cast_environment_->Logging()->InsertPacketEvent(received_time, - PACKET_RECEIVED, - VIDEO_EVENT, - rtp_timestamp, - 0, - i, - num_packets - 1, - size); + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = received_time; + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = VIDEO_EVENT; + receive_event->rtp_timestamp = rtp_timestamp; + receive_event->frame_id = 0; + receive_event->packet_id = i; + receive_event->max_packet_id = num_packets - 1; + receive_event->size = size; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); + num_packets_received++; } @@ -538,43 +565,51 @@ TEST_F(StatsEventSubscriberTest, Histograms) { for (int i = 0; i < 10; ++i) { ++frame_id; ++rtp_timestamp; - cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), - FRAME_CAPTURE_BEGIN, - VIDEO_EVENT, - rtp_timestamp, - frame_id); + + scoped_ptr<FrameEvent> capture_begin_event(new FrameEvent()); + capture_begin_event->timestamp = sender_clock_->NowTicks(); + capture_begin_event->type = FRAME_CAPTURE_BEGIN; + capture_begin_event->media_type = VIDEO_EVENT; + capture_begin_event->rtp_timestamp = rtp_timestamp; + cast_environment_->logger()->DispatchFrameEvent(capture_begin_event.Pass()); + AdvanceClocks(base::TimeDelta::FromMilliseconds(10)); - cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), - FRAME_CAPTURE_END, - VIDEO_EVENT, - rtp_timestamp, - frame_id); + scoped_ptr<FrameEvent> capture_end_event(new FrameEvent()); + capture_end_event->timestamp = sender_clock_->NowTicks(); + capture_end_event->type = FRAME_CAPTURE_END; + capture_end_event->media_type = VIDEO_EVENT; + capture_end_event->rtp_timestamp = rtp_timestamp; + cast_environment_->logger()->DispatchFrameEvent(capture_end_event.Pass()); + AdvanceClocks(base::TimeDelta::FromMilliseconds(15)); - cast_environment_->Logging()->InsertEncodedFrameEvent( - sender_clock_->NowTicks(), - FRAME_ENCODED, - VIDEO_EVENT, - rtp_timestamp, - frame_id, - 1024, - true, - 5678, - 9.10, - 11.12); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = sender_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = rtp_timestamp; + encode_event->frame_id = frame_id; + encode_event->size = 1024; + encode_event->key_frame = true; + encode_event->target_bitrate = 5678; + encode_event->encoder_cpu_utilization = 9.10; + encode_event->idealized_bitrate_utilization = 11.12; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); } // Send 3 packets for the last frame. // Queueing latencies are 100ms, 200ms and 300ms. for (int i = 0; i < 3; ++i) { AdvanceClocks(base::TimeDelta::FromMilliseconds(100)); - cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(), - PACKET_SENT_TO_NETWORK, - VIDEO_EVENT, - rtp_timestamp, - 0, - i, - 2, - 123); + scoped_ptr<PacketEvent> send_event(new PacketEvent()); + send_event->timestamp = sender_clock_->NowTicks(); + send_event->type = PACKET_SENT_TO_NETWORK; + send_event->media_type = VIDEO_EVENT; + send_event->rtp_timestamp = rtp_timestamp; + send_event->frame_id = 0; + send_event->packet_id = i; + send_event->max_packet_id = 2; + send_event->size = 123; + cast_environment_->logger()->DispatchPacketEvent(send_event.Pass()); } // Receive 3 packets for the last frame. @@ -582,23 +617,26 @@ TEST_F(StatsEventSubscriberTest, Histograms) { // Packet latencies are 400ms. AdvanceClocks(base::TimeDelta::FromMilliseconds(100)); for (int i = 0; i < 3; ++i) { - cast_environment_->Logging()->InsertPacketEvent(receiver_clock_.NowTicks(), - PACKET_RECEIVED, - VIDEO_EVENT, - rtp_timestamp, - 0, - i, - 2, - 123); + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = receiver_clock_.NowTicks(); + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = VIDEO_EVENT; + receive_event->rtp_timestamp = rtp_timestamp; + receive_event->frame_id = 0; + receive_event->packet_id = i; + receive_event->max_packet_id = 2; + receive_event->size = 123; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); } - cast_environment_->Logging()->InsertFrameEventWithDelay( - receiver_clock_.NowTicks(), - FRAME_PLAYOUT, - VIDEO_EVENT, - rtp_timestamp, - frame_id, - base::TimeDelta::FromMilliseconds(100)); + scoped_ptr<FrameEvent> playout_event(new FrameEvent()); + playout_event->timestamp = receiver_clock_.NowTicks(); + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = VIDEO_EVENT; + playout_event->rtp_timestamp = rtp_timestamp; + playout_event->frame_id = frame_id; + playout_event->delay_delta = base::TimeDelta::FromMilliseconds(100); + cast_environment_->logger()->DispatchFrameEvent(playout_event.Pass()); StatsEventSubscriber::SimpleHistogram* histogram; scoped_ptr<base::ListValue> values; diff --git a/media/cast/net/cast_transport_sender.h b/media/cast/net/cast_transport_sender.h index fc88a5c..b20c9df 100644 --- a/media/cast/net/cast_transport_sender.h +++ b/media/cast/net/cast_transport_sender.h @@ -20,6 +20,7 @@ #include "base/basictypes.h" #include "base/callback.h" +#include "base/memory/scoped_ptr.h" #include "base/single_thread_task_runner.h" #include "base/threading/non_thread_safe.h" #include "base/time/tick_clock.h" @@ -48,8 +49,8 @@ struct RtcpTimeData; typedef base::Callback<void(CastTransportStatus status)> CastTransportStatusCallback; -typedef base::Callback<void(const std::vector<PacketEvent>&, - const std::vector<FrameEvent>&)> +typedef base::Callback<void(scoped_ptr<std::vector<FrameEvent>>, + scoped_ptr<std::vector<PacketEvent>>)> BulkRawEventsCallback; // The application should only trigger this class from the transport thread. diff --git a/media/cast/net/cast_transport_sender_impl.cc b/media/cast/net/cast_transport_sender_impl.cc index 9a763de..936bf81 100644 --- a/media/cast/net/cast_transport_sender_impl.cc +++ b/media/cast/net/cast_transport_sender_impl.cc @@ -95,15 +95,14 @@ CastTransportSenderImpl::CastTransportSenderImpl( : clock_(clock), status_callback_(status_callback), transport_task_runner_(transport_task_runner), - transport_( - external_transport ? - NULL : - new UdpTransport(net_log, - transport_task_runner, - local_end_point, - remote_end_point, - GetTransportSendBufferSize(*options), - status_callback)), + transport_(external_transport + ? nullptr + : new UdpTransport(net_log, + transport_task_runner, + local_end_point, + remote_end_point, + GetTransportSendBufferSize(*options), + status_callback)), pacer_(LookupOptionWithDefault(*options, kOptionPacerTargetBurstSize, kTargetBurstSize), @@ -111,7 +110,7 @@ CastTransportSenderImpl::CastTransportSenderImpl( kOptionPacerMaxBurstSize, kMaxBurstSize), clock, - &logging_, + raw_events_callback.is_null() ? nullptr : &recent_packet_events_, external_transport ? external_transport : transport_.get(), transport_task_runner), raw_events_callback_(raw_events_callback), @@ -122,8 +121,6 @@ CastTransportSenderImpl::CastTransportSenderImpl( DCHECK(clock_); if (!raw_events_callback_.is_null()) { DCHECK(raw_events_callback_interval > base::TimeDelta()); - event_subscriber_.reset(new SimpleEventSubscriber); - logging_.AddRawEventSubscriber(event_subscriber_.get()); transport_task_runner->PostDelayedTask( FROM_HERE, base::Bind(&CastTransportSenderImpl::SendRawEvents, @@ -161,8 +158,6 @@ CastTransportSenderImpl::~CastTransportSenderImpl() { if (transport_) { transport_->StopReceiving(); } - if (event_subscriber_.get()) - logging_.RemoveRawEventSubscriber(event_subscriber_.get()); } void CastTransportSenderImpl::InitializeAudio( @@ -341,13 +336,17 @@ PacketReceiverCallback CastTransportSenderImpl::PacketReceiverForTesting() { } void CastTransportSenderImpl::SendRawEvents() { - DCHECK(event_subscriber_.get()); DCHECK(!raw_events_callback_.is_null()); - std::vector<PacketEvent> packet_events; - std::vector<FrameEvent> frame_events; - event_subscriber_->GetPacketEventsAndReset(&packet_events); - event_subscriber_->GetFrameEventsAndReset(&frame_events); - raw_events_callback_.Run(packet_events, frame_events); + + if (!recent_frame_events_.empty() || !recent_packet_events_.empty()) { + scoped_ptr<std::vector<FrameEvent>> frame_events( + new std::vector<FrameEvent>()); + frame_events->swap(recent_frame_events_); + scoped_ptr<std::vector<PacketEvent>> packet_events( + new std::vector<PacketEvent>()); + packet_events->swap(recent_packet_events_); + raw_events_callback_.Run(frame_events.Pass(), packet_events.Pass()); + } transport_task_runner_->PostDelayedTask( FROM_HERE, @@ -390,35 +389,40 @@ bool CastTransportSenderImpl::OnReceivedPacket(scoped_ptr<Packet> packet) { void CastTransportSenderImpl::OnReceivedLogMessage( EventMediaType media_type, const RtcpReceiverLogMessage& log) { + if (raw_events_callback_.is_null()) + return; + // Add received log messages into our log system. - RtcpReceiverLogMessage::const_iterator it = log.begin(); - for (; it != log.end(); ++it) { - uint32 rtp_timestamp = it->rtp_timestamp_; - - RtcpReceiverEventLogMessages::const_iterator event_it = - it->event_log_messages_.begin(); - for (; event_it != it->event_log_messages_.end(); ++event_it) { - switch (event_it->type) { - case PACKET_RECEIVED: - logging_.InsertPacketEvent( - event_it->event_timestamp, event_it->type, - media_type, rtp_timestamp, - kFrameIdUnknown, event_it->packet_id, 0, 0); + for (const RtcpReceiverFrameLogMessage& frame_log_message : log) { + for (const RtcpReceiverEventLogMessage& event_log_message : + frame_log_message.event_log_messages_) { + switch (event_log_message.type) { + case PACKET_RECEIVED: { + recent_packet_events_.push_back(PacketEvent()); + PacketEvent& receive_event = recent_packet_events_.back(); + receive_event.timestamp = event_log_message.event_timestamp; + receive_event.type = event_log_message.type; + receive_event.media_type = media_type; + receive_event.rtp_timestamp = frame_log_message.rtp_timestamp_; + receive_event.packet_id = event_log_message.packet_id; break; + } case FRAME_ACK_SENT: case FRAME_DECODED: - logging_.InsertFrameEvent( - event_it->event_timestamp, event_it->type, media_type, - rtp_timestamp, kFrameIdUnknown); - break; - case FRAME_PLAYOUT: - logging_.InsertFrameEventWithDelay( - event_it->event_timestamp, event_it->type, media_type, - rtp_timestamp, kFrameIdUnknown, event_it->delay_delta); + case FRAME_PLAYOUT: { + recent_frame_events_.push_back(FrameEvent()); + FrameEvent& frame_event = recent_frame_events_.back(); + frame_event.timestamp = event_log_message.event_timestamp; + frame_event.type = event_log_message.type; + frame_event.media_type = media_type; + frame_event.rtp_timestamp = frame_log_message.rtp_timestamp_; + if (event_log_message.type == FRAME_PLAYOUT) + frame_event.delay_delta = event_log_message.delay_delta; break; + } default: VLOG(2) << "Received log message via RTCP that we did not expect: " - << static_cast<int>(event_it->type); + << event_log_message.type; break; } } diff --git a/media/cast/net/cast_transport_sender_impl.h b/media/cast/net/cast_transport_sender_impl.h index a5538e7..7a83afd 100644 --- a/media/cast/net/cast_transport_sender_impl.h +++ b/media/cast/net/cast_transport_sender_impl.h @@ -25,6 +25,7 @@ #define MEDIA_CAST_NET_CAST_TRANSPORT_SENDER_IMPL_H_ #include <set> +#include <vector> #include "base/callback.h" #include "base/gtest_prod_util.h" @@ -35,7 +36,6 @@ #include "base/time/time.h" #include "media/cast/common/transport_encryption_handler.h" #include "media/cast/logging/logging_defines.h" -#include "media/cast/logging/simple_event_subscriber.h" #include "media/cast/net/cast_transport_config.h" #include "media/cast/net/cast_transport_sender.h" #include "media/cast/net/pacing/paced_sender.h" @@ -136,7 +136,7 @@ class CastTransportSenderImpl : public CastTransportSender { const DedupInfo& dedup_info); // If |raw_events_callback_| is non-null, calls it with events collected - // by |event_subscriber_| since last call. + // in |recent_frame_events_| and |recent_packet_events_| since last call. void SendRawEvents(); // Called when a packet is received. @@ -155,7 +155,10 @@ class CastTransportSenderImpl : public CastTransportSender { CastTransportStatusCallback status_callback_; scoped_refptr<base::SingleThreadTaskRunner> transport_task_runner_; - LoggingImpl logging_; + // FrameEvents and PacketEvents pending delivery via |raw_events_callback_|. + // Do not add elements to these when |raw_events_callback_.is_null()|. + std::vector<FrameEvent> recent_frame_events_; + std::vector<PacketEvent> recent_packet_events_; // Interface to a UDP socket. scoped_ptr<UdpTransport> transport_; @@ -178,9 +181,6 @@ class CastTransportSenderImpl : public CastTransportSender { TransportEncryptionHandler audio_encryptor_; TransportEncryptionHandler video_encryptor_; - // This is non-null iff |raw_events_callback_| is non-null. - scoped_ptr<SimpleEventSubscriber> event_subscriber_; - BulkRawEventsCallback raw_events_callback_; base::TimeDelta raw_events_callback_interval_; diff --git a/media/cast/net/cast_transport_sender_impl_unittest.cc b/media/cast/net/cast_transport_sender_impl_unittest.cc index 921bddf..9758f3e 100644 --- a/media/cast/net/cast_transport_sender_impl_unittest.cc +++ b/media/cast/net/cast_transport_sender_impl_unittest.cc @@ -66,8 +66,7 @@ class FakePacketSender : public PacketSender { class CastTransportSenderImplTest : public ::testing::Test { protected: - CastTransportSenderImplTest() - : num_times_callback_called_(0) { + CastTransportSenderImplTest() : num_times_logging_callback_called_(0) { testing_clock_.Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); task_runner_ = new test::FakeSingleThreadTaskRunner(&testing_clock_); @@ -151,9 +150,9 @@ class CastTransportSenderImplTest : public ::testing::Test { RtcpRttCallback()); } - void LogRawEvents(const std::vector<PacketEvent>& packet_events, - const std::vector<FrameEvent>& frame_events) { - num_times_callback_called_++; + void LogRawEvents(scoped_ptr<std::vector<FrameEvent>> frame_events, + scoped_ptr<std::vector<PacketEvent>> packet_events) { + num_times_logging_callback_called_++; } static void UpdateCastTransportStatus(CastTransportStatus status) { @@ -163,31 +162,26 @@ class CastTransportSenderImplTest : public ::testing::Test { scoped_refptr<test::FakeSingleThreadTaskRunner> task_runner_; scoped_ptr<CastTransportSenderImpl> transport_sender_; FakePacketSender transport_; - int num_times_callback_called_; + int num_times_logging_callback_called_; }; TEST_F(CastTransportSenderImplTest, InitWithoutLogging) { InitWithoutLogging(); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); - EXPECT_EQ(0, num_times_callback_called_); -} - -TEST_F(CastTransportSenderImplTest, InitWithLogging) { - InitWithLogging(); - task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); - EXPECT_EQ(5, num_times_callback_called_); + EXPECT_EQ(0, num_times_logging_callback_called_); } TEST_F(CastTransportSenderImplTest, InitWithOptions) { InitWithOptions(); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); - EXPECT_EQ(0, num_times_callback_called_); + EXPECT_EQ(0, num_times_logging_callback_called_); } TEST_F(CastTransportSenderImplTest, NacksCancelRetransmits) { - InitWithoutLogging(); + InitWithLogging(); InitializeVideo(); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); + EXPECT_EQ(0, num_times_logging_callback_called_); // A fake frame that will be decomposed into 4 packets. EncodedFrame fake_frame; @@ -199,6 +193,7 @@ TEST_F(CastTransportSenderImplTest, NacksCancelRetransmits) { transport_sender_->InsertFrame(kVideoSsrc, fake_frame); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(10)); EXPECT_EQ(4, transport_.packets_sent()); + EXPECT_EQ(1, num_times_logging_callback_called_); // Resend packet 0. MissingFramesAndPacketsMap missing_packets; @@ -213,6 +208,7 @@ TEST_F(CastTransportSenderImplTest, NacksCancelRetransmits) { kVideoSsrc, missing_packets, true, dedup_info); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(10)); + EXPECT_EQ(2, num_times_logging_callback_called_); RtcpCastMessage cast_message; cast_message.media_ssrc = kVideoSsrc; @@ -223,6 +219,7 @@ TEST_F(CastTransportSenderImplTest, NacksCancelRetransmits) { cast_message); transport_.SetPaused(false); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(10)); + EXPECT_EQ(3, num_times_logging_callback_called_); // Resend one packet in the socket when unpaused. // Resend one more packet from NACK. @@ -230,9 +227,10 @@ TEST_F(CastTransportSenderImplTest, NacksCancelRetransmits) { } TEST_F(CastTransportSenderImplTest, CancelRetransmits) { - InitWithoutLogging(); + InitWithLogging(); InitializeVideo(); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); + EXPECT_EQ(0, num_times_logging_callback_called_); // A fake frame that will be decomposed into 4 packets. EncodedFrame fake_frame; @@ -244,6 +242,7 @@ TEST_F(CastTransportSenderImplTest, CancelRetransmits) { transport_sender_->InsertFrame(kVideoSsrc, fake_frame); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(10)); EXPECT_EQ(4, transport_.packets_sent()); + EXPECT_EQ(1, num_times_logging_callback_called_); // Resend all packets for frame 1. MissingFramesAndPacketsMap missing_packets; @@ -256,21 +255,25 @@ TEST_F(CastTransportSenderImplTest, CancelRetransmits) { kVideoSsrc, missing_packets, true, dedup_info); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(10)); + EXPECT_EQ(2, num_times_logging_callback_called_); + std::vector<uint32> cancel_sending_frames; cancel_sending_frames.push_back(1); transport_sender_->CancelSendingFrames(kVideoSsrc, cancel_sending_frames); transport_.SetPaused(false); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(10)); + EXPECT_EQ(2, num_times_logging_callback_called_); // Resend one packet in the socket when unpaused. EXPECT_EQ(5, transport_.packets_sent()); } TEST_F(CastTransportSenderImplTest, Kickstart) { - InitWithoutLogging(); + InitWithLogging(); InitializeVideo(); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); + EXPECT_EQ(0, num_times_logging_callback_called_); // A fake frame that will be decomposed into 4 packets. EncodedFrame fake_frame; @@ -285,6 +288,7 @@ TEST_F(CastTransportSenderImplTest, Kickstart) { transport_.SetPaused(false); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(10)); EXPECT_EQ(4, transport_.packets_sent()); + EXPECT_EQ(1, num_times_logging_callback_called_); // Resend 2 packets for frame 1. MissingFramesAndPacketsMap missing_packets; @@ -299,6 +303,7 @@ TEST_F(CastTransportSenderImplTest, Kickstart) { transport_sender_->ResendFrameForKickstart(kVideoSsrc, 1); transport_.SetPaused(false); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(10)); + EXPECT_EQ(2, num_times_logging_callback_called_); // Resend one packet in the socket when unpaused. // Two more retransmission packets sent. @@ -306,10 +311,11 @@ TEST_F(CastTransportSenderImplTest, Kickstart) { } TEST_F(CastTransportSenderImplTest, DedupRetransmissionWithAudio) { - InitWithoutLogging(); + InitWithLogging(); InitializeAudio(); InitializeVideo(); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); + EXPECT_EQ(0, num_times_logging_callback_called_); // Send two audio frames. EncodedFrame fake_audio; @@ -334,6 +340,7 @@ TEST_F(CastTransportSenderImplTest, DedupRetransmissionWithAudio) { cast_message); task_runner_->RunTasks(); EXPECT_EQ(2, transport_.packets_sent()); + EXPECT_EQ(0, num_times_logging_callback_called_); // Only 4 ms since last. // Send a fake video frame that will be decomposed into 4 packets. EncodedFrame fake_video; @@ -343,6 +350,7 @@ TEST_F(CastTransportSenderImplTest, DedupRetransmissionWithAudio) { transport_sender_->InsertFrame(kVideoSsrc, fake_video); task_runner_->RunTasks(); EXPECT_EQ(6, transport_.packets_sent()); + EXPECT_EQ(0, num_times_logging_callback_called_); // Only 4 ms since last. // Retransmission is reject because audio is not acked yet. cast_message.media_ssrc = kVideoSsrc; @@ -354,6 +362,7 @@ TEST_F(CastTransportSenderImplTest, DedupRetransmissionWithAudio) { cast_message); task_runner_->RunTasks(); EXPECT_EQ(6, transport_.packets_sent()); + EXPECT_EQ(1, num_times_logging_callback_called_); // Ack the second audio frame. cast_message.media_ssrc = kAudioSsrc; @@ -365,6 +374,7 @@ TEST_F(CastTransportSenderImplTest, DedupRetransmissionWithAudio) { cast_message); task_runner_->RunTasks(); EXPECT_EQ(6, transport_.packets_sent()); + EXPECT_EQ(1, num_times_logging_callback_called_); // Only 6 ms since last. // Retransmission of video packet now accepted. cast_message.media_ssrc = kVideoSsrc; @@ -376,6 +386,10 @@ TEST_F(CastTransportSenderImplTest, DedupRetransmissionWithAudio) { cast_message); task_runner_->RunTasks(); EXPECT_EQ(7, transport_.packets_sent()); + EXPECT_EQ(1, num_times_logging_callback_called_); // Only 8 ms since last. + + task_runner_->Sleep(base::TimeDelta::FromMilliseconds(2)); + EXPECT_EQ(2, num_times_logging_callback_called_); } } // namespace cast diff --git a/media/cast/net/pacing/paced_sender.cc b/media/cast/net/pacing/paced_sender.cc index 6b39f07..b8642b1 100644 --- a/media/cast/net/pacing/paced_sender.cc +++ b/media/cast/net/pacing/paced_sender.cc @@ -8,7 +8,6 @@ #include "base/bind.h" #include "base/debug/dump_without_crashing.h" #include "base/message_loop/message_loop.h" -#include "media/cast/logging/logging_impl.h" namespace media { namespace cast { @@ -45,11 +44,11 @@ PacedSender::PacedSender( size_t target_burst_size, size_t max_burst_size, base::TickClock* clock, - LoggingImpl* logging, + std::vector<PacketEvent>* recent_packet_events, PacketSender* transport, const scoped_refptr<base::SingleThreadTaskRunner>& transport_task_runner) : clock_(clock), - logging_(logging), + recent_packet_events_(recent_packet_events), transport_(transport), transport_task_runner_(transport_task_runner), audio_ssrc_(0), @@ -62,8 +61,7 @@ PacedSender::PacedSender( current_burst_size_(0), state_(State_Unblocked), has_reached_upper_bound_once_(false), - weak_factory_(this) { -} + weak_factory_(this) {} PacedSender::~PacedSender() {} @@ -320,27 +318,37 @@ void PacedSender::SendStoredPackets() { state_ = State_Unblocked; } -void PacedSender::LogPacketEvent(const Packet& packet, CastLoggingEvent event) { - // Get SSRC from packet and compare with the audio_ssrc / video_ssrc to see - // if the packet is audio or video. - DCHECK_GE(packet.size(), 12u); - base::BigEndianReader reader(reinterpret_cast<const char*>(&packet[8]), 4); +void PacedSender::LogPacketEvent(const Packet& packet, CastLoggingEvent type) { + if (!recent_packet_events_) + return; + + recent_packet_events_->push_back(PacketEvent()); + PacketEvent& event = recent_packet_events_->back(); + + // Populate the new PacketEvent by parsing the wire-format |packet|. + // + // TODO(miu): This parsing logic belongs in RtpParser. + event.timestamp = clock_->NowTicks(); + event.type = type; + base::BigEndianReader reader(reinterpret_cast<const char*>(&packet[0]), + packet.size()); + bool success = reader.Skip(4); + success &= reader.ReadU32(&event.rtp_timestamp); uint32 ssrc; - bool success = reader.ReadU32(&ssrc); - DCHECK(success); - bool is_audio; + success &= reader.ReadU32(&ssrc); if (ssrc == audio_ssrc_) { - is_audio = true; + event.media_type = AUDIO_EVENT; } else if (ssrc == video_ssrc_) { - is_audio = false; + event.media_type = VIDEO_EVENT; } else { DVLOG(3) << "Got unknown ssrc " << ssrc << " when logging packet event"; return; } - - EventMediaType media_type = is_audio ? AUDIO_EVENT : VIDEO_EVENT; - logging_->InsertSinglePacketEvent(clock_->NowTicks(), event, media_type, - packet); + success &= reader.Skip(2); + success &= reader.ReadU16(&event.packet_id); + success &= reader.ReadU16(&event.max_packet_id); + event.size = packet.size(); + DCHECK(success); } } // namespace cast diff --git a/media/cast/net/pacing/paced_sender.h b/media/cast/net/pacing/paced_sender.h index 122cf55..a5fcfd17 100644 --- a/media/cast/net/pacing/paced_sender.h +++ b/media/cast/net/pacing/paced_sender.h @@ -26,8 +26,6 @@ namespace cast { static const size_t kTargetBurstSize = 10; static const size_t kMaxBurstSize = 20; -class LoggingImpl; - // Use std::pair for free comparison operators. // { capture_time, ssrc, packet_id } // The PacketKey is designed to meet two criteria: @@ -79,13 +77,15 @@ class PacedSender : public PacedPacketSender, public base::NonThreadSafe, public base::SupportsWeakPtr<PacedSender> { public: - // The |external_transport| should only be used by the Cast receiver and for + // |recent_packet_events| is an externally-owned vector where PacedSender will + // add PacketEvents related to sending, retransmission, and rejection. The + // |external_transport| should only be used by the Cast receiver and for // testing. PacedSender( size_t target_burst_size, // Should normally be kTargetBurstSize. size_t max_burst_size, // Should normally be kMaxBurstSize. base::TickClock* clock, - LoggingImpl* logging, + std::vector<PacketEvent>* recent_packet_events, PacketSender* external_transport, const scoped_refptr<base::SingleThreadTaskRunner>& transport_task_runner); @@ -120,6 +120,9 @@ class PacedSender : public PacedPacketSender, private: // Actually sends the packets to the transport. void SendStoredPackets(); + + // Convenience method for building a PacketEvent and storing it in the + // externally-owned container of |recent_packet_events_|. void LogPacketEvent(const Packet& packet, CastLoggingEvent event); // Returns true if retransmission for packet indexed by |packet_key| is @@ -163,9 +166,11 @@ class PacedSender : public PacedPacketSender, // Returns true if the packet should have a higher priority. bool IsHighPriority(const PacketKey& packet_key) const; - base::TickClock* const clock_; // Not owned by this class. - LoggingImpl* const logging_; // Not owned by this class. - PacketSender* transport_; // Not owned by this class. + // These are externally-owned objects injected via the constructor. + base::TickClock* const clock_; + std::vector<PacketEvent>* const recent_packet_events_; + PacketSender* const transport_; + scoped_refptr<base::SingleThreadTaskRunner> transport_task_runner_; uint32 audio_ssrc_; uint32 video_ssrc_; diff --git a/media/cast/net/pacing/paced_sender_unittest.cc b/media/cast/net/pacing/paced_sender_unittest.cc index 2387d42..13d5afd 100644 --- a/media/cast/net/pacing/paced_sender_unittest.cc +++ b/media/cast/net/pacing/paced_sender_unittest.cc @@ -6,8 +6,6 @@ #include "base/big_endian.h" #include "base/test/simple_test_tick_clock.h" -#include "media/cast/logging/logging_impl.h" -#include "media/cast/logging/simple_event_subscriber.h" #include "media/cast/net/pacing/paced_sender.h" #include "media/cast/test/fake_single_thread_task_runner.h" #include "testing/gmock/include/gmock/gmock.h" @@ -27,6 +25,7 @@ static const size_t kNackSize = 105; static const int64 kStartMillisecond = INT64_C(12345678900000); static const uint32 kVideoSsrc = 0x1234; static const uint32 kAudioSsrc = 0x5678; +static const uint32 kFrameRtpTimestamp = 12345; class TestPacketSender : public PacketSender { public: @@ -59,24 +58,16 @@ class TestPacketSender : public PacketSender { class PacedSenderTest : public ::testing::Test { protected: PacedSenderTest() { - logging_.AddRawEventSubscriber(&subscriber_); testing_clock_.Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); task_runner_ = new test::FakeSingleThreadTaskRunner(&testing_clock_); - paced_sender_.reset(new PacedSender(kTargetBurstSize, - kMaxBurstSize, - &testing_clock_, - &logging_, - &mock_transport_, - task_runner_)); + paced_sender_.reset(new PacedSender(kTargetBurstSize, kMaxBurstSize, + &testing_clock_, &packet_events_, + &mock_transport_, task_runner_)); paced_sender_->RegisterAudioSsrc(kAudioSsrc); paced_sender_->RegisterVideoSsrc(kVideoSsrc); } - ~PacedSenderTest() override { - logging_.RemoveRawEventSubscriber(&subscriber_); - } - static void UpdateCastTransportStatus(CastTransportStatus status) { NOTREACHED(); } @@ -98,12 +89,17 @@ class PacedSenderTest : public ::testing::Test { PacketRef packet(new base::RefCountedData<Packet>); packet->data.resize(packet_size, kValue); - // Write ssrc to packet so that it can be recognized as a - // "video frame" for logging purposes. - base::BigEndianWriter writer( - reinterpret_cast<char*>(&packet->data[8]), 4); - bool success = writer.WriteU32(audio ? kAudioSsrc : kVideoSsrc); - DCHECK(success); + // Fill-in packet header fields to test the header parsing (for populating + // the logging events). + base::BigEndianWriter writer(reinterpret_cast<char*>(&packet->data[0]), + packet_size); + bool success = writer.Skip(4); + success &= writer.WriteU32(kFrameRtpTimestamp); + success &= writer.WriteU32(audio ? kAudioSsrc : kVideoSsrc); + success &= writer.Skip(2); + success &= writer.WriteU16(i); + success &= writer.WriteU16(num_of_packets_in_frame - 1); + CHECK(success); packets.push_back(std::make_pair(key, packet)); } return packets; @@ -123,8 +119,7 @@ class PacedSenderTest : public ::testing::Test { return mock_transport_.expected_packet_size_.empty(); } - LoggingImpl logging_; - SimpleEventSubscriber subscriber_; + std::vector<PacketEvent> packet_events_; base::SimpleTestTickClock testing_clock_; TestPacketSender mock_transport_; scoped_refptr<test::FakeSingleThreadTaskRunner> task_runner_; @@ -154,6 +149,7 @@ TEST_F(PacedSenderTest, BasicPace) { SendPacketVector packets = CreateSendPacketVector(kSize1, num_of_packets, false); + const base::TimeTicks earliest_event_timestamp = testing_clock_.NowTicks(); mock_transport_.AddExpectedSize(kSize1, 10); EXPECT_TRUE(paced_sender_->SendPackets(packets)); @@ -177,20 +173,21 @@ TEST_F(PacedSenderTest, BasicPace) { // Check that we don't get any more packets. EXPECT_TRUE(RunUntilEmpty(3)); - - std::vector<PacketEvent> packet_events; - subscriber_.GetPacketEventsAndReset(&packet_events); - EXPECT_EQ(num_of_packets, static_cast<int>(packet_events.size())); - int sent_to_network_event_count = 0; - for (std::vector<PacketEvent>::iterator it = packet_events.begin(); - it != packet_events.end(); - ++it) { - if (it->type == PACKET_SENT_TO_NETWORK) - sent_to_network_event_count++; - else - FAIL() << "Got unexpected event type " << CastLoggingToString(it->type); + const base::TimeTicks latest_event_timestamp = testing_clock_.NowTicks(); + + // Check that packet logging events match expected values. + EXPECT_EQ(num_of_packets, static_cast<int>(packet_events_.size())); + uint16 expected_packet_id = 0; + for (const PacketEvent& e : packet_events_) { + ASSERT_LE(earliest_event_timestamp, e.timestamp); + ASSERT_GE(latest_event_timestamp, e.timestamp); + ASSERT_EQ(PACKET_SENT_TO_NETWORK, e.type); + ASSERT_EQ(VIDEO_EVENT, e.media_type); + ASSERT_EQ(kFrameRtpTimestamp, e.rtp_timestamp); + ASSERT_EQ(num_of_packets - 1, e.max_packet_id); + ASSERT_EQ(expected_packet_id++, e.packet_id); + ASSERT_EQ(kSize1, e.size); } - EXPECT_EQ(num_of_packets, sent_to_network_event_count); } TEST_F(PacedSenderTest, PaceWithNack) { @@ -249,32 +246,28 @@ TEST_F(PacedSenderTest, PaceWithNack) { // No more packets. EXPECT_TRUE(RunUntilEmpty(5)); - std::vector<PacketEvent> packet_events; - subscriber_.GetPacketEventsAndReset(&packet_events); int expected_video_network_event_count = num_of_packets_in_frame; int expected_video_retransmitted_event_count = 2 * num_of_packets_in_nack; expected_video_retransmitted_event_count -= 2; // 2 packets deduped int expected_audio_network_event_count = num_of_packets_in_frame; EXPECT_EQ(expected_video_network_event_count + - expected_video_retransmitted_event_count + - expected_audio_network_event_count, - static_cast<int>(packet_events.size())); + expected_video_retransmitted_event_count + + expected_audio_network_event_count, + static_cast<int>(packet_events_.size())); int audio_network_event_count = 0; int video_network_event_count = 0; int video_retransmitted_event_count = 0; - for (std::vector<PacketEvent>::iterator it = packet_events.begin(); - it != packet_events.end(); - ++it) { - if (it->type == PACKET_SENT_TO_NETWORK) { - if (it->media_type == VIDEO_EVENT) + for (const PacketEvent& e : packet_events_) { + if (e.type == PACKET_SENT_TO_NETWORK) { + if (e.media_type == VIDEO_EVENT) video_network_event_count++; else audio_network_event_count++; - } else if (it->type == PACKET_RETRANSMITTED) { - if (it->media_type == VIDEO_EVENT) + } else if (e.type == PACKET_RETRANSMITTED) { + if (e.media_type == VIDEO_EVENT) video_retransmitted_event_count++; } else { - FAIL() << "Got unexpected event type " << CastLoggingToString(it->type); + FAIL() << "Got unexpected event type " << CastLoggingToString(e.type); } } EXPECT_EQ(expected_audio_network_event_count, audio_network_event_count); diff --git a/media/cast/net/rtcp/receiver_rtcp_event_subscriber_unittest.cc b/media/cast/net/rtcp/receiver_rtcp_event_subscriber_unittest.cc index bd31d24..4980494 100644 --- a/media/cast/net/rtcp/receiver_rtcp_event_subscriber_unittest.cc +++ b/media/cast/net/rtcp/receiver_rtcp_event_subscriber_unittest.cc @@ -37,56 +37,92 @@ class ReceiverRtcpEventSubscriberTest : public ::testing::Test { void TearDown() final { if (event_subscriber_) { - cast_environment_->Logging()->RemoveRawEventSubscriber( - event_subscriber_.get()); + cast_environment_->logger()->Unsubscribe(event_subscriber_.get()); + event_subscriber_.reset(); } } void Init(EventMediaType type) { event_subscriber_.reset( new ReceiverRtcpEventSubscriber(kMaxEventEntries, type)); - cast_environment_->Logging()->AddRawEventSubscriber( - event_subscriber_.get()); + cast_environment_->logger()->Subscribe(event_subscriber_.get()); } void InsertEvents() { // Video events - cast_environment_->Logging()->InsertFrameEventWithDelay( - testing_clock_->NowTicks(), FRAME_PLAYOUT, VIDEO_EVENT, - /*rtp_timestamp*/ 100u, /*frame_id*/ 2u, - base::TimeDelta::FromMilliseconds(kDelayMs)); - cast_environment_->Logging()->InsertFrameEvent( - testing_clock_->NowTicks(), FRAME_DECODED, VIDEO_EVENT, - /*rtp_timestamp*/ 200u, /*frame_id*/ 1u); - cast_environment_->Logging()->InsertPacketEvent( - testing_clock_->NowTicks(), PACKET_RECEIVED, VIDEO_EVENT, - /*rtp_timestamp */ 200u, /*frame_id*/ 2u, /*packet_id*/ 1u, - /*max_packet_id*/ 10u, /*size*/ 1024u); + scoped_ptr<FrameEvent> playout_event(new FrameEvent()); + playout_event->timestamp = testing_clock_->NowTicks(); + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = VIDEO_EVENT; + playout_event->rtp_timestamp = 100u; + playout_event->frame_id = 2u; + playout_event->delay_delta = base::TimeDelta::FromMilliseconds(kDelayMs); + cast_environment_->logger()->DispatchFrameEvent(playout_event.Pass()); + + scoped_ptr<FrameEvent> decode_event(new FrameEvent()); + decode_event->timestamp = testing_clock_->NowTicks(); + decode_event->type = FRAME_DECODED; + decode_event->media_type = VIDEO_EVENT; + decode_event->rtp_timestamp = 200u; + decode_event->frame_id = 1u; + cast_environment_->logger()->DispatchFrameEvent(decode_event.Pass()); + + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = testing_clock_->NowTicks(); + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = VIDEO_EVENT; + receive_event->rtp_timestamp = 200u; + receive_event->frame_id = 2u; + receive_event->packet_id = 1u; + receive_event->max_packet_id = 10u; + receive_event->size = 1024u; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); // Audio events - cast_environment_->Logging()->InsertFrameEventWithDelay( - testing_clock_->NowTicks(), FRAME_PLAYOUT, AUDIO_EVENT, - /*rtp_timestamp*/ 300u, /*frame_id*/ 4u, - base::TimeDelta::FromMilliseconds(kDelayMs)); - cast_environment_->Logging()->InsertFrameEvent( - testing_clock_->NowTicks(), FRAME_DECODED, AUDIO_EVENT, - /*rtp_timestamp*/ 400u, /*frame_id*/ 3u); - cast_environment_->Logging()->InsertPacketEvent( - testing_clock_->NowTicks(), PACKET_RECEIVED, AUDIO_EVENT, - /*rtp_timestamp */ 400u, /*frame_id*/ 5u, /*packet_id*/ 1u, - /*max_packet_id*/ 10u, /*size*/ 128u); + playout_event.reset(new FrameEvent()); + playout_event->timestamp = testing_clock_->NowTicks(); + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = AUDIO_EVENT; + playout_event->rtp_timestamp = 300u; + playout_event->frame_id = 4u; + playout_event->delay_delta = base::TimeDelta::FromMilliseconds(kDelayMs); + cast_environment_->logger()->DispatchFrameEvent(playout_event.Pass()); + + decode_event.reset(new FrameEvent()); + decode_event->timestamp = testing_clock_->NowTicks(); + decode_event->type = FRAME_DECODED; + decode_event->media_type = AUDIO_EVENT; + decode_event->rtp_timestamp = 400u; + decode_event->frame_id = 3u; + cast_environment_->logger()->DispatchFrameEvent(decode_event.Pass()); + + receive_event.reset(new PacketEvent()); + receive_event->timestamp = testing_clock_->NowTicks(); + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = AUDIO_EVENT; + receive_event->rtp_timestamp = 400u; + receive_event->frame_id = 5u; + receive_event->packet_id = 1u; + receive_event->max_packet_id = 10u; + receive_event->size = 128u; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); // Unrelated events - cast_environment_->Logging()->InsertFrameEvent(testing_clock_->NowTicks(), - FRAME_CAPTURE_END, - VIDEO_EVENT, - /*rtp_timestamp*/ 100u, - /*frame_id*/ 1u); - cast_environment_->Logging()->InsertFrameEvent(testing_clock_->NowTicks(), - FRAME_CAPTURE_END, - AUDIO_EVENT, - /*rtp_timestamp*/ 100u, - /*frame_id*/ 1u); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = testing_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = VIDEO_EVENT; + encode_event->rtp_timestamp = 100u; + encode_event->frame_id = 1u; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); + + encode_event.reset(new FrameEvent()); + encode_event->timestamp = testing_clock_->NowTicks(); + encode_event->type = FRAME_ENCODED; + encode_event->media_type = AUDIO_EVENT; + encode_event->rtp_timestamp = 100u; + encode_event->frame_id = 1u; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); } base::SimpleTestTickClock* testing_clock_; // Owned by CastEnvironment. @@ -117,9 +153,13 @@ TEST_F(ReceiverRtcpEventSubscriberTest, DropEventsWhenSizeExceeded) { Init(VIDEO_EVENT); for (uint32 i = 1u; i <= 10u; ++i) { - cast_environment_->Logging()->InsertFrameEvent( - testing_clock_->NowTicks(), FRAME_DECODED, VIDEO_EVENT, - /*rtp_timestamp*/ i * 10, /*frame_id*/ i); + scoped_ptr<FrameEvent> decode_event(new FrameEvent()); + decode_event->timestamp = testing_clock_->NowTicks(); + decode_event->type = FRAME_DECODED; + decode_event->media_type = VIDEO_EVENT; + decode_event->rtp_timestamp = i * 10; + decode_event->frame_id = i; + cast_environment_->logger()->DispatchFrameEvent(decode_event.Pass()); } ReceiverRtcpEventSubscriber::RtcpEvents rtcp_events; diff --git a/media/cast/net/rtp/rtp_packetizer_unittest.cc b/media/cast/net/rtp/rtp_packetizer_unittest.cc index 6669b5e..12cafd6 100644 --- a/media/cast/net/rtp/rtp_packetizer_unittest.cc +++ b/media/cast/net/rtp/rtp_packetizer_unittest.cc @@ -8,8 +8,6 @@ #include "base/memory/scoped_ptr.h" #include "base/test/simple_test_tick_clock.h" -#include "media/cast/logging/logging_impl.h" -#include "media/cast/logging/simple_event_subscriber.h" #include "media/cast/net/pacing/paced_sender.h" #include "media/cast/net/rtp/packet_storage.h" #include "media/cast/net/rtp/rtp_parser.h" @@ -114,11 +112,8 @@ class RtpPacketizerTest : public ::testing::Test { config_.payload_type = kPayload; config_.max_payload_length = kMaxPacketLength; transport_.reset(new TestRtpPacketTransport(config_)); - pacer_.reset(new PacedSender(kTargetBurstSize, - kMaxBurstSize, - &testing_clock_, - &logging_, - transport_.get(), + pacer_.reset(new PacedSender(kTargetBurstSize, kMaxBurstSize, + &testing_clock_, nullptr, transport_.get(), task_runner_)); pacer_->RegisterVideoSsrc(config_.ssrc); rtp_packetizer_.reset(new RtpPacketizer( @@ -144,7 +139,6 @@ class RtpPacketizerTest : public ::testing::Test { PacketStorage packet_storage_; RtpPacketizerConfig config_; scoped_ptr<TestRtpPacketTransport> transport_; - LoggingImpl logging_; scoped_ptr<PacedSender> pacer_; scoped_ptr<RtpPacketizer> rtp_packetizer_; diff --git a/media/cast/receiver/audio_decoder.cc b/media/cast/receiver/audio_decoder.cc index f8a40be..929deb5 100644 --- a/media/cast/receiver/audio_decoder.cc +++ b/media/cast/receiver/audio_decoder.cc @@ -59,6 +59,15 @@ class AudioDecoder::ImplBase scoped_ptr<AudioBus> decoded_audio = Decode( encoded_frame->mutable_bytes(), static_cast<int>(encoded_frame->data.size())); + + scoped_ptr<FrameEvent> event(new FrameEvent()); + event->timestamp = cast_environment_->Clock()->NowTicks(); + event->type = FRAME_DECODED; + event->media_type = AUDIO_EVENT; + event->rtp_timestamp = encoded_frame->rtp_timestamp; + event->frame_id = encoded_frame->frame_id; + cast_environment_->logger()->DispatchFrameEvent(event.Pass()); + cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, base::Bind(callback, diff --git a/media/cast/receiver/cast_receiver_impl.cc b/media/cast/receiver/cast_receiver_impl.cc index 5a01bb0..83d8bf7 100644 --- a/media/cast/receiver/cast_receiver_impl.cc +++ b/media/cast/receiver/cast_receiver_impl.cc @@ -178,14 +178,20 @@ void CastReceiverImpl::EmitDecodedAudioFrame( scoped_ptr<AudioBus> audio_bus, bool is_continuous) { DCHECK(cast_environment->CurrentlyOn(CastEnvironment::MAIN)); + if (audio_bus.get()) { - const base::TimeTicks now = cast_environment->Clock()->NowTicks(); - cast_environment->Logging()->InsertFrameEvent( - now, FRAME_DECODED, AUDIO_EVENT, rtp_timestamp, frame_id); - cast_environment->Logging()->InsertFrameEventWithDelay( - now, FRAME_PLAYOUT, AUDIO_EVENT, rtp_timestamp, frame_id, - playout_time - now); + // TODO(miu): This is reporting incorrect timestamp and delay. + // http://crbug.com/547251 + scoped_ptr<FrameEvent> playout_event(new FrameEvent()); + playout_event->timestamp = cast_environment->Clock()->NowTicks(); + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = AUDIO_EVENT; + playout_event->rtp_timestamp = rtp_timestamp; + playout_event->frame_id = frame_id; + playout_event->delay_delta = playout_time - playout_event->timestamp; + cast_environment->logger()->DispatchFrameEvent(playout_event.Pass()); } + callback.Run(audio_bus.Pass(), playout_time, is_continuous); } @@ -199,13 +205,18 @@ void CastReceiverImpl::EmitDecodedVideoFrame( const scoped_refptr<VideoFrame>& video_frame, bool is_continuous) { DCHECK(cast_environment->CurrentlyOn(CastEnvironment::MAIN)); + if (video_frame.get()) { - const base::TimeTicks now = cast_environment->Clock()->NowTicks(); - cast_environment->Logging()->InsertFrameEvent( - now, FRAME_DECODED, VIDEO_EVENT, rtp_timestamp, frame_id); - cast_environment->Logging()->InsertFrameEventWithDelay( - now, FRAME_PLAYOUT, VIDEO_EVENT, rtp_timestamp, frame_id, - playout_time - now); + // TODO(miu): This is reporting incorrect timestamp and delay. + // http://crbug.com/547251 + scoped_ptr<FrameEvent> playout_event(new FrameEvent()); + playout_event->timestamp = cast_environment->Clock()->NowTicks(); + playout_event->type = FRAME_PLAYOUT; + playout_event->media_type = VIDEO_EVENT; + playout_event->rtp_timestamp = rtp_timestamp; + playout_event->frame_id = frame_id; + playout_event->delay_delta = playout_time - playout_event->timestamp; + cast_environment->logger()->DispatchFrameEvent(playout_event.Pass()); // Used by chrome/browser/extension/api/cast_streaming/performance_test.cc TRACE_EVENT_INSTANT1( @@ -213,6 +224,7 @@ void CastReceiverImpl::EmitDecodedVideoFrame( TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp); } + callback.Run(video_frame, playout_time, is_continuous); } diff --git a/media/cast/receiver/frame_receiver.cc b/media/cast/receiver/frame_receiver.cc index c0b15df..3d89594 100644 --- a/media/cast/receiver/frame_receiver.cc +++ b/media/cast/receiver/frame_receiver.cc @@ -55,13 +55,13 @@ FrameReceiver::FrameReceiver( DCHECK_GT(config.rtp_max_delay_ms, 0); DCHECK_GT(config.target_frame_rate, 0); decryptor_.Initialize(config.aes_key, config.aes_iv_mask); - cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_); + cast_environment_->logger()->Subscribe(&event_subscriber_); memset(frame_id_to_rtp_timestamp_, 0, sizeof(frame_id_to_rtp_timestamp_)); } FrameReceiver::~FrameReceiver() { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); - cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); + cast_environment_->logger()->Unsubscribe(&event_subscriber_); } void FrameReceiver::RequestEncodedFrame( @@ -110,10 +110,17 @@ void FrameReceiver::ProcessParsedPacket(const RtpCastHeader& rtp_header, frame_id_to_rtp_timestamp_[rtp_header.frame_id & 0xff] = rtp_header.rtp_timestamp; - cast_environment_->Logging()->InsertPacketEvent( - now, PACKET_RECEIVED, event_media_type_, rtp_header.rtp_timestamp, - rtp_header.frame_id, rtp_header.packet_id, rtp_header.max_packet_id, - payload_size); + + scoped_ptr<PacketEvent> receive_event(new PacketEvent()); + receive_event->timestamp = now; + receive_event->type = PACKET_RECEIVED; + receive_event->media_type = event_media_type_; + receive_event->rtp_timestamp = rtp_header.rtp_timestamp; + receive_event->frame_id = rtp_header.frame_id; + receive_event->packet_id = rtp_header.packet_id; + receive_event->max_packet_id = rtp_header.max_packet_id; + receive_event->size = payload_size; + cast_environment_->logger()->DispatchPacketEvent(receive_event.Pass()); bool duplicate = false; const bool complete = @@ -165,9 +172,14 @@ void FrameReceiver::CastFeedback(const RtcpCastMessage& cast_message) { base::TimeTicks now = cast_environment_->Clock()->NowTicks(); RtpTimestamp rtp_timestamp = frame_id_to_rtp_timestamp_[cast_message.ack_frame_id & 0xff]; - cast_environment_->Logging()->InsertFrameEvent( - now, FRAME_ACK_SENT, event_media_type_, - rtp_timestamp, cast_message.ack_frame_id); + + scoped_ptr<FrameEvent> ack_sent_event(new FrameEvent()); + ack_sent_event->timestamp = now; + ack_sent_event->type = FRAME_ACK_SENT; + ack_sent_event->media_type = event_media_type_; + ack_sent_event->rtp_timestamp = rtp_timestamp; + ack_sent_event->frame_id = cast_message.ack_frame_id; + cast_environment_->logger()->DispatchFrameEvent(ack_sent_event.Pass()); ReceiverRtcpEventSubscriber::RtcpEvents rtcp_events; event_subscriber_.GetRtcpEventsWithRedundancy(&rtcp_events); diff --git a/media/cast/receiver/frame_receiver_unittest.cc b/media/cast/receiver/frame_receiver_unittest.cc index a92b93a..79a6ef2 100644 --- a/media/cast/receiver/frame_receiver_unittest.cc +++ b/media/cast/receiver/frame_receiver_unittest.cc @@ -154,7 +154,7 @@ TEST_F(FrameReceiverTest, RejectsUnparsablePackets) { CreateFrameReceiverOfVideo(); SimpleEventSubscriber event_subscriber; - cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Subscribe(&event_subscriber); const bool success = receiver_->ProcessPacket( scoped_ptr<Packet>(new Packet(kPacketSize, 0xff)).Pass()); @@ -164,14 +164,14 @@ TEST_F(FrameReceiverTest, RejectsUnparsablePackets) { std::vector<FrameEvent> frame_events; event_subscriber.GetFrameEventsAndReset(&frame_events); EXPECT_TRUE(frame_events.empty()); - cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Unsubscribe(&event_subscriber); } TEST_F(FrameReceiverTest, ReceivesOneFrame) { CreateFrameReceiverOfAudio(); SimpleEventSubscriber event_subscriber; - cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Subscribe(&event_subscriber); EXPECT_CALL(mock_transport_, SendRtcpFromRtpReceiver(_, _, _, _, _, _, _)) .WillRepeatedly(testing::Return()); @@ -205,14 +205,14 @@ TEST_F(FrameReceiverTest, ReceivesOneFrame) { EXPECT_EQ(AUDIO_EVENT, frame_events.begin()->media_type); EXPECT_EQ(rtp_header_.frame_id, frame_events.begin()->frame_id); EXPECT_EQ(rtp_header_.rtp_timestamp, frame_events.begin()->rtp_timestamp); - cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Unsubscribe(&event_subscriber); } TEST_F(FrameReceiverTest, ReceivesFramesSkippingWhenAppropriate) { CreateFrameReceiverOfAudio(); SimpleEventSubscriber event_subscriber; - cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Subscribe(&event_subscriber); EXPECT_CALL(mock_transport_, SendRtcpFromRtpReceiver(_, _, _, _, _, _, _)) .WillRepeatedly(testing::Return()); @@ -308,14 +308,14 @@ TEST_F(FrameReceiverTest, ReceivesFramesSkippingWhenAppropriate) { EXPECT_EQ(frame_offset * rtp_advance_per_frame, frame_events[i].rtp_timestamp); } - cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Unsubscribe(&event_subscriber); } TEST_F(FrameReceiverTest, ReceivesFramesRefusingToSkipAny) { CreateFrameReceiverOfVideo(); SimpleEventSubscriber event_subscriber; - cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Subscribe(&event_subscriber); EXPECT_CALL(mock_transport_, SendRtcpFromRtpReceiver(_, _, _, _, _, _, _)) .WillRepeatedly(testing::Return()); @@ -414,7 +414,7 @@ TEST_F(FrameReceiverTest, ReceivesFramesRefusingToSkipAny) { EXPECT_EQ(frame_offset * rtp_advance_per_frame, frame_events[i].rtp_timestamp); } - cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Unsubscribe(&event_subscriber); } } // namespace cast diff --git a/media/cast/receiver/video_decoder.cc b/media/cast/receiver/video_decoder.cc index f9b24a420..534eac0 100644 --- a/media/cast/receiver/video_decoder.cc +++ b/media/cast/receiver/video_decoder.cc @@ -61,6 +61,15 @@ class VideoDecoder::ImplBase const scoped_refptr<VideoFrame> decoded_frame = Decode( encoded_frame->mutable_bytes(), static_cast<int>(encoded_frame->data.size())); + + scoped_ptr<FrameEvent> decode_event(new FrameEvent()); + decode_event->timestamp = cast_environment_->Clock()->NowTicks(); + decode_event->type = FRAME_DECODED; + decode_event->media_type = VIDEO_EVENT; + decode_event->rtp_timestamp = encoded_frame->rtp_timestamp; + decode_event->frame_id = encoded_frame->frame_id; + cast_environment_->logger()->DispatchFrameEvent(decode_event.Pass()); + cast_environment_->PostTask( CastEnvironment::MAIN, FROM_HERE, diff --git a/media/cast/sender/audio_encoder.cc b/media/cast/sender/audio_encoder.cc index f521b51..80d69fe9 100644 --- a/media/cast/sender/audio_encoder.cc +++ b/media/cast/sender/audio_encoder.cc @@ -156,6 +156,9 @@ class AudioEncoder::ImplBase TRACE_EVENT_ASYNC_END1("cast.stream", "Audio Encode", audio_frame.get(), "Deadline utilization", audio_frame->deadline_utilization); + + audio_frame->encode_completion_time = + cast_environment_->Clock()->NowTicks(); cast_environment_->PostTask( CastEnvironment::MAIN, FROM_HERE, diff --git a/media/cast/sender/audio_encoder.h b/media/cast/sender/audio_encoder.h index 61ac08b..aac20d7 100644 --- a/media/cast/sender/audio_encoder.h +++ b/media/cast/sender/audio_encoder.h @@ -9,6 +9,7 @@ #include "base/memory/scoped_ptr.h" #include "base/threading/thread_checker.h" #include "media/base/audio_bus.h" +#include "media/cast/cast_defines.h" #include "media/cast/cast_environment.h" #include "media/cast/sender/sender_encoded_frame.h" diff --git a/media/cast/sender/external_video_encoder.cc b/media/cast/sender/external_video_encoder.cc index ca389a5c..196b16e 100644 --- a/media/cast/sender/external_video_encoder.cc +++ b/media/cast/sender/external_video_encoder.cc @@ -30,16 +30,6 @@ namespace { enum { MAX_H264_QUANTIZER = 51 }; static const size_t kOutputBufferCount = 3; -void LogFrameEncodedEvent( - const scoped_refptr<media::cast::CastEnvironment>& cast_environment, - base::TimeTicks event_time, - media::cast::RtpTimestamp rtp_timestamp, - uint32 frame_id) { - cast_environment->Logging()->InsertFrameEvent( - event_time, media::cast::FRAME_ENCODED, media::cast::VIDEO_EVENT, - rtp_timestamp, frame_id); -} - } // namespace namespace media { @@ -331,15 +321,8 @@ class ExternalVideoEncoder::VEAClientImpl base::debug::ClearCrashKey(kZeroEncodeDetails); } - cast_environment_->PostTask( - CastEnvironment::MAIN, - FROM_HERE, - base::Bind(&LogFrameEncodedEvent, - cast_environment_, - cast_environment_->Clock()->NowTicks(), - encoded_frame->rtp_timestamp, - encoded_frame->frame_id)); - + encoded_frame->encode_completion_time = + cast_environment_->Clock()->NowTicks(); cast_environment_->PostTask( CastEnvironment::MAIN, FROM_HERE, diff --git a/media/cast/sender/frame_sender.cc b/media/cast/sender/frame_sender.cc index ec37a6d..772cf01 100644 --- a/media/cast/sender/frame_sender.cc +++ b/media/cast/sender/frame_sender.cc @@ -215,15 +215,19 @@ void FrameSender::SendEncodedFrame( VLOG_IF(1, !is_audio_ && encoded_frame->dependency == EncodedFrame::KEY) << SENDER_SSRC << "Sending encoded key frame, id=" << frame_id; - cast_environment_->Logging()->InsertEncodedFrameEvent( - last_send_time_, FRAME_ENCODED, - is_audio_ ? AUDIO_EVENT : VIDEO_EVENT, - encoded_frame->rtp_timestamp, - frame_id, static_cast<int>(encoded_frame->data.size()), - encoded_frame->dependency == EncodedFrame::KEY, - requested_bitrate_before_encode, - encoded_frame->deadline_utilization, - encoded_frame->lossy_utilization); + scoped_ptr<FrameEvent> encode_event(new FrameEvent()); + encode_event->timestamp = encoded_frame->encode_completion_time; + encode_event->type = FRAME_ENCODED; + encode_event->media_type = is_audio_ ? AUDIO_EVENT : VIDEO_EVENT; + encode_event->rtp_timestamp = encoded_frame->rtp_timestamp; + encode_event->frame_id = frame_id; + encode_event->size = encoded_frame->data.size(); + encode_event->key_frame = encoded_frame->dependency == EncodedFrame::KEY; + encode_event->target_bitrate = requested_bitrate_before_encode; + encode_event->encoder_cpu_utilization = encoded_frame->deadline_utilization; + encode_event->idealized_bitrate_utilization = + encoded_frame->lossy_utilization; + cast_environment_->logger()->DispatchFrameEvent(encode_event.Pass()); RecordLatestFrameTimestamps(frame_id, encoded_frame->reference_time, @@ -321,12 +325,14 @@ void FrameSender::OnReceivedCastFeedback(const RtcpCastMessage& cast_feedback) { base::TimeTicks now = cast_environment_->Clock()->NowTicks(); congestion_control_->AckFrame(cast_feedback.ack_frame_id, now); - cast_environment_->Logging()->InsertFrameEvent( - now, - FRAME_ACK_RECEIVED, - is_audio_ ? AUDIO_EVENT : VIDEO_EVENT, - GetRecordedRtpTimestamp(cast_feedback.ack_frame_id), - cast_feedback.ack_frame_id); + scoped_ptr<FrameEvent> ack_event(new FrameEvent()); + ack_event->timestamp = now; + ack_event->type = FRAME_ACK_RECEIVED; + ack_event->media_type = is_audio_ ? AUDIO_EVENT : VIDEO_EVENT; + ack_event->rtp_timestamp = + GetRecordedRtpTimestamp(cast_feedback.ack_frame_id); + ack_event->frame_id = cast_feedback.ack_frame_id; + cast_environment_->logger()->DispatchFrameEvent(ack_event.Pass()); const bool is_acked_out_of_order = static_cast<int32>(cast_feedback.ack_frame_id - diff --git a/media/cast/sender/h264_vt_encoder.cc b/media/cast/sender/h264_vt_encoder.cc index 53aaf65..d02b738 100644 --- a/media/cast/sender/h264_vt_encoder.cc +++ b/media/cast/sender/h264_vt_encoder.cc @@ -756,6 +756,8 @@ void H264VideoToolboxEncoder::CompressionCallback(void* encoder_opaque, // TODO(miu): Compute and populate the |deadline_utilization| and // |lossy_utilization| performance metrics in |encoded_frame|. + encoded_frame->encode_completion_time = + encoder->cast_environment_->Clock()->NowTicks(); encoder->cast_environment_->PostTask( CastEnvironment::MAIN, FROM_HERE, base::Bind(request->frame_encoded_callback, diff --git a/media/cast/sender/sender_encoded_frame.h b/media/cast/sender/sender_encoded_frame.h index 8a3b2fa..fa7787d 100644 --- a/media/cast/sender/sender_encoded_frame.h +++ b/media/cast/sender/sender_encoded_frame.h @@ -5,6 +5,7 @@ #ifndef MEDIA_CAST_SENDER_SENDER_ENCODED_FRAME_H_ #define MEDIA_CAST_SENDER_SENDER_ENCODED_FRAME_H_ +#include "base/time/time.h" #include "media/cast/net/cast_transport_config.h" namespace media { @@ -42,6 +43,9 @@ struct SenderEncodedFrame : public EncodedFrame { // // TODO(miu): Rename to idealized_bitrate_utilization. double lossy_utilization; + + // The time at which the encode of the frame completed. + base::TimeTicks encode_completion_time; }; } // namespace cast diff --git a/media/cast/sender/video_encoder_impl.cc b/media/cast/sender/video_encoder_impl.cc index d6b8e45..fcfac17 100644 --- a/media/cast/sender/video_encoder_impl.cc +++ b/media/cast/sender/video_encoder_impl.cc @@ -45,6 +45,7 @@ void EncodeVideoFrameOnEncoderThread( scoped_ptr<SenderEncodedFrame> encoded_frame(new SenderEncodedFrame()); encoder->Encode(video_frame, reference_time, encoded_frame.get()); + encoded_frame->encode_completion_time = environment->Clock()->NowTicks(); environment->PostTask( CastEnvironment::MAIN, FROM_HERE, diff --git a/media/cast/sender/video_sender.cc b/media/cast/sender/video_sender.cc index a96f2fd..f8890bb 100644 --- a/media/cast/sender/video_sender.cc +++ b/media/cast/sender/video_sender.cc @@ -41,26 +41,35 @@ const int kTargetUtilizationPercentage = 75; // Extract capture begin/end timestamps from |video_frame|'s metadata and log // it. -void LogVideoCaptureTimestamps(const CastEnvironment& cast_environment, +void LogVideoCaptureTimestamps(CastEnvironment* cast_environment, const media::VideoFrame& video_frame, RtpTimestamp rtp_timestamp) { - base::TimeTicks capture_begin_time; - base::TimeTicks capture_end_time; + scoped_ptr<FrameEvent> capture_begin_event(new FrameEvent()); + capture_begin_event->type = FRAME_CAPTURE_BEGIN; + capture_begin_event->media_type = VIDEO_EVENT; + capture_begin_event->rtp_timestamp = rtp_timestamp; + + scoped_ptr<FrameEvent> capture_end_event(new FrameEvent()); + capture_end_event->type = FRAME_CAPTURE_END; + capture_end_event->media_type = VIDEO_EVENT; + capture_end_event->rtp_timestamp = rtp_timestamp; + capture_end_event->width = video_frame.visible_rect().width(); + capture_end_event->height = video_frame.visible_rect().height(); + if (!video_frame.metadata()->GetTimeTicks( - media::VideoFrameMetadata::CAPTURE_BEGIN_TIME, &capture_begin_time) || + media::VideoFrameMetadata::CAPTURE_BEGIN_TIME, + &capture_begin_event->timestamp) || !video_frame.metadata()->GetTimeTicks( - media::VideoFrameMetadata::CAPTURE_END_TIME, &capture_end_time)) { + media::VideoFrameMetadata::CAPTURE_END_TIME, + &capture_end_event->timestamp)) { // The frame capture timestamps were not provided by the video capture // source. Simply log the events as happening right now. - capture_begin_time = capture_end_time = - cast_environment.Clock()->NowTicks(); + capture_begin_event->timestamp = capture_end_event->timestamp = + cast_environment->Clock()->NowTicks(); } - cast_environment.Logging()->InsertFrameEvent( - capture_begin_time, FRAME_CAPTURE_BEGIN, VIDEO_EVENT, rtp_timestamp, - kFrameIdUnknown); - cast_environment.Logging()->InsertCapturedVideoFrameEvent( - capture_end_time, rtp_timestamp, video_frame.visible_rect().width(), - video_frame.visible_rect().height()); + + cast_environment->logger()->DispatchFrameEvent(capture_begin_event.Pass()); + cast_environment->logger()->DispatchFrameEvent(capture_end_event.Pass()); } } // namespace @@ -142,7 +151,8 @@ void VideoSender::InsertRawVideoFrame( const RtpTimestamp rtp_timestamp = TimeDeltaToRtpDelta(video_frame->timestamp(), kVideoFrequency); - LogVideoCaptureTimestamps(*cast_environment_, *video_frame, rtp_timestamp); + LogVideoCaptureTimestamps(cast_environment_.get(), *video_frame, + rtp_timestamp); // Used by chrome/browser/extension/api/cast_streaming/performance_test.cc TRACE_EVENT_INSTANT2( diff --git a/media/cast/sender/video_sender_unittest.cc b/media/cast/sender/video_sender_unittest.cc index 4e4996b..4b4c930 100644 --- a/media/cast/sender/video_sender_unittest.cc +++ b/media/cast/sender/video_sender_unittest.cc @@ -386,7 +386,7 @@ TEST_F(VideoSenderTest, LogAckReceivedEvent) { ASSERT_EQ(STATUS_INITIALIZED, operational_status_); SimpleEventSubscriber event_subscriber; - cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Subscribe(&event_subscriber); int num_frames = 10; for (int i = 0; i < num_frames; i++) { @@ -412,7 +412,7 @@ TEST_F(VideoSenderTest, LogAckReceivedEvent) { EXPECT_EQ(VIDEO_EVENT, frame_events.rbegin()->media_type); EXPECT_EQ(num_frames - 1u, frame_events.rbegin()->frame_id); - cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); + cast_environment_->logger()->Unsubscribe(&event_subscriber); } TEST_F(VideoSenderTest, StopSendingInTheAbsenceOfAck) { diff --git a/media/cast/test/cast_benchmarks.cc b/media/cast/test/cast_benchmarks.cc index bea587e..19d5edf 100644 --- a/media/cast/test/cast_benchmarks.cc +++ b/media/cast/test/cast_benchmarks.cc @@ -84,9 +84,8 @@ void ExpectAudioSuccess(OperationalStatus status) { EXPECT_EQ(STATUS_INITIALIZED, status); } -void IgnoreRawEvents(const std::vector<PacketEvent>& packet_events, - const std::vector<FrameEvent>& frame_events) { -} +void IgnoreRawEvents(scoped_ptr<std::vector<FrameEvent>> frame_events, + scoped_ptr<std::vector<PacketEvent>> packet_events) {} } // namespace diff --git a/media/cast/test/end2end_unittest.cc b/media/cast/test/end2end_unittest.cc index e8137c0..b7880c4 100644 --- a/media/cast/test/end2end_unittest.cc +++ b/media/cast/test/end2end_unittest.cc @@ -448,8 +448,7 @@ class End2EndTest : public ::testing::Test { test_receiver_video_callback_(new TestReceiverVideoCallback()) { testing_clock_.Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); - cast_environment_sender_->Logging()->AddRawEventSubscriber( - &event_subscriber_sender_); + cast_environment_sender_->logger()->Subscribe(&event_subscriber_sender_); } void Configure(Codec video_codec, @@ -575,28 +574,21 @@ class End2EndTest : public ::testing::Test { void Create() { net::IPEndPoint dummy_endpoint; transport_sender_.reset(new CastTransportSenderImpl( - NULL, - testing_clock_sender_, - dummy_endpoint, - dummy_endpoint, + nullptr, testing_clock_sender_, dummy_endpoint, dummy_endpoint, make_scoped_ptr(new base::DictionaryValue), base::Bind(&UpdateCastTransportStatus), - base::Bind(&End2EndTest::LogRawEvents, base::Unretained(this)), - base::TimeDelta::FromMilliseconds(1), - task_runner_sender_, - PacketReceiverCallback(), - &sender_to_receiver_)); + base::Bind(&LogEventDispatcher::DispatchBatchOfEvents, + base::Unretained(cast_environment_sender_->logger())), + base::TimeDelta::FromMilliseconds(1), task_runner_sender_, + PacketReceiverCallback(), &sender_to_receiver_)); transport_receiver_.reset(new CastTransportSenderImpl( - NULL, - testing_clock_sender_, - dummy_endpoint, - dummy_endpoint, + nullptr, testing_clock_sender_, dummy_endpoint, dummy_endpoint, make_scoped_ptr(new base::DictionaryValue), base::Bind(&UpdateCastTransportStatus), - base::Bind(&End2EndTest::LogRawEvents, base::Unretained(this)), - base::TimeDelta::FromMilliseconds(1), - task_runner_sender_, + base::Bind(&LogEventDispatcher::DispatchBatchOfEvents, + base::Unretained(cast_environment_receiver_->logger())), + base::TimeDelta::FromMilliseconds(1), task_runner_sender_, base::Bind(&End2EndTest::ReceivePacket, base::Unretained(this)), &receiver_to_sender_)); @@ -639,8 +631,7 @@ class End2EndTest : public ::testing::Test { } ~End2EndTest() override { - cast_environment_sender_->Logging()->RemoveRawEventSubscriber( - &event_subscriber_sender_); + cast_environment_sender_->logger()->Unsubscribe(&event_subscriber_sender_); } void TearDown() final { @@ -742,33 +733,6 @@ class End2EndTest : public ::testing::Test { base::Unretained(this))); } - void LogRawEvents(const std::vector<PacketEvent>& packet_events, - const std::vector<FrameEvent>& frame_events) { - for (std::vector<media::cast::PacketEvent>::const_iterator it = - packet_events.begin(); - it != packet_events.end(); - ++it) { - cast_environment_sender_->Logging()->InsertPacketEvent(it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id, - it->packet_id, - it->max_packet_id, - it->size); - } - for (std::vector<media::cast::FrameEvent>::const_iterator it = - frame_events.begin(); - it != frame_events.end(); - ++it) { - cast_environment_sender_->Logging()->InsertFrameEvent(it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id); - } - } - FrameReceiverConfig audio_receiver_config_; FrameReceiverConfig video_receiver_config_; AudioSenderConfig audio_sender_config_; @@ -1251,6 +1215,8 @@ TEST_F(End2EndTest, AudioLogging) { EXPECT_EQ(num_audio_frames_requested, test_receiver_audio_callback_->number_times_called()); + RunTasks(750); // Make sure that we send a RTCP message with the log. + // Logging tests. // Verify that all frames and all required events were logged. event_subscriber_sender_.GetFrameEventsAndReset(&frame_events_); diff --git a/media/cast/test/sender.cc b/media/cast/test/sender.cc index 514bc74..5791ffe 100644 --- a/media/cast/test/sender.cc +++ b/media/cast/test/sender.cc @@ -70,37 +70,6 @@ void UpdateCastTransportStatus( VLOG(1) << "Transport status: " << status; } -void LogRawEvents( - const scoped_refptr<media::cast::CastEnvironment>& cast_environment, - const std::vector<media::cast::PacketEvent>& packet_events, - const std::vector<media::cast::FrameEvent>& frame_events) { - VLOG(1) << "Got packet events from transport, size: " << packet_events.size(); - for (std::vector<media::cast::PacketEvent>::const_iterator it = - packet_events.begin(); - it != packet_events.end(); - ++it) { - cast_environment->Logging()->InsertPacketEvent(it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id, - it->packet_id, - it->max_packet_id, - it->size); - } - VLOG(1) << "Got frame events from transport, size: " << frame_events.size(); - for (std::vector<media::cast::FrameEvent>::const_iterator it = - frame_events.begin(); - it != frame_events.end(); - ++it) { - cast_environment->Logging()->InsertFrameEvent(it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id); - } -} - void QuitLoopOnInitializationResult(media::cast::OperationalStatus result) { CHECK(result == media::cast::STATUS_INITIALIZED) << "Cast sender uninitialized"; @@ -146,10 +115,8 @@ void WriteLogsToFileAndDestroySubscribers( scoped_ptr<media::cast::EncodingEventSubscriber> audio_event_subscriber, base::ScopedFILE video_log_file, base::ScopedFILE audio_log_file) { - cast_environment->Logging()->RemoveRawEventSubscriber( - video_event_subscriber.get()); - cast_environment->Logging()->RemoveRawEventSubscriber( - audio_event_subscriber.get()); + cast_environment->logger()->Unsubscribe(video_event_subscriber.get()); + cast_environment->logger()->Unsubscribe(audio_event_subscriber.get()); VLOG(0) << "Dumping logging data for video stream."; media::cast::proto::LogMetadata log_metadata; @@ -175,22 +142,20 @@ void WriteLogsToFileAndDestroySubscribers( 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::StatsEventSubscriber> video_stats_subscriber, + scoped_ptr<media::cast::StatsEventSubscriber> audio_stats_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()); + cast_environment->logger()->Unsubscribe(video_stats_subscriber.get()); + cast_environment->logger()->Unsubscribe(audio_stats_subscriber.get()); + cast_environment->logger()->Unsubscribe(estimator.get()); - scoped_ptr<base::DictionaryValue> stats = video_event_subscriber->GetStats(); + scoped_ptr<base::DictionaryValue> stats = video_stats_subscriber->GetStats(); std::string json; base::JSONWriter::WriteWithOptions( *stats, base::JSONWriter::OPTIONS_PRETTY_PRINT, &json); VLOG(0) << "Video stats: " << json; - stats = audio_event_subscriber->GetStats(); + stats = audio_stats_subscriber->GetStats(); json.clear(); base::JSONWriter::WriteWithOptions( *stats, base::JSONWriter::OPTIONS_PRETTY_PRINT, &json); @@ -272,16 +237,14 @@ int main(int argc, char** argv) { // CastTransportSender initialization. scoped_ptr<media::cast::CastTransportSender> transport_sender = media::cast::CastTransportSender::Create( - NULL, // net log. - cast_environment->Clock(), - net::IPEndPoint(), - remote_endpoint, + nullptr, // net log. + cast_environment->Clock(), net::IPEndPoint(), remote_endpoint, make_scoped_ptr(new base::DictionaryValue), // options base::Bind(&UpdateCastTransportStatus), - base::Bind(&LogRawEvents, cast_environment), + base::Bind(&media::cast::LogEventDispatcher::DispatchBatchOfEvents, + base::Unretained(cast_environment->logger())), base::TimeDelta::FromSeconds(1), - media::cast::PacketReceiverCallback(), - io_message_loop.task_runner()); + media::cast::PacketReceiverCallback(), io_message_loop.task_runner()); // Set up event subscribers. scoped_ptr<media::cast::EncodingEventSubscriber> video_event_subscriber; @@ -294,15 +257,13 @@ int main(int argc, char** argv) { media::cast::VIDEO_EVENT, 10000)); audio_event_subscriber.reset(new media::cast::EncodingEventSubscriber( media::cast::AUDIO_EVENT, 10000)); - cast_environment->Logging()->AddRawEventSubscriber( - video_event_subscriber.get()); - cast_environment->Logging()->AddRawEventSubscriber( - audio_event_subscriber.get()); + cast_environment->logger()->Subscribe(video_event_subscriber.get()); + cast_environment->logger()->Subscribe(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()); + cast_environment->logger()->Subscribe(offset_estimator.get()); scoped_ptr<media::cast::StatsEventSubscriber> video_stats_subscriber( new media::cast::StatsEventSubscriber(media::cast::VIDEO_EVENT, cast_environment->Clock(), @@ -311,10 +272,8 @@ int main(int argc, char** argv) { 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()); + cast_environment->logger()->Subscribe(video_stats_subscriber.get()); + cast_environment->logger()->Subscribe(audio_stats_subscriber.get()); base::ScopedFILE video_log_file(fopen(video_log_file_name.c_str(), "w")); if (!video_log_file) { diff --git a/media/cast/test/simulator.cc b/media/cast/test/simulator.cc index 540f377..f63a797 100644 --- a/media/cast/test/simulator.cc +++ b/media/cast/test/simulator.cc @@ -121,45 +121,6 @@ void LogVideoOperationalStatus(OperationalStatus status) { LOG(INFO) << "Video status: " << status; } -void LogTransportEvents(const scoped_refptr<CastEnvironment>& env, - const std::vector<PacketEvent>& packet_events, - const std::vector<FrameEvent>& frame_events) { - for (std::vector<media::cast::PacketEvent>::const_iterator it = - packet_events.begin(); - it != packet_events.end(); - ++it) { - env->Logging()->InsertPacketEvent(it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id, - it->packet_id, - it->max_packet_id, - it->size); - } - for (std::vector<media::cast::FrameEvent>::const_iterator it = - frame_events.begin(); - it != frame_events.end(); - ++it) { - if (it->type == FRAME_PLAYOUT) { - env->Logging()->InsertFrameEventWithDelay( - it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id, - it->delay_delta); - } else { - env->Logging()->InsertFrameEvent( - it->timestamp, - it->type, - it->media_type, - it->rtp_timestamp, - it->frame_id); - } - } -} - // Maintains a queue of encoded video frames. // This works by tracking FRAME_CAPTURE_END and FRAME_ENCODED events. // If a video frame is detected to be encoded it transfers a frame @@ -356,8 +317,8 @@ void RunSimulation(const base::FilePath& source_path, 100 * 60 * 60); EncodingEventSubscriber video_event_subscriber(VIDEO_EVENT, 30 * 60 * 60); - sender_env->Logging()->AddRawEventSubscriber(&audio_event_subscriber); - sender_env->Logging()->AddRawEventSubscriber(&video_event_subscriber); + sender_env->logger()->Subscribe(&audio_event_subscriber); + sender_env->logger()->Subscribe(&video_event_subscriber); // Audio sender config. AudioSenderConfig audio_sender_config = GetDefaultAudioSenderConfig(); @@ -405,15 +366,12 @@ void RunSimulation(const base::FilePath& source_path, // Cast receiver. scoped_ptr<CastTransportSender> transport_receiver( new CastTransportSenderImpl( - NULL, - &testing_clock, - net::IPEndPoint(), - net::IPEndPoint(), + nullptr, &testing_clock, net::IPEndPoint(), net::IPEndPoint(), make_scoped_ptr(new base::DictionaryValue), base::Bind(&UpdateCastTransportStatus), - base::Bind(&LogTransportEvents, receiver_env), - base::TimeDelta::FromSeconds(1), - task_runner, + base::Bind(&LogEventDispatcher::DispatchBatchOfEvents, + base::Unretained(receiver_env->logger())), + base::TimeDelta::FromSeconds(1), task_runner, base::Bind(&PacketProxy::ReceivePacket, base::Unretained(&packet_proxy)), &receiver_to_sender)); @@ -426,19 +384,14 @@ void RunSimulation(const base::FilePath& source_path, packet_proxy.receiver = cast_receiver.get(); // Cast sender and transport sender. - scoped_ptr<CastTransportSender> transport_sender( - new CastTransportSenderImpl( - NULL, - &testing_clock, - net::IPEndPoint(), - net::IPEndPoint(), - make_scoped_ptr(new base::DictionaryValue), - base::Bind(&UpdateCastTransportStatus), - base::Bind(&LogTransportEvents, sender_env), - base::TimeDelta::FromSeconds(1), - task_runner, - PacketReceiverCallback(), - &sender_to_receiver)); + scoped_ptr<CastTransportSender> transport_sender(new CastTransportSenderImpl( + nullptr, &testing_clock, net::IPEndPoint(), net::IPEndPoint(), + make_scoped_ptr(new base::DictionaryValue), + base::Bind(&UpdateCastTransportStatus), + base::Bind(&LogEventDispatcher::DispatchBatchOfEvents, + base::Unretained(sender_env->logger())), + base::TimeDelta::FromSeconds(1), task_runner, PacketReceiverCallback(), + &sender_to_receiver)); scoped_ptr<CastSender> cast_sender( CastSender::Create(sender_env, transport_sender.get())); @@ -486,7 +439,7 @@ void RunSimulation(const base::FilePath& source_path, scoped_ptr<EncodedVideoFrameTracker> video_frame_tracker; if (quality_test) { video_frame_tracker.reset(new EncodedVideoFrameTracker(&media_source)); - sender_env->Logging()->AddRawEventSubscriber(video_frame_tracker.get()); + sender_env->logger()->Subscribe(video_frame_tracker.get()); } // Quality metrics computed for each frame decoded. @@ -544,6 +497,12 @@ void RunSimulation(const base::FilePath& source_path, elapsed_time += step; } + // Unsubscribe from logging events. + sender_env->logger()->Unsubscribe(&audio_event_subscriber); + sender_env->logger()->Unsubscribe(&video_event_subscriber); + if (quality_test) + sender_env->logger()->Unsubscribe(video_frame_tracker.get()); + // Get event logs for audio and video. media::cast::proto::LogMetadata audio_metadata, video_metadata; media::cast::FrameEventList audio_frame_events, video_frame_events; |