diff options
51 files changed, 1965 insertions, 1428 deletions
diff --git a/chrome/browser/media/cast_transport_host_filter.cc b/chrome/browser/media/cast_transport_host_filter.cc index 3f140734..cb3e42d 100644 --- a/chrome/browser/media/cast_transport_host_filter.cc +++ b/chrome/browser/media/cast_transport_host_filter.cc @@ -63,11 +63,12 @@ void CastTransportHostFilter::NotifyStatusChange( void CastTransportHostFilter::SendRawEvents( int32 channel_id, - 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)); + 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)); } 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 094d7e7..b30e08b 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, - scoped_ptr<std::vector<media::cast::FrameEvent>> frame_events, - scoped_ptr<std::vector<media::cast::PacketEvent>> packet_events); + const std::vector<media::cast::PacketEvent>& packet_events, + const std::vector<media::cast::FrameEvent>& frame_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 06ea93d..e7930fa 100644 --- a/chrome/renderer/media/cast_receiver_session_delegate.cc +++ b/chrome/renderer/media/cast_receiver_session_delegate.cc @@ -13,6 +13,12 @@ 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 7f6b963..98de8fd 100644 --- a/chrome/renderer/media/cast_receiver_session_delegate.h +++ b/chrome/renderer/media/cast_receiver_session_delegate.h @@ -19,6 +19,9 @@ 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 f39154d..5cca597 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(&media::cast::LogEventDispatcher::DispatchBatchOfEvents, - base::Unretained(cast_environment_->logger())))); + base::Bind(&CastSessionDelegateBase::LogRawEvents, + base::Unretained(this)))); } void CastSessionDelegateBase::StatusNotificationCB( @@ -313,3 +313,44 @@ 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 cd4e63a2f..378c50e 100644 --- a/chrome/renderer/media/cast_session_delegate.h +++ b/chrome/renderer/media/cast_session_delegate.h @@ -62,6 +62,9 @@ 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_; @@ -133,6 +136,10 @@ 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 afa858a..e814dc2 100644 --- a/chrome/renderer/media/cast_transport_sender_ipc.cc +++ b/chrome/renderer/media/cast_transport_sender_ipc.cc @@ -142,19 +142,7 @@ void CastTransportSenderIPC::OnNotifyStatusChange( void CastTransportSenderIPC::OnRawEvents( const std::vector<media::cast::PacketEvent>& packet_events, const std::vector<media::cast::FrameEvent>& 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()); + raw_events_callback_.Run(packet_events, frame_events); } void CastTransportSenderIPC::OnRtt(uint32 ssrc, base::TimeDelta rtt) { diff --git a/media/cast/BUILD.gn b/media/cast/BUILD.gn index c9c8fc5..6b87e13 100644 --- a/media/cast/BUILD.gn +++ b/media/cast/BUILD.gn @@ -27,12 +27,14 @@ 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", @@ -280,6 +282,8 @@ 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 1ef6cda..3e8310d 100644 --- a/media/cast/cast.gyp +++ b/media/cast/cast.gyp @@ -43,12 +43,14 @@ '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 e3def4f..f22f0a4 100644 --- a/media/cast/cast_environment.cc +++ b/media/cast/cast_environment.cc @@ -10,6 +10,14 @@ using base::SingleThreadTaskRunner; +namespace { + +void DeleteLoggingOnMainThread(scoped_ptr<media::cast::LoggingImpl> logging) { + logging.reset(); +} + +} // namespace + namespace media { namespace cast { @@ -22,9 +30,17 @@ CastEnvironment::CastEnvironment( audio_thread_proxy_(audio_thread_proxy), video_thread_proxy_(video_thread_proxy), clock_(clock.Pass()), - logger_(this) {} + logging_(new LoggingImpl) {} -CastEnvironment::~CastEnvironment() {} +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_))); + } +} 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 9b29d4a..83b5ce3 100644 --- a/media/cast/cast_environment.h +++ b/media/cast/cast_environment.h @@ -11,7 +11,8 @@ #include "base/single_thread_task_runner.h" #include "base/time/tick_clock.h" #include "base/time/time.h" -#include "media/cast/logging/log_event_dispatcher.h" +#include "media/cast/logging/logging_defines.h" +#include "media/cast/logging/logging_impl.h" namespace media { namespace cast { @@ -55,8 +56,10 @@ class CastEnvironment : public base::RefCountedThreadSafe<CastEnvironment> { // All of the media::cast implementation must use this TickClock. base::TickClock* Clock() const { return clock_.get(); } - // Thread-safe log event dispatcher. - LogEventDispatcher* logger() { return &logger_; } + // 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(); } scoped_refptr<base::SingleThreadTaskRunner> GetTaskRunner( ThreadId identifier) const; @@ -73,7 +76,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_; - LogEventDispatcher logger_; + scoped_ptr<LoggingImpl> logging_; private: friend class base::RefCountedThreadSafe<CastEnvironment>; diff --git a/media/cast/cast_testing.gypi b/media/cast/cast_testing.gypi index 461bedd..116727e 100644 --- a/media/cast/cast_testing.gypi +++ b/media/cast/cast_testing.gypi @@ -76,6 +76,8 @@ '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 123a8fe..b052bbb 100644 --- a/media/cast/logging/encoding_event_subscriber_unittest.cc +++ b/media/cast/logging/encoding_event_subscriber_unittest.cc @@ -43,12 +43,15 @@ 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_->logger()->Subscribe(event_subscriber_.get()); + cast_environment_->Logging()->AddRawEventSubscriber( + event_subscriber_.get()); } ~EncodingEventSubscriberTest() override { - if (event_subscriber_) - cast_environment_->logger()->Unsubscribe(event_subscriber_.get()); + if (event_subscriber_) { + cast_environment_->Logging()->RemoveRawEventSubscriber( + event_subscriber_.get()); + } } void GetEventsAndReset() { @@ -76,30 +79,20 @@ TEST_F(EncodingEventSubscriberTest, FrameEventTruncating) { int width = 320; int height = 180; for (int i = 0; i < 11; i++) { - 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()); - + 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); width += 160; height += 90; } @@ -126,16 +119,14 @@ TEST_F(EncodingEventSubscriberTest, PacketEventTruncating) { // Entry with RTP timestamp 0 should get dropped. for (int i = 0; i < 11; i++) { - 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()); + 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); } GetEventsAndReset(); @@ -150,22 +141,18 @@ TEST_F(EncodingEventSubscriberTest, EventFiltering) { base::TimeTicks now(testing_clock_->NowTicks()); RtpTimestamp rtp_timestamp = 100; - 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()); + cast_environment_->Logging()->InsertFrameEvent(now, + FRAME_DECODED, + VIDEO_EVENT, + rtp_timestamp, + /*frame_id*/ 0); // This is an AUDIO_EVENT and shouldn't be processed by the subscriber. - 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()); + cast_environment_->Logging()->InsertFrameEvent(now, + FRAME_DECODED, + AUDIO_EVENT, + rtp_timestamp, + /*frame_id*/ 0); GetEventsAndReset(); @@ -187,13 +174,10 @@ TEST_F(EncodingEventSubscriberTest, FrameEvent) { Init(VIDEO_EVENT); base::TimeTicks now(testing_clock_->NowTicks()); RtpTimestamp rtp_timestamp = 100; - 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()); + cast_environment_->Logging()->InsertFrameEvent(now, FRAME_DECODED, + VIDEO_EVENT, + rtp_timestamp, + /*frame_id*/ 0); GetEventsAndReset(); @@ -223,14 +207,9 @@ TEST_F(EncodingEventSubscriberTest, FrameEventDelay) { base::TimeTicks now(testing_clock_->NowTicks()); RtpTimestamp rtp_timestamp = 100; int delay_ms = 100; - 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()); + cast_environment_->Logging()->InsertFrameEventWithDelay( + now, FRAME_PLAYOUT, AUDIO_EVENT, rtp_timestamp, + /*frame_id*/ 0, base::TimeDelta::FromMilliseconds(delay_ms)); GetEventsAndReset(); @@ -262,18 +241,10 @@ TEST_F(EncodingEventSubscriberTest, FrameEventSize) { int target_bitrate = 1024; double encoder_cpu_utilization = 0.90; double idealized_bitrate_utilization = 0.42; - 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()); + 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); GetEventsAndReset(); @@ -305,37 +276,22 @@ TEST_F(EncodingEventSubscriberTest, MultipleFrameEvents) { RtpTimestamp rtp_timestamp1 = 100; RtpTimestamp rtp_timestamp2 = 200; base::TimeTicks now1(testing_clock_->NowTicks()); - 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)); + 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)); base::TimeTicks now2(testing_clock_->NowTicks()); - 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)); + 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)); base::TimeTicks now3(testing_clock_->NowTicks()); - 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()); + cast_environment_->Logging()->InsertFrameEvent( + now3, FRAME_DECODED, AUDIO_EVENT, rtp_timestamp1, /*frame_id*/ 0); GetEventsAndReset(); @@ -382,16 +338,10 @@ TEST_F(EncodingEventSubscriberTest, PacketEvent) { RtpTimestamp rtp_timestamp = 100; int packet_id = 2; int size = 100; - 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()); + cast_environment_->Logging()->InsertPacketEvent( + now, PACKET_RECEIVED, AUDIO_EVENT, + rtp_timestamp, /*frame_id*/ 0, packet_id, + /*max_packet_id*/ 10, size); GetEventsAndReset(); @@ -424,29 +374,25 @@ TEST_F(EncodingEventSubscriberTest, MultiplePacketEventsForPacket) { RtpTimestamp rtp_timestamp = 100; int packet_id = 2; int size = 100; - 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)); + 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)); base::TimeTicks now2(testing_clock_->NowTicks()); - 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()); + cast_environment_->Logging()->InsertPacketEvent(now2, + PACKET_RETRANSMITTED, + VIDEO_EVENT, + rtp_timestamp, + /*frame_id*/ 0, + packet_id, + /*max_packet_id*/ 10, + size); GetEventsAndReset(); @@ -479,29 +425,25 @@ TEST_F(EncodingEventSubscriberTest, MultiplePacketEventsForFrame) { int packet_id_1 = 2; int packet_id_2 = 3; int size = 100; - 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)); + 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)); base::TimeTicks now2(testing_clock_->NowTicks()); - 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()); + cast_environment_->Logging()->InsertPacketEvent(now2, + PACKET_RETRANSMITTED, + VIDEO_EVENT, + rtp_timestamp, + /*frame_id*/ 0, + packet_id_2, + /*max_packet_id*/ 10, + size); GetEventsAndReset(); @@ -540,29 +482,25 @@ TEST_F(EncodingEventSubscriberTest, MultiplePacketEvents) { int packet_id_1 = 2; int packet_id_2 = 3; int size = 100; - 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)); + 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)); base::TimeTicks now2(testing_clock_->NowTicks()); - 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()); + cast_environment_->Logging()->InsertPacketEvent(now2, + PACKET_RETRANSMITTED, + VIDEO_EVENT, + rtp_timestamp_2, + /*frame_id*/ 0, + packet_id_2, + /*max_packet_id*/ 10, + size); GetEventsAndReset(); @@ -606,21 +544,16 @@ TEST_F(EncodingEventSubscriberTest, FirstRtpTimestamp) { RtpTimestamp rtp_timestamp = 12345; base::TimeTicks now(testing_clock_->NowTicks()); - 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()); + 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); GetEventsAndReset(); @@ -637,13 +570,11 @@ TEST_F(EncodingEventSubscriberTest, FirstRtpTimestamp) { rtp_timestamp = 67890; - 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()); - + cast_environment_->Logging()->InsertFrameEvent(now, + FRAME_CAPTURE_BEGIN, + VIDEO_EVENT, + rtp_timestamp, + /*frame_id*/ 0); GetEventsAndReset(); EXPECT_EQ(rtp_timestamp, first_rtp_timestamp_); @@ -654,22 +585,17 @@ TEST_F(EncodingEventSubscriberTest, RelativeRtpTimestampWrapAround) { RtpTimestamp rtp_timestamp = 0xffffffff - 20; base::TimeTicks now(testing_clock_->NowTicks()); - 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()); + cast_environment_->Logging()->InsertFrameEvent(now, + FRAME_CAPTURE_BEGIN, + VIDEO_EVENT, + rtp_timestamp, + /*frame_id*/ 0); // RtpTimestamp has now wrapped around. - 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()); + cast_environment_->Logging()->InsertCapturedVideoFrameEvent( + now, + rtp_timestamp + 30, + 1280, 720); GetEventsAndReset(); @@ -688,15 +614,12 @@ TEST_F(EncodingEventSubscriberTest, MaxEventsPerProto) { Init(VIDEO_EVENT); RtpTimestamp rtp_timestamp = 100; for (int i = 0; i < kMaxEventsPerProto + 1; i++) { - 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)); + cast_environment_->Logging()->InsertFrameEvent(testing_clock_->NowTicks(), + FRAME_ACK_RECEIVED, + VIDEO_EVENT, + rtp_timestamp, + /*frame_id*/ 0); + testing_clock_->Advance(base::TimeDelta::FromMilliseconds(30)); } GetEventsAndReset(); @@ -710,18 +633,16 @@ TEST_F(EncodingEventSubscriberTest, MaxEventsPerProto) { EXPECT_EQ(kMaxEventsPerProto, frame_event->event_type_size()); for (int i = 0; i < kMaxPacketsPerFrame + 1; i++) { - 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)); + 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)); } GetEventsAndReset(); @@ -741,18 +662,16 @@ TEST_F(EncodingEventSubscriberTest, MaxEventsPerProto) { EXPECT_EQ(1, packet_event->base_packet_event_size()); for (int j = 0; j < kMaxEventsPerProto + 1; j++) { - 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)); + 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)); } GetEventsAndReset(); diff --git a/media/cast/logging/log_event_dispatcher.cc b/media/cast/logging/log_event_dispatcher.cc deleted file mode 100644 index ac0e9ab..0000000 --- a/media/cast/logging/log_event_dispatcher.cc +++ /dev/null @@ -1,137 +0,0 @@ -// 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 deleted file mode 100644 index d84e79b..0000000 --- a/media/cast/logging/log_event_dispatcher.h +++ /dev/null @@ -1,81 +0,0 @@ -// 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 new file mode 100644 index 0000000..b64674f --- /dev/null +++ b/media/cast/logging/logging_impl.cc @@ -0,0 +1,131 @@ +// 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 new file mode 100644 index 0000000..1fc3e76 --- /dev/null +++ b/media/cast/logging/logging_impl.h @@ -0,0 +1,86 @@ +// 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 new file mode 100644 index 0000000..fb2779c --- /dev/null +++ b/media/cast/logging/logging_impl_unittest.cc @@ -0,0 +1,235 @@ +// 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 new file mode 100644 index 0000000..b80c05e --- /dev/null +++ b/media/cast/logging/logging_raw.cc @@ -0,0 +1,140 @@ +// 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 new file mode 100644 index 0000000..49ec985 --- /dev/null +++ b/media/cast/logging/logging_raw.h @@ -0,0 +1,106 @@ +// 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 new file mode 100644 index 0000000..0ecfbbf --- /dev/null +++ b/media/cast/logging/logging_raw_unittest.cc @@ -0,0 +1,202 @@ +// 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 ecfe10d..5dc5f79 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_->logger()->Subscribe(&event_subscriber_); - cast_environment_->logger()->Subscribe(&stats_subscriber_); + cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_); + cast_environment_->Logging()->AddRawEventSubscriber(&stats_subscriber_); } RawEventSubscriberBundleForStream::~RawEventSubscriberBundleForStream() { - cast_environment_->logger()->Unsubscribe(&event_subscriber_); - cast_environment_->logger()->Unsubscribe(&stats_subscriber_); + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); + cast_environment_->Logging()->RemoveRawEventSubscriber(&stats_subscriber_); } EncodingEventSubscriber* @@ -45,14 +45,17 @@ RawEventSubscriberBundle::RawEventSubscriberBundle( : cast_environment_(cast_environment) {} RawEventSubscriberBundle::~RawEventSubscriberBundle() { - if (receiver_offset_estimator_.get()) - cast_environment_->logger()->Unsubscribe(receiver_offset_estimator_.get()); + if (receiver_offset_estimator_.get()) { + cast_environment_->Logging()->RemoveRawEventSubscriber( + receiver_offset_estimator_.get()); + } } void RawEventSubscriberBundle::AddEventSubscribers(bool is_audio) { if (!receiver_offset_estimator_.get()) { receiver_offset_estimator_.reset(new ReceiverTimeOffsetEstimatorImpl); - cast_environment_->logger()->Subscribe(receiver_offset_estimator_.get()); + cast_environment_->Logging()->AddRawEventSubscriber( + receiver_offset_estimator_.get()); } SubscribersMapByStream::iterator it = subscribers_.find(is_audio); if (it != subscribers_.end()) @@ -71,7 +74,8 @@ void RawEventSubscriberBundle::RemoveEventSubscribers(bool is_audio) { subscribers_.erase(it); if (subscribers_.empty()) { - cast_environment_->logger()->Unsubscribe(receiver_offset_estimator_.get()); + cast_environment_->Logging()->RemoveRawEventSubscriber( + 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 2cbaafd..ca791d4 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_->logger()->Subscribe(&estimator_); + cast_environment_->Logging()->AddRawEventSubscriber(&estimator_); } ~ReceiverTimeOffsetEstimatorImplTest() override { - cast_environment_->logger()->Unsubscribe(&estimator_); + cast_environment_->Logging()->RemoveRawEventSubscriber(&estimator_); } void AdvanceClocks(base::TimeDelta time) { - task_runner_->Sleep(time); + sender_clock_->Advance(time); receiver_clock_.Advance(time); } @@ -63,62 +63,44 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EstimateOffset) { AdvanceClocks(base::TimeDelta::FromMilliseconds(20)); - 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()); + 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); EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); AdvanceClocks(base::TimeDelta::FromMilliseconds(10)); - 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()); + 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); EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); AdvanceClocks(base::TimeDelta::FromMilliseconds(30)); - 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()); + cast_environment_->Logging()->InsertFrameEvent( + sender_clock_->NowTicks(), FRAME_ACK_RECEIVED, VIDEO_EVENT, + rtp_timestamp, frame_id); EXPECT_TRUE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); @@ -130,7 +112,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 doesn't mean +// Same scenario as above, but event C arrives before event B. It doens't mean // event C occurred before event B. TEST_F(ReceiverTimeOffsetEstimatorImplTest, EventCArrivesBeforeEventB) { int64 true_offset_ms = 100; @@ -146,29 +128,23 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EventCArrivesBeforeEventB) { AdvanceClocks(base::TimeDelta::FromMilliseconds(20)); - 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()); + 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); EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); @@ -177,34 +153,20 @@ TEST_F(ReceiverTimeOffsetEstimatorImplTest, EventCArrivesBeforeEventB) { AdvanceClocks(base::TimeDelta::FromMilliseconds(30)); base::TimeTicks event_c_time = sender_clock_->NowTicks(); - 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()); + cast_environment_->Logging()->InsertFrameEvent( + event_c_time, FRAME_ACK_RECEIVED, VIDEO_EVENT, rtp_timestamp, frame_id); EXPECT_FALSE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); - 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()); + 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); EXPECT_TRUE(estimator_.GetReceiverOffsetBounds(&lower_bound, &upper_bound)); @@ -236,155 +198,111 @@ 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)); - 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()); + 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); AdvanceClocks(base::TimeDelta::FromMilliseconds(10)); - 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()); + 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); AdvanceClocks(base::TimeDelta::FromMilliseconds(20)); - 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()); + 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); AdvanceClocks(base::TimeDelta::FromMilliseconds(5)); - 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()); + cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), + FRAME_ACK_RECEIVED, + VIDEO_EVENT, + rtp_timestamp_b, + frame_id_b); AdvanceClocks(base::TimeDelta::FromMilliseconds(5)); - 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()); + cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), + FRAME_ACK_RECEIVED, + VIDEO_EVENT, + rtp_timestamp_a, + frame_id_a); AdvanceClocks(base::TimeDelta::FromMilliseconds(17)); - 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()); + 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); AdvanceClocks(base::TimeDelta::FromMilliseconds(3)); - 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()); + 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); AdvanceClocks(base::TimeDelta::FromMilliseconds(30)); - 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()); + cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), + FRAME_ACK_RECEIVED, + VIDEO_EVENT, + rtp_timestamp_c, + frame_id_c); 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 92b6c6e..bf2c210 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_->logger()->Subscribe(&event_subscriber_); + cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_); } ~SimpleEventSubscriberTest() override { - cast_environment_->logger()->Unsubscribe(&event_subscriber_); + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); } base::SimpleTestTickClock* testing_clock_; // Owned by CastEnvironment. @@ -40,58 +40,32 @@ class SimpleEventSubscriberTest : public ::testing::Test { TEST_F(SimpleEventSubscriberTest, GetAndResetEvents) { // Log some frame events. - 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()); + 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); // Log some packet events. - 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()); + 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); std::vector<FrameEvent> frame_events; event_subscriber_.GetFrameEventsAndReset(&frame_events); @@ -99,7 +73,7 @@ TEST_F(SimpleEventSubscriberTest, GetAndResetEvents) { std::vector<PacketEvent> packet_events; event_subscriber_.GetPacketEventsAndReset(&packet_events); - EXPECT_EQ(2u, packet_events.size()); + EXPECT_EQ(3u, 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 d649c89..09dc517 100644 --- a/media/cast/logging/stats_event_subscriber_unittest.cc +++ b/media/cast/logging/stats_event_subscriber_unittest.cc @@ -35,17 +35,19 @@ class StatsEventSubscriberTest : public ::testing::Test { fake_offset_estimator_( base::TimeDelta::FromSeconds(kReceiverOffsetSecs)) { receiver_clock_.Advance(base::TimeDelta::FromSeconds(kReceiverOffsetSecs)); - cast_environment_->logger()->Subscribe(&fake_offset_estimator_); + cast_environment_->Logging()->AddRawEventSubscriber( + &fake_offset_estimator_); } ~StatsEventSubscriberTest() override { if (subscriber_.get()) - cast_environment_->logger()->Unsubscribe(subscriber_.get()); - cast_environment_->logger()->Unsubscribe(&fake_offset_estimator_); + cast_environment_->Logging()->RemoveRawEventSubscriber(subscriber_.get()); + cast_environment_->Logging()->RemoveRawEventSubscriber( + &fake_offset_estimator_); } void AdvanceClocks(base::TimeDelta delta) { - task_runner_->Sleep(delta); + sender_clock_->Advance(delta); receiver_clock_.Advance(delta); } @@ -53,7 +55,7 @@ class StatsEventSubscriberTest : public ::testing::Test { DCHECK(!subscriber_.get()); subscriber_.reset(new StatsEventSubscriber( event_media_type, cast_environment_->Clock(), &fake_offset_estimator_)); - cast_environment_->logger()->Subscribe(subscriber_.get()); + cast_environment_->Logging()->AddRawEventSubscriber(subscriber_.get()); } base::SimpleTestTickClock* sender_clock_; // Owned by CastEnvironment. @@ -77,35 +79,30 @@ 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++) { - 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()); - + cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), + FRAME_CAPTURE_BEGIN, + VIDEO_EVENT, + rtp_timestamp, + frame_id); AdvanceClocks(base::TimeDelta::FromMicroseconds(10)); - 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()); - + cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), + FRAME_CAPTURE_END, + VIDEO_EVENT, + rtp_timestamp, + frame_id); if (i % 2 == 0) { AdvanceClocks(base::TimeDelta::FromMicroseconds(10)); - 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()); + cast_environment_->Logging()->InsertEncodedFrameEvent( + sender_clock_->NowTicks(), + FRAME_ENCODED, + VIDEO_EVENT, + rtp_timestamp, + frame_id, + 1024, + true, + 5678, + 9.10, + 11.12); } else if (i < extra_frames) { dropped_frames++; } @@ -158,18 +155,16 @@ TEST_F(StatsEventSubscriberTest, Encode) { for (int i = 0; i < num_frames; i++) { int size = 1000 + base::RandInt(-100, 100); total_size += size; - 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()); + cast_environment_->Logging()->InsertEncodedFrameEvent( + sender_clock_->NowTicks(), + FRAME_ENCODED, VIDEO_EVENT, + rtp_timestamp, + frame_id, + size, + true, + 5678, + 9.10, + 11.12); last_event_time = sender_clock_->NowTicks(); AdvanceClocks(base::TimeDelta::FromMicroseconds(35678)); @@ -220,13 +215,10 @@ TEST_F(StatsEventSubscriberTest, Decode) { int num_frames = 10; base::TimeTicks start_time = sender_clock_->NowTicks(); for (int i = 0; i < num_frames; i++) { - 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()); + cast_environment_->Logging()->InsertFrameEvent(receiver_clock_.NowTicks(), + FRAME_DECODED, VIDEO_EVENT, + rtp_timestamp, + frame_id); AdvanceClocks(base::TimeDelta::FromMicroseconds(36789)); rtp_timestamp += 90; @@ -259,14 +251,13 @@ TEST_F(StatsEventSubscriberTest, PlayoutDelay) { base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms); if (delay_ms > 0) late_frames++; - 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()); + cast_environment_->Logging()->InsertFrameEventWithDelay( + receiver_clock_.NowTicks(), + FRAME_PLAYOUT, + VIDEO_EVENT, + rtp_timestamp, + frame_id, + delay); AdvanceClocks(base::TimeDelta::FromMicroseconds(37890)); rtp_timestamp += 90; @@ -291,12 +282,11 @@ TEST_F(StatsEventSubscriberTest, E2ELatency) { int num_frames = 10; base::TimeDelta total_latency; for (int i = 0; i < num_frames; i++) { - 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()); + cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), + FRAME_CAPTURE_BEGIN, + VIDEO_EVENT, + rtp_timestamp, + frame_id); int latency_micros = 100000 + base::RandInt(-5000, 50000); base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros); @@ -306,14 +296,13 @@ TEST_F(StatsEventSubscriberTest, E2ELatency) { base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_micros); total_latency += latency; - 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()); + cast_environment_->Logging()->InsertFrameEventWithDelay( + receiver_clock_.NowTicks(), + FRAME_PLAYOUT, + VIDEO_EVENT, + rtp_timestamp, + frame_id, + delay); rtp_timestamp += 90; frame_id++; @@ -349,13 +338,11 @@ TEST_F(StatsEventSubscriberTest, Packets) { base::TimeTicks sender_encoded_time = sender_clock_->NowTicks(); base::TimeTicks receiver_encoded_time = receiver_clock_.NowTicks(); - 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()); + cast_environment_->Logging()->InsertFrameEvent(sender_encoded_time, + FRAME_ENCODED, + VIDEO_EVENT, + rtp_timestamp, + 0); // Every 2nd packet will be retransmitted once. // Every 4th packet will be retransmitted twice. @@ -364,17 +351,14 @@ TEST_F(StatsEventSubscriberTest, Packets) { int size = 1000 + base::RandInt(-100, 100); total_size += 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()); - + cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(), + PACKET_SENT_TO_NETWORK, + VIDEO_EVENT, + rtp_timestamp, + 0, + i, + num_packets - 1, + size); num_packets_transmitted++; total_queueing_latency += sender_clock_->NowTicks() - sender_encoded_time; @@ -395,17 +379,15 @@ TEST_F(StatsEventSubscriberTest, Packets) { // Retransmission 1. AdvanceClocks(base::TimeDelta::FromMicroseconds(12345)); if (i % 2 == 0) { - 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()); - + cast_environment_->Logging()->InsertPacketEvent( + receiver_clock_.NowTicks(), + PACKET_RETRANSMITTED, + VIDEO_EVENT, + rtp_timestamp, + 0, + i, + num_packets - 1, + size); retransmit_total_size += size; num_packets_transmitted++; num_packets_retransmitted++; @@ -414,17 +396,15 @@ TEST_F(StatsEventSubscriberTest, Packets) { // Retransmission 2. AdvanceClocks(base::TimeDelta::FromMicroseconds(13456)); if (i % 4 == 0) { - 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()); - + cast_environment_->Logging()->InsertPacketEvent( + receiver_clock_.NowTicks(), + PACKET_RETRANSMITTED, + VIDEO_EVENT, + rtp_timestamp, + 0, + i, + num_packets - 1, + size); retransmit_total_size += size; num_packets_transmitted++; num_packets_retransmitted++; @@ -433,45 +413,38 @@ TEST_F(StatsEventSubscriberTest, Packets) { // Retransmission 3. AdvanceClocks(base::TimeDelta::FromMicroseconds(14567)); if (i % 8 == 0) { - 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()); - + 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); retransmit_total_size += size; num_packets_transmitted++; num_packets_retransmitted++; num_packets_rtx_rejected++; } - 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()); - + cast_environment_->Logging()->InsertPacketEvent(received_time, + PACKET_RECEIVED, + VIDEO_EVENT, + rtp_timestamp, + 0, + i, + num_packets - 1, + size); num_packets_received++; } @@ -565,51 +538,43 @@ TEST_F(StatsEventSubscriberTest, Histograms) { for (int i = 0; i < 10; ++i) { ++frame_id; ++rtp_timestamp; - - 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()); - + cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), + FRAME_CAPTURE_BEGIN, + VIDEO_EVENT, + rtp_timestamp, + frame_id); AdvanceClocks(base::TimeDelta::FromMilliseconds(10)); - 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()); - + cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), + FRAME_CAPTURE_END, + VIDEO_EVENT, + rtp_timestamp, + frame_id); AdvanceClocks(base::TimeDelta::FromMilliseconds(15)); - 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()); + cast_environment_->Logging()->InsertEncodedFrameEvent( + sender_clock_->NowTicks(), + FRAME_ENCODED, + VIDEO_EVENT, + rtp_timestamp, + frame_id, + 1024, + true, + 5678, + 9.10, + 11.12); } // 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)); - 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()); + cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(), + PACKET_SENT_TO_NETWORK, + VIDEO_EVENT, + rtp_timestamp, + 0, + i, + 2, + 123); } // Receive 3 packets for the last frame. @@ -617,26 +582,23 @@ TEST_F(StatsEventSubscriberTest, Histograms) { // Packet latencies are 400ms. AdvanceClocks(base::TimeDelta::FromMilliseconds(100)); for (int i = 0; i < 3; ++i) { - 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()->InsertPacketEvent(receiver_clock_.NowTicks(), + PACKET_RECEIVED, + VIDEO_EVENT, + rtp_timestamp, + 0, + i, + 2, + 123); } - 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()); + cast_environment_->Logging()->InsertFrameEventWithDelay( + receiver_clock_.NowTicks(), + FRAME_PLAYOUT, + VIDEO_EVENT, + rtp_timestamp, + frame_id, + base::TimeDelta::FromMilliseconds(100)); 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 b20c9df..fc88a5c 100644 --- a/media/cast/net/cast_transport_sender.h +++ b/media/cast/net/cast_transport_sender.h @@ -20,7 +20,6 @@ #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" @@ -49,8 +48,8 @@ struct RtcpTimeData; typedef base::Callback<void(CastTransportStatus status)> CastTransportStatusCallback; -typedef base::Callback<void(scoped_ptr<std::vector<FrameEvent>>, - scoped_ptr<std::vector<PacketEvent>>)> +typedef base::Callback<void(const std::vector<PacketEvent>&, + const std::vector<FrameEvent>&)> 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 936bf81..9a763de 100644 --- a/media/cast/net/cast_transport_sender_impl.cc +++ b/media/cast/net/cast_transport_sender_impl.cc @@ -95,14 +95,15 @@ CastTransportSenderImpl::CastTransportSenderImpl( : clock_(clock), status_callback_(status_callback), transport_task_runner_(transport_task_runner), - transport_(external_transport - ? nullptr - : new UdpTransport(net_log, - transport_task_runner, - local_end_point, - remote_end_point, - GetTransportSendBufferSize(*options), - status_callback)), + transport_( + external_transport ? + NULL : + new UdpTransport(net_log, + transport_task_runner, + local_end_point, + remote_end_point, + GetTransportSendBufferSize(*options), + status_callback)), pacer_(LookupOptionWithDefault(*options, kOptionPacerTargetBurstSize, kTargetBurstSize), @@ -110,7 +111,7 @@ CastTransportSenderImpl::CastTransportSenderImpl( kOptionPacerMaxBurstSize, kMaxBurstSize), clock, - raw_events_callback.is_null() ? nullptr : &recent_packet_events_, + &logging_, external_transport ? external_transport : transport_.get(), transport_task_runner), raw_events_callback_(raw_events_callback), @@ -121,6 +122,8 @@ 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, @@ -158,6 +161,8 @@ CastTransportSenderImpl::~CastTransportSenderImpl() { if (transport_) { transport_->StopReceiving(); } + if (event_subscriber_.get()) + logging_.RemoveRawEventSubscriber(event_subscriber_.get()); } void CastTransportSenderImpl::InitializeAudio( @@ -336,17 +341,13 @@ PacketReceiverCallback CastTransportSenderImpl::PacketReceiverForTesting() { } void CastTransportSenderImpl::SendRawEvents() { + DCHECK(event_subscriber_.get()); DCHECK(!raw_events_callback_.is_null()); - - 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()); - } + 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); transport_task_runner_->PostDelayedTask( FROM_HERE, @@ -389,40 +390,35 @@ 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. - 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; + 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); break; - } case FRAME_ACK_SENT: case FRAME_DECODED: - 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; + 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); break; - } default: VLOG(2) << "Received log message via RTCP that we did not expect: " - << event_log_message.type; + << static_cast<int>(event_it->type); break; } } diff --git a/media/cast/net/cast_transport_sender_impl.h b/media/cast/net/cast_transport_sender_impl.h index 7a83afd..a5538e7 100644 --- a/media/cast/net/cast_transport_sender_impl.h +++ b/media/cast/net/cast_transport_sender_impl.h @@ -25,7 +25,6 @@ #define MEDIA_CAST_NET_CAST_TRANSPORT_SENDER_IMPL_H_ #include <set> -#include <vector> #include "base/callback.h" #include "base/gtest_prod_util.h" @@ -36,6 +35,7 @@ #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 - // in |recent_frame_events_| and |recent_packet_events_| since last call. + // by |event_subscriber_| since last call. void SendRawEvents(); // Called when a packet is received. @@ -155,10 +155,7 @@ class CastTransportSenderImpl : public CastTransportSender { CastTransportStatusCallback status_callback_; scoped_refptr<base::SingleThreadTaskRunner> transport_task_runner_; - // 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_; + LoggingImpl logging_; // Interface to a UDP socket. scoped_ptr<UdpTransport> transport_; @@ -181,6 +178,9 @@ 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 9758f3e..921bddf 100644 --- a/media/cast/net/cast_transport_sender_impl_unittest.cc +++ b/media/cast/net/cast_transport_sender_impl_unittest.cc @@ -66,7 +66,8 @@ class FakePacketSender : public PacketSender { class CastTransportSenderImplTest : public ::testing::Test { protected: - CastTransportSenderImplTest() : num_times_logging_callback_called_(0) { + CastTransportSenderImplTest() + : num_times_callback_called_(0) { testing_clock_.Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); task_runner_ = new test::FakeSingleThreadTaskRunner(&testing_clock_); @@ -150,9 +151,9 @@ class CastTransportSenderImplTest : public ::testing::Test { RtcpRttCallback()); } - void LogRawEvents(scoped_ptr<std::vector<FrameEvent>> frame_events, - scoped_ptr<std::vector<PacketEvent>> packet_events) { - num_times_logging_callback_called_++; + void LogRawEvents(const std::vector<PacketEvent>& packet_events, + const std::vector<FrameEvent>& frame_events) { + num_times_callback_called_++; } static void UpdateCastTransportStatus(CastTransportStatus status) { @@ -162,26 +163,31 @@ class CastTransportSenderImplTest : public ::testing::Test { scoped_refptr<test::FakeSingleThreadTaskRunner> task_runner_; scoped_ptr<CastTransportSenderImpl> transport_sender_; FakePacketSender transport_; - int num_times_logging_callback_called_; + int num_times_callback_called_; }; TEST_F(CastTransportSenderImplTest, InitWithoutLogging) { InitWithoutLogging(); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); - EXPECT_EQ(0, num_times_logging_callback_called_); + 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_); } TEST_F(CastTransportSenderImplTest, InitWithOptions) { InitWithOptions(); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); - EXPECT_EQ(0, num_times_logging_callback_called_); + EXPECT_EQ(0, num_times_callback_called_); } TEST_F(CastTransportSenderImplTest, NacksCancelRetransmits) { - InitWithLogging(); + InitWithoutLogging(); 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; @@ -193,7 +199,6 @@ 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; @@ -208,7 +213,6 @@ 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; @@ -219,7 +223,6 @@ 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. @@ -227,10 +230,9 @@ TEST_F(CastTransportSenderImplTest, NacksCancelRetransmits) { } TEST_F(CastTransportSenderImplTest, CancelRetransmits) { - InitWithLogging(); + InitWithoutLogging(); 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; @@ -242,7 +244,6 @@ 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; @@ -255,25 +256,21 @@ 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) { - InitWithLogging(); + InitWithoutLogging(); 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; @@ -288,7 +285,6 @@ 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; @@ -303,7 +299,6 @@ 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. @@ -311,11 +306,10 @@ TEST_F(CastTransportSenderImplTest, Kickstart) { } TEST_F(CastTransportSenderImplTest, DedupRetransmissionWithAudio) { - InitWithLogging(); + InitWithoutLogging(); InitializeAudio(); InitializeVideo(); task_runner_->Sleep(base::TimeDelta::FromMilliseconds(50)); - EXPECT_EQ(0, num_times_logging_callback_called_); // Send two audio frames. EncodedFrame fake_audio; @@ -340,7 +334,6 @@ 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; @@ -350,7 +343,6 @@ 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; @@ -362,7 +354,6 @@ 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; @@ -374,7 +365,6 @@ 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; @@ -386,10 +376,6 @@ 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 b8642b1..6b39f07 100644 --- a/media/cast/net/pacing/paced_sender.cc +++ b/media/cast/net/pacing/paced_sender.cc @@ -8,6 +8,7 @@ #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 { @@ -44,11 +45,11 @@ PacedSender::PacedSender( size_t target_burst_size, size_t max_burst_size, base::TickClock* clock, - std::vector<PacketEvent>* recent_packet_events, + LoggingImpl* logging, PacketSender* transport, const scoped_refptr<base::SingleThreadTaskRunner>& transport_task_runner) : clock_(clock), - recent_packet_events_(recent_packet_events), + logging_(logging), transport_(transport), transport_task_runner_(transport_task_runner), audio_ssrc_(0), @@ -61,7 +62,8 @@ PacedSender::PacedSender( current_burst_size_(0), state_(State_Unblocked), has_reached_upper_bound_once_(false), - weak_factory_(this) {} + weak_factory_(this) { +} PacedSender::~PacedSender() {} @@ -318,37 +320,27 @@ void PacedSender::SendStoredPackets() { state_ = State_Unblocked; } -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); +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); uint32 ssrc; - success &= reader.ReadU32(&ssrc); + bool success = reader.ReadU32(&ssrc); + DCHECK(success); + bool is_audio; if (ssrc == audio_ssrc_) { - event.media_type = AUDIO_EVENT; + is_audio = true; } else if (ssrc == video_ssrc_) { - event.media_type = VIDEO_EVENT; + is_audio = false; } else { DVLOG(3) << "Got unknown ssrc " << ssrc << " when logging packet event"; return; } - success &= reader.Skip(2); - success &= reader.ReadU16(&event.packet_id); - success &= reader.ReadU16(&event.max_packet_id); - event.size = packet.size(); - DCHECK(success); + + EventMediaType media_type = is_audio ? AUDIO_EVENT : VIDEO_EVENT; + logging_->InsertSinglePacketEvent(clock_->NowTicks(), event, media_type, + packet); } } // namespace cast diff --git a/media/cast/net/pacing/paced_sender.h b/media/cast/net/pacing/paced_sender.h index a5fcfd17..122cf55 100644 --- a/media/cast/net/pacing/paced_sender.h +++ b/media/cast/net/pacing/paced_sender.h @@ -26,6 +26,8 @@ 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: @@ -77,15 +79,13 @@ class PacedSender : public PacedPacketSender, public base::NonThreadSafe, public base::SupportsWeakPtr<PacedSender> { public: - // |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 + // 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, - std::vector<PacketEvent>* recent_packet_events, + LoggingImpl* logging, PacketSender* external_transport, const scoped_refptr<base::SingleThreadTaskRunner>& transport_task_runner); @@ -120,9 +120,6 @@ 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 @@ -166,11 +163,9 @@ class PacedSender : public PacedPacketSender, // Returns true if the packet should have a higher priority. bool IsHighPriority(const PacketKey& packet_key) const; - // These are externally-owned objects injected via the constructor. - base::TickClock* const clock_; - std::vector<PacketEvent>* const recent_packet_events_; - PacketSender* const transport_; - + base::TickClock* const clock_; // Not owned by this class. + LoggingImpl* const logging_; // Not owned by this class. + PacketSender* transport_; // Not owned by this class. 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 13d5afd..2387d42 100644 --- a/media/cast/net/pacing/paced_sender_unittest.cc +++ b/media/cast/net/pacing/paced_sender_unittest.cc @@ -6,6 +6,8 @@ #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" @@ -25,7 +27,6 @@ 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: @@ -58,16 +59,24 @@ 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_, &packet_events_, - &mock_transport_, task_runner_)); + paced_sender_.reset(new PacedSender(kTargetBurstSize, + kMaxBurstSize, + &testing_clock_, + &logging_, + &mock_transport_, + task_runner_)); paced_sender_->RegisterAudioSsrc(kAudioSsrc); paced_sender_->RegisterVideoSsrc(kVideoSsrc); } + ~PacedSenderTest() override { + logging_.RemoveRawEventSubscriber(&subscriber_); + } + static void UpdateCastTransportStatus(CastTransportStatus status) { NOTREACHED(); } @@ -89,17 +98,12 @@ class PacedSenderTest : public ::testing::Test { PacketRef packet(new base::RefCountedData<Packet>); packet->data.resize(packet_size, kValue); - // 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); + // 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); packets.push_back(std::make_pair(key, packet)); } return packets; @@ -119,7 +123,8 @@ class PacedSenderTest : public ::testing::Test { return mock_transport_.expected_packet_size_.empty(); } - std::vector<PacketEvent> packet_events_; + LoggingImpl logging_; + SimpleEventSubscriber subscriber_; base::SimpleTestTickClock testing_clock_; TestPacketSender mock_transport_; scoped_refptr<test::FakeSingleThreadTaskRunner> task_runner_; @@ -149,7 +154,6 @@ 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)); @@ -173,21 +177,20 @@ TEST_F(PacedSenderTest, BasicPace) { // Check that we don't get any more packets. EXPECT_TRUE(RunUntilEmpty(3)); - 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); + + 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); } + EXPECT_EQ(num_of_packets, sent_to_network_event_count); } TEST_F(PacedSenderTest, PaceWithNack) { @@ -246,28 +249,32 @@ 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 (const PacketEvent& e : packet_events_) { - if (e.type == PACKET_SENT_TO_NETWORK) { - if (e.media_type == VIDEO_EVENT) + 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) video_network_event_count++; else audio_network_event_count++; - } else if (e.type == PACKET_RETRANSMITTED) { - if (e.media_type == VIDEO_EVENT) + } else if (it->type == PACKET_RETRANSMITTED) { + if (it->media_type == VIDEO_EVENT) video_retransmitted_event_count++; } else { - FAIL() << "Got unexpected event type " << CastLoggingToString(e.type); + FAIL() << "Got unexpected event type " << CastLoggingToString(it->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 4980494..bd31d24 100644 --- a/media/cast/net/rtcp/receiver_rtcp_event_subscriber_unittest.cc +++ b/media/cast/net/rtcp/receiver_rtcp_event_subscriber_unittest.cc @@ -37,92 +37,56 @@ class ReceiverRtcpEventSubscriberTest : public ::testing::Test { void TearDown() final { if (event_subscriber_) { - cast_environment_->logger()->Unsubscribe(event_subscriber_.get()); - event_subscriber_.reset(); + cast_environment_->Logging()->RemoveRawEventSubscriber( + event_subscriber_.get()); } } void Init(EventMediaType type) { event_subscriber_.reset( new ReceiverRtcpEventSubscriber(kMaxEventEntries, type)); - cast_environment_->logger()->Subscribe(event_subscriber_.get()); + cast_environment_->Logging()->AddRawEventSubscriber( + event_subscriber_.get()); } void InsertEvents() { // Video events - 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()); + 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); // Audio events - 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()); + 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); // Unrelated events - 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()); + 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); } base::SimpleTestTickClock* testing_clock_; // Owned by CastEnvironment. @@ -153,13 +117,9 @@ TEST_F(ReceiverRtcpEventSubscriberTest, DropEventsWhenSizeExceeded) { Init(VIDEO_EVENT); for (uint32 i = 1u; i <= 10u; ++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()); + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), FRAME_DECODED, VIDEO_EVENT, + /*rtp_timestamp*/ i * 10, /*frame_id*/ i); } 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 12cafd6..6669b5e 100644 --- a/media/cast/net/rtp/rtp_packetizer_unittest.cc +++ b/media/cast/net/rtp/rtp_packetizer_unittest.cc @@ -8,6 +8,8 @@ #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" @@ -112,8 +114,11 @@ 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_, nullptr, transport_.get(), + pacer_.reset(new PacedSender(kTargetBurstSize, + kMaxBurstSize, + &testing_clock_, + &logging_, + transport_.get(), task_runner_)); pacer_->RegisterVideoSsrc(config_.ssrc); rtp_packetizer_.reset(new RtpPacketizer( @@ -139,6 +144,7 @@ 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 929deb5..f8a40be 100644 --- a/media/cast/receiver/audio_decoder.cc +++ b/media/cast/receiver/audio_decoder.cc @@ -59,15 +59,6 @@ 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 83d8bf7..5a01bb0 100644 --- a/media/cast/receiver/cast_receiver_impl.cc +++ b/media/cast/receiver/cast_receiver_impl.cc @@ -178,20 +178,14 @@ void CastReceiverImpl::EmitDecodedAudioFrame( scoped_ptr<AudioBus> audio_bus, bool is_continuous) { DCHECK(cast_environment->CurrentlyOn(CastEnvironment::MAIN)); - if (audio_bus.get()) { - // 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()); + 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); } - callback.Run(audio_bus.Pass(), playout_time, is_continuous); } @@ -205,18 +199,13 @@ void CastReceiverImpl::EmitDecodedVideoFrame( const scoped_refptr<VideoFrame>& video_frame, bool is_continuous) { DCHECK(cast_environment->CurrentlyOn(CastEnvironment::MAIN)); - if (video_frame.get()) { - // 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()); + 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); // Used by chrome/browser/extension/api/cast_streaming/performance_test.cc TRACE_EVENT_INSTANT1( @@ -224,7 +213,6 @@ 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 3d89594..c0b15df 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_->logger()->Subscribe(&event_subscriber_); + cast_environment_->Logging()->AddRawEventSubscriber(&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_->logger()->Unsubscribe(&event_subscriber_); + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); } void FrameReceiver::RequestEncodedFrame( @@ -110,17 +110,10 @@ void FrameReceiver::ProcessParsedPacket(const RtpCastHeader& rtp_header, frame_id_to_rtp_timestamp_[rtp_header.frame_id & 0xff] = rtp_header.rtp_timestamp; - - 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()); + 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); bool duplicate = false; const bool complete = @@ -172,14 +165,9 @@ 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]; - - 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()); + cast_environment_->Logging()->InsertFrameEvent( + now, FRAME_ACK_SENT, event_media_type_, + rtp_timestamp, cast_message.ack_frame_id); 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 79a6ef2..a92b93a 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_->logger()->Subscribe(&event_subscriber); + cast_environment_->Logging()->AddRawEventSubscriber(&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_->logger()->Unsubscribe(&event_subscriber); + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); } TEST_F(FrameReceiverTest, ReceivesOneFrame) { CreateFrameReceiverOfAudio(); SimpleEventSubscriber event_subscriber; - cast_environment_->logger()->Subscribe(&event_subscriber); + cast_environment_->Logging()->AddRawEventSubscriber(&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_->logger()->Unsubscribe(&event_subscriber); + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); } TEST_F(FrameReceiverTest, ReceivesFramesSkippingWhenAppropriate) { CreateFrameReceiverOfAudio(); SimpleEventSubscriber event_subscriber; - cast_environment_->logger()->Subscribe(&event_subscriber); + cast_environment_->Logging()->AddRawEventSubscriber(&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_->logger()->Unsubscribe(&event_subscriber); + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); } TEST_F(FrameReceiverTest, ReceivesFramesRefusingToSkipAny) { CreateFrameReceiverOfVideo(); SimpleEventSubscriber event_subscriber; - cast_environment_->logger()->Subscribe(&event_subscriber); + cast_environment_->Logging()->AddRawEventSubscriber(&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_->logger()->Unsubscribe(&event_subscriber); + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); } } // namespace cast diff --git a/media/cast/receiver/video_decoder.cc b/media/cast/receiver/video_decoder.cc index 534eac0..f9b24a420 100644 --- a/media/cast/receiver/video_decoder.cc +++ b/media/cast/receiver/video_decoder.cc @@ -61,15 +61,6 @@ 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 80d69fe9..f521b51 100644 --- a/media/cast/sender/audio_encoder.cc +++ b/media/cast/sender/audio_encoder.cc @@ -156,9 +156,6 @@ 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 aac20d7..61ac08b 100644 --- a/media/cast/sender/audio_encoder.h +++ b/media/cast/sender/audio_encoder.h @@ -9,7 +9,6 @@ #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 196b16e..ca389a5c 100644 --- a/media/cast/sender/external_video_encoder.cc +++ b/media/cast/sender/external_video_encoder.cc @@ -30,6 +30,16 @@ 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 { @@ -321,8 +331,15 @@ class ExternalVideoEncoder::VEAClientImpl base::debug::ClearCrashKey(kZeroEncodeDetails); } - encoded_frame->encode_completion_time = - cast_environment_->Clock()->NowTicks(); + cast_environment_->PostTask( + CastEnvironment::MAIN, + FROM_HERE, + base::Bind(&LogFrameEncodedEvent, + cast_environment_, + cast_environment_->Clock()->NowTicks(), + encoded_frame->rtp_timestamp, + encoded_frame->frame_id)); + cast_environment_->PostTask( CastEnvironment::MAIN, FROM_HERE, diff --git a/media/cast/sender/frame_sender.cc b/media/cast/sender/frame_sender.cc index 772cf01..ec37a6d 100644 --- a/media/cast/sender/frame_sender.cc +++ b/media/cast/sender/frame_sender.cc @@ -215,19 +215,15 @@ void FrameSender::SendEncodedFrame( VLOG_IF(1, !is_audio_ && encoded_frame->dependency == EncodedFrame::KEY) << SENDER_SSRC << "Sending encoded key frame, id=" << frame_id; - 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()); + 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); RecordLatestFrameTimestamps(frame_id, encoded_frame->reference_time, @@ -325,14 +321,12 @@ void FrameSender::OnReceivedCastFeedback(const RtcpCastMessage& cast_feedback) { base::TimeTicks now = cast_environment_->Clock()->NowTicks(); congestion_control_->AckFrame(cast_feedback.ack_frame_id, now); - 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()); + 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); 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 d02b738..53aaf65 100644 --- a/media/cast/sender/h264_vt_encoder.cc +++ b/media/cast/sender/h264_vt_encoder.cc @@ -756,8 +756,6 @@ 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 fa7787d..8a3b2fa 100644 --- a/media/cast/sender/sender_encoded_frame.h +++ b/media/cast/sender/sender_encoded_frame.h @@ -5,7 +5,6 @@ #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 { @@ -43,9 +42,6 @@ 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 fcfac17..d6b8e45 100644 --- a/media/cast/sender/video_encoder_impl.cc +++ b/media/cast/sender/video_encoder_impl.cc @@ -45,7 +45,6 @@ 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 f8890bb..a96f2fd 100644 --- a/media/cast/sender/video_sender.cc +++ b/media/cast/sender/video_sender.cc @@ -41,35 +41,26 @@ const int kTargetUtilizationPercentage = 75; // Extract capture begin/end timestamps from |video_frame|'s metadata and log // it. -void LogVideoCaptureTimestamps(CastEnvironment* cast_environment, +void LogVideoCaptureTimestamps(const CastEnvironment& cast_environment, const media::VideoFrame& video_frame, RtpTimestamp rtp_timestamp) { - 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(); - + base::TimeTicks capture_begin_time; + base::TimeTicks capture_end_time; if (!video_frame.metadata()->GetTimeTicks( - media::VideoFrameMetadata::CAPTURE_BEGIN_TIME, - &capture_begin_event->timestamp) || + media::VideoFrameMetadata::CAPTURE_BEGIN_TIME, &capture_begin_time) || !video_frame.metadata()->GetTimeTicks( - media::VideoFrameMetadata::CAPTURE_END_TIME, - &capture_end_event->timestamp)) { + media::VideoFrameMetadata::CAPTURE_END_TIME, &capture_end_time)) { // The frame capture timestamps were not provided by the video capture // source. Simply log the events as happening right now. - capture_begin_event->timestamp = capture_end_event->timestamp = - cast_environment->Clock()->NowTicks(); + capture_begin_time = capture_end_time = + cast_environment.Clock()->NowTicks(); } - - cast_environment->logger()->DispatchFrameEvent(capture_begin_event.Pass()); - cast_environment->logger()->DispatchFrameEvent(capture_end_event.Pass()); + 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()); } } // namespace @@ -151,8 +142,7 @@ void VideoSender::InsertRawVideoFrame( const RtpTimestamp rtp_timestamp = TimeDeltaToRtpDelta(video_frame->timestamp(), kVideoFrequency); - LogVideoCaptureTimestamps(cast_environment_.get(), *video_frame, - rtp_timestamp); + LogVideoCaptureTimestamps(*cast_environment_, *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 4b4c930..4e4996b 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_->logger()->Subscribe(&event_subscriber); + cast_environment_->Logging()->AddRawEventSubscriber(&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_->logger()->Unsubscribe(&event_subscriber); + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber); } TEST_F(VideoSenderTest, StopSendingInTheAbsenceOfAck) { diff --git a/media/cast/test/end2end_unittest.cc b/media/cast/test/end2end_unittest.cc index b7880c4..e8137c0 100644 --- a/media/cast/test/end2end_unittest.cc +++ b/media/cast/test/end2end_unittest.cc @@ -448,7 +448,8 @@ class End2EndTest : public ::testing::Test { test_receiver_video_callback_(new TestReceiverVideoCallback()) { testing_clock_.Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); - cast_environment_sender_->logger()->Subscribe(&event_subscriber_sender_); + cast_environment_sender_->Logging()->AddRawEventSubscriber( + &event_subscriber_sender_); } void Configure(Codec video_codec, @@ -574,21 +575,28 @@ class End2EndTest : public ::testing::Test { void Create() { net::IPEndPoint dummy_endpoint; transport_sender_.reset(new CastTransportSenderImpl( - nullptr, testing_clock_sender_, dummy_endpoint, dummy_endpoint, + NULL, + testing_clock_sender_, + dummy_endpoint, + dummy_endpoint, make_scoped_ptr(new base::DictionaryValue), base::Bind(&UpdateCastTransportStatus), - base::Bind(&LogEventDispatcher::DispatchBatchOfEvents, - base::Unretained(cast_environment_sender_->logger())), - base::TimeDelta::FromMilliseconds(1), task_runner_sender_, - PacketReceiverCallback(), &sender_to_receiver_)); + base::Bind(&End2EndTest::LogRawEvents, base::Unretained(this)), + base::TimeDelta::FromMilliseconds(1), + task_runner_sender_, + PacketReceiverCallback(), + &sender_to_receiver_)); transport_receiver_.reset(new CastTransportSenderImpl( - nullptr, testing_clock_sender_, dummy_endpoint, dummy_endpoint, + NULL, + testing_clock_sender_, + dummy_endpoint, + dummy_endpoint, make_scoped_ptr(new base::DictionaryValue), base::Bind(&UpdateCastTransportStatus), - base::Bind(&LogEventDispatcher::DispatchBatchOfEvents, - base::Unretained(cast_environment_receiver_->logger())), - base::TimeDelta::FromMilliseconds(1), task_runner_sender_, + base::Bind(&End2EndTest::LogRawEvents, base::Unretained(this)), + base::TimeDelta::FromMilliseconds(1), + task_runner_sender_, base::Bind(&End2EndTest::ReceivePacket, base::Unretained(this)), &receiver_to_sender_)); @@ -631,7 +639,8 @@ class End2EndTest : public ::testing::Test { } ~End2EndTest() override { - cast_environment_sender_->logger()->Unsubscribe(&event_subscriber_sender_); + cast_environment_sender_->Logging()->RemoveRawEventSubscriber( + &event_subscriber_sender_); } void TearDown() final { @@ -733,6 +742,33 @@ 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_; @@ -1215,8 +1251,6 @@ 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 5791ffe..514bc74 100644 --- a/media/cast/test/sender.cc +++ b/media/cast/test/sender.cc @@ -70,6 +70,37 @@ 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"; @@ -115,8 +146,10 @@ void WriteLogsToFileAndDestroySubscribers( scoped_ptr<media::cast::EncodingEventSubscriber> audio_event_subscriber, base::ScopedFILE video_log_file, base::ScopedFILE audio_log_file) { - cast_environment->logger()->Unsubscribe(video_event_subscriber.get()); - cast_environment->logger()->Unsubscribe(audio_event_subscriber.get()); + cast_environment->Logging()->RemoveRawEventSubscriber( + video_event_subscriber.get()); + cast_environment->Logging()->RemoveRawEventSubscriber( + audio_event_subscriber.get()); VLOG(0) << "Dumping logging data for video stream."; media::cast::proto::LogMetadata log_metadata; @@ -142,20 +175,22 @@ void WriteLogsToFileAndDestroySubscribers( void WriteStatsAndDestroySubscribers( const scoped_refptr<media::cast::CastEnvironment>& cast_environment, - scoped_ptr<media::cast::StatsEventSubscriber> video_stats_subscriber, - scoped_ptr<media::cast::StatsEventSubscriber> audio_stats_subscriber, + scoped_ptr<media::cast::StatsEventSubscriber> video_event_subscriber, + scoped_ptr<media::cast::StatsEventSubscriber> audio_event_subscriber, scoped_ptr<media::cast::ReceiverTimeOffsetEstimatorImpl> estimator) { - cast_environment->logger()->Unsubscribe(video_stats_subscriber.get()); - cast_environment->logger()->Unsubscribe(audio_stats_subscriber.get()); - cast_environment->logger()->Unsubscribe(estimator.get()); + cast_environment->Logging()->RemoveRawEventSubscriber( + video_event_subscriber.get()); + cast_environment->Logging()->RemoveRawEventSubscriber( + audio_event_subscriber.get()); + cast_environment->Logging()->RemoveRawEventSubscriber(estimator.get()); - scoped_ptr<base::DictionaryValue> stats = video_stats_subscriber->GetStats(); + scoped_ptr<base::DictionaryValue> stats = video_event_subscriber->GetStats(); std::string json; base::JSONWriter::WriteWithOptions( *stats, base::JSONWriter::OPTIONS_PRETTY_PRINT, &json); VLOG(0) << "Video stats: " << json; - stats = audio_stats_subscriber->GetStats(); + stats = audio_event_subscriber->GetStats(); json.clear(); base::JSONWriter::WriteWithOptions( *stats, base::JSONWriter::OPTIONS_PRETTY_PRINT, &json); @@ -237,14 +272,16 @@ int main(int argc, char** argv) { // CastTransportSender initialization. scoped_ptr<media::cast::CastTransportSender> transport_sender = media::cast::CastTransportSender::Create( - nullptr, // net log. - cast_environment->Clock(), net::IPEndPoint(), remote_endpoint, + NULL, // net log. + cast_environment->Clock(), + net::IPEndPoint(), + remote_endpoint, make_scoped_ptr(new base::DictionaryValue), // options base::Bind(&UpdateCastTransportStatus), - base::Bind(&media::cast::LogEventDispatcher::DispatchBatchOfEvents, - base::Unretained(cast_environment->logger())), + base::Bind(&LogRawEvents, cast_environment), 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; @@ -257,13 +294,15 @@ 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->logger()->Subscribe(video_event_subscriber.get()); - cast_environment->logger()->Subscribe(audio_event_subscriber.get()); + cast_environment->Logging()->AddRawEventSubscriber( + video_event_subscriber.get()); + cast_environment->Logging()->AddRawEventSubscriber( + audio_event_subscriber.get()); // Subscribers for stats. scoped_ptr<media::cast::ReceiverTimeOffsetEstimatorImpl> offset_estimator( new media::cast::ReceiverTimeOffsetEstimatorImpl()); - cast_environment->logger()->Subscribe(offset_estimator.get()); + cast_environment->Logging()->AddRawEventSubscriber(offset_estimator.get()); scoped_ptr<media::cast::StatsEventSubscriber> video_stats_subscriber( new media::cast::StatsEventSubscriber(media::cast::VIDEO_EVENT, cast_environment->Clock(), @@ -272,8 +311,10 @@ int main(int argc, char** argv) { new media::cast::StatsEventSubscriber(media::cast::AUDIO_EVENT, cast_environment->Clock(), offset_estimator.get())); - cast_environment->logger()->Subscribe(video_stats_subscriber.get()); - cast_environment->logger()->Subscribe(audio_stats_subscriber.get()); + cast_environment->Logging()->AddRawEventSubscriber( + video_stats_subscriber.get()); + cast_environment->Logging()->AddRawEventSubscriber( + audio_stats_subscriber.get()); base::ScopedFILE video_log_file(fopen(video_log_file_name.c_str(), "w")); if (!video_log_file) { diff --git a/media/cast/test/simulator.cc b/media/cast/test/simulator.cc index f63a797..540f377 100644 --- a/media/cast/test/simulator.cc +++ b/media/cast/test/simulator.cc @@ -121,6 +121,45 @@ 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 @@ -317,8 +356,8 @@ void RunSimulation(const base::FilePath& source_path, 100 * 60 * 60); EncodingEventSubscriber video_event_subscriber(VIDEO_EVENT, 30 * 60 * 60); - sender_env->logger()->Subscribe(&audio_event_subscriber); - sender_env->logger()->Subscribe(&video_event_subscriber); + sender_env->Logging()->AddRawEventSubscriber(&audio_event_subscriber); + sender_env->Logging()->AddRawEventSubscriber(&video_event_subscriber); // Audio sender config. AudioSenderConfig audio_sender_config = GetDefaultAudioSenderConfig(); @@ -366,12 +405,15 @@ void RunSimulation(const base::FilePath& source_path, // Cast receiver. scoped_ptr<CastTransportSender> transport_receiver( new CastTransportSenderImpl( - nullptr, &testing_clock, net::IPEndPoint(), net::IPEndPoint(), + NULL, + &testing_clock, + net::IPEndPoint(), + net::IPEndPoint(), make_scoped_ptr(new base::DictionaryValue), base::Bind(&UpdateCastTransportStatus), - base::Bind(&LogEventDispatcher::DispatchBatchOfEvents, - base::Unretained(receiver_env->logger())), - base::TimeDelta::FromSeconds(1), task_runner, + base::Bind(&LogTransportEvents, receiver_env), + base::TimeDelta::FromSeconds(1), + task_runner, base::Bind(&PacketProxy::ReceivePacket, base::Unretained(&packet_proxy)), &receiver_to_sender)); @@ -384,14 +426,19 @@ 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( - 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<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<CastSender> cast_sender( CastSender::Create(sender_env, transport_sender.get())); @@ -439,7 +486,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->logger()->Subscribe(video_frame_tracker.get()); + sender_env->Logging()->AddRawEventSubscriber(video_frame_tracker.get()); } // Quality metrics computed for each frame decoded. @@ -497,12 +544,6 @@ 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; |