From adb0fd7992ddc7c94741471fe54f68757491f156 Mon Sep 17 00:00:00 2001 From: "imcheng@chromium.org" Date: Sun, 9 Feb 2014 03:05:12 +0000 Subject: Changed LoggingRaw from pull-based to subscriber-based: - LoggingRaw no longer keeps its own maps internally. - LoggingRaw now keeps a list of RawEventSubscriber; these subscribers will be notified when there are new raw events. -- Added functions AddSubscriber() / RemoveSubscriber() - Added RawEventSubscriber, which is an interface with 3 functions, each handles a type of raw event (Frame, Packet, Generic) - Added 3 RawEventSubscriber implementations: -- ReceiverRtcpEventSubscriber, which keeps track of events that we want to send over via RTCP from receiver to sender, sorted by rtp timestamp, using a fixed size buffer. There is some data transformation involved. --- This is used in VideoReceiver / AudioReceiver -- SenderRtcpEventSubscriber, which keeps track of events that we want to send over via RTCP from sender to receiver, sorted by rtp timestamp, using a fixed size buffer. There is some data transformation involved and is slightly different from the receiver version. --- This is used in VideoSender -- SimpleEventSubscriber, which keeps track of all events as-is and periodically calls the given callback with the data at a fixed interval. --- I plan to use this in JS app / uploading use case. Other changes: - Remove SupportsWeakPtr from LoggingRaw, as it is not needed, as LoggingRaw is used as an object in LoggingImpl only. Proposal doc: https://docs.google.com/a/google.com/document/d/1GUIN4ZcScnAz_QuqDhxbvp5F6BOvLBjamdW0edMC5p4/edit?disco=AAAAAHx2Ng0 Note: I talked to Herve about his logging requirements, I can draft up a subscriber implementation for that too, if you would like to see how it roughly looks like. Review URL: https://codereview.chromium.org/139783013 git-svn-id: svn://svn.chromium.org/chrome/trunk/src@249973 0039d316-1c4b-4281-b951-d872f2087c98 --- media/cast/audio_receiver/audio_receiver.cc | 186 +++++------ media/cast/audio_receiver/audio_receiver.h | 21 +- .../cast/audio_receiver/audio_receiver_unittest.cc | 42 ++- media/cast/cast.gyp | 9 +- media/cast/logging/logging_defines.cc | 117 +++---- media/cast/logging/logging_defines.h | 78 ++--- media/cast/logging/logging_impl.cc | 119 +++---- media/cast/logging/logging_impl.h | 44 +-- media/cast/logging/logging_impl_unittest.cc | 350 +++++++++++++++++++++ media/cast/logging/logging_raw.cc | 239 ++++---------- media/cast/logging/logging_raw.h | 82 ++--- media/cast/logging/logging_raw_unittest.cc | 221 +++++++++++++ media/cast/logging/logging_unittest.cc | 329 ------------------- media/cast/logging/raw_event_subscriber.h | 36 +++ media/cast/logging/simple_event_subscriber.cc | 62 ++++ media/cast/logging/simple_event_subscriber.h | 64 ++++ .../logging/simple_event_subscriber_unittest.cc | 91 ++++++ media/cast/rtcp/receiver_rtcp_event_subscriber.cc | 144 +++++++++ media/cast/rtcp/receiver_rtcp_event_subscriber.h | 94 ++++++ .../receiver_rtcp_event_subscriber_unittest.cc | 185 +++++++++++ media/cast/rtcp/rtcp.cc | 148 +++------ media/cast/rtcp/rtcp.gyp | 5 + media/cast/rtcp/rtcp_defines.cc | 48 +++ media/cast/rtcp/rtcp_defines.h | 43 ++- media/cast/rtcp/rtcp_sender.cc | 91 +++--- media/cast/rtcp/sender_rtcp_event_subscriber.cc | 100 ++++++ media/cast/rtcp/sender_rtcp_event_subscriber.h | 80 +++++ .../rtcp/sender_rtcp_event_subscriber_unittest.cc | 122 +++++++ media/cast/test/end2end_unittest.cc | 297 +++++++++++------ media/cast/video_receiver/video_receiver.cc | 174 +++++----- media/cast/video_receiver/video_receiver.h | 11 +- media/cast/video_sender/video_sender.cc | 88 +++--- media/cast/video_sender/video_sender.h | 8 +- 33 files changed, 2414 insertions(+), 1314 deletions(-) create mode 100644 media/cast/logging/logging_impl_unittest.cc create mode 100644 media/cast/logging/logging_raw_unittest.cc delete mode 100644 media/cast/logging/logging_unittest.cc create mode 100644 media/cast/logging/raw_event_subscriber.h create mode 100644 media/cast/logging/simple_event_subscriber.cc create mode 100644 media/cast/logging/simple_event_subscriber.h create mode 100644 media/cast/logging/simple_event_subscriber_unittest.cc create mode 100644 media/cast/rtcp/receiver_rtcp_event_subscriber.cc create mode 100644 media/cast/rtcp/receiver_rtcp_event_subscriber.h create mode 100644 media/cast/rtcp/receiver_rtcp_event_subscriber_unittest.cc create mode 100644 media/cast/rtcp/rtcp_defines.cc create mode 100644 media/cast/rtcp/sender_rtcp_event_subscriber.cc create mode 100644 media/cast/rtcp/sender_rtcp_event_subscriber.h create mode 100644 media/cast/rtcp/sender_rtcp_event_subscriber_unittest.cc (limited to 'media') diff --git a/media/cast/audio_receiver/audio_receiver.cc b/media/cast/audio_receiver/audio_receiver.cc index 8d10d90..30ce561 100644 --- a/media/cast/audio_receiver/audio_receiver.cc +++ b/media/cast/audio_receiver/audio_receiver.cc @@ -10,14 +10,28 @@ #include "base/strings/string_piece.h" #include "media/cast/audio_receiver/audio_decoder.h" #include "media/cast/framer/framer.h" +#include "media/cast/rtcp/receiver_rtcp_event_subscriber.h" #include "media/cast/rtcp/rtcp.h" #include "media/cast/rtp_receiver/rtp_receiver.h" #include "media/cast/transport/cast_transport_defines.h" +namespace { + +using media::cast::kMaxIpPacketSize; +using media::cast::kRtcpCastLogHeaderSize; +using media::cast::kRtcpReceiverEventLogSize; + // Max time we wait until an audio frame is due to be played out is released. static const int64 kMaxAudioFrameWaitMs = 20; static const int64 kMinSchedulingDelayMs = 1; +// This is an upper bound on number of events that can fit into a single RTCP +// packet. +static const int64 kMaxEventSubscriberEntries = + (kMaxIpPacketSize - kRtcpCastLogHeaderSize) / kRtcpReceiverEventLogSize; + +} // namespace + namespace media { namespace cast { @@ -36,8 +50,8 @@ class LocalRtpAudioData : public RtpData { virtual void OnReceivedPayloadData(const uint8* payload_data, size_t payload_size, const RtpCastHeader* rtp_header) OVERRIDE { - audio_receiver_->IncomingParsedRtpPacket( - payload_data, payload_size, *rtp_header); + audio_receiver_->IncomingParsedRtpPacket(payload_data, payload_size, + *rtp_header); } private: @@ -68,8 +82,8 @@ class LocalRtpReceiverStatistics : public RtpReceiverStatistics { uint32* cumulative_lost, // 24 bits valid. uint32* extended_high_sequence_number, uint32* jitter) OVERRIDE { - rtp_receiver_->GetStatistics( - fraction_lost, cumulative_lost, extended_high_sequence_number, jitter); + rtp_receiver_->GetStatistics(fraction_lost, cumulative_lost, + extended_high_sequence_number, jitter); } private: @@ -80,6 +94,11 @@ AudioReceiver::AudioReceiver(scoped_refptr cast_environment, const AudioReceiverConfig& audio_config, transport::PacedPacketSender* const packet_sender) : cast_environment_(cast_environment), + event_subscriber_( + cast_environment->GetMessageSingleThreadTaskRunnerForThread( + CastEnvironment::MAIN), + kMaxEventSubscriberEntries, + ReceiverRtcpEventSubscriber::kAudioEventSubscriber), codec_(audio_config.codec), frequency_(audio_config.frequency), audio_buffer_(), @@ -93,12 +112,10 @@ AudioReceiver::AudioReceiver(scoped_refptr cast_environment, if (audio_config.use_external_decoder) { audio_buffer_.reset(new Framer(cast_environment->Clock(), incoming_payload_feedback_.get(), - audio_config.incoming_ssrc, - true, - 0)); + audio_config.incoming_ssrc, true, 0)); } else { - audio_decoder_.reset(new AudioDecoder( - cast_environment, audio_config, incoming_payload_feedback_.get())); + audio_decoder_.reset(new AudioDecoder(cast_environment, audio_config, + incoming_payload_feedback_.get())); } decryptor_.Initialize(audio_config.aes_key, audio_config.aes_iv_mask); rtp_receiver_.reset(new RtpReceiver(cast_environment->Clock(), @@ -109,20 +126,17 @@ AudioReceiver::AudioReceiver(scoped_refptr cast_environment, new LocalRtpReceiverStatistics(rtp_receiver_.get())); base::TimeDelta rtcp_interval_delta = base::TimeDelta::FromMilliseconds(audio_config.rtcp_interval); - rtcp_.reset(new Rtcp(cast_environment, - NULL, - NULL, - packet_sender, - NULL, + rtcp_.reset(new Rtcp(cast_environment, NULL, NULL, packet_sender, NULL, rtp_audio_receiver_statistics_.get(), - audio_config.rtcp_mode, - rtcp_interval_delta, - audio_config.feedback_ssrc, - audio_config.incoming_ssrc, + audio_config.rtcp_mode, rtcp_interval_delta, + audio_config.feedback_ssrc, audio_config.incoming_ssrc, audio_config.rtcp_c_name)); + cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_); } -AudioReceiver::~AudioReceiver() {} +AudioReceiver::~AudioReceiver() { + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); +} void AudioReceiver::InitializeTimers() { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); @@ -137,12 +151,8 @@ void AudioReceiver::IncomingParsedRtpPacket(const uint8* payload_data, base::TimeTicks now = cast_environment_->Clock()->NowTicks(); cast_environment_->Logging()->InsertPacketEvent( - now, - kAudioPacketReceived, - rtp_header.webrtc.header.timestamp, - rtp_header.frame_id, - rtp_header.packet_id, - rtp_header.max_packet_id, + now, kAudioPacketReceived, rtp_header.webrtc.header.timestamp, + rtp_header.frame_id, rtp_header.packet_id, rtp_header.max_packet_id, payload_size); // TODO(pwestin): update this as video to refresh over time. @@ -168,20 +178,16 @@ void AudioReceiver::IncomingParsedRtpPacket(const uint8* payload_data, payload_size); } audio_decoder_->IncomingParsedRtpPacket( - reinterpret_cast(plaintext.data()), - plaintext.size(), + reinterpret_cast(plaintext.data()), plaintext.size(), rtp_header); if (!queued_decoded_callbacks_.empty()) { DecodedAudioCallbackData decoded_data = queued_decoded_callbacks_.front(); queued_decoded_callbacks_.pop_front(); cast_environment_->PostTask( - CastEnvironment::AUDIO_DECODER, - FROM_HERE, + CastEnvironment::AUDIO_DECODER, FROM_HERE, base::Bind(&AudioReceiver::DecodeAudioFrameThread, - base::Unretained(this), - decoded_data.number_of_10ms_blocks, - decoded_data.desired_frequency, - decoded_data.callback)); + base::Unretained(this), decoded_data.number_of_10ms_blocks, + decoded_data.desired_frequency, decoded_data.callback)); } return; } @@ -190,52 +196,39 @@ void AudioReceiver::IncomingParsedRtpPacket(const uint8* payload_data, DCHECK(!audio_decoder_) << "Invalid internal state"; bool duplicate = false; - bool complete = audio_buffer_->InsertPacket( - payload_data, payload_size, rtp_header, &duplicate); + bool complete = audio_buffer_->InsertPacket(payload_data, payload_size, + rtp_header, &duplicate); if (duplicate) { cast_environment_->Logging()->InsertPacketEvent( - now, - kDuplicatePacketReceived, - rtp_header.webrtc.header.timestamp, - rtp_header.frame_id, - rtp_header.packet_id, - rtp_header.max_packet_id, + now, kDuplicatePacketReceived, rtp_header.webrtc.header.timestamp, + rtp_header.frame_id, rtp_header.packet_id, rtp_header.max_packet_id, payload_size); // Duplicate packets are ignored. return; } - if (!complete) - return; // Audio frame not complete; wait for more packets. - if (queued_encoded_callbacks_.empty()) - return; + if (!complete) return; // Audio frame not complete; wait for more packets. + if (queued_encoded_callbacks_.empty()) return; AudioFrameEncodedCallback callback = queued_encoded_callbacks_.front(); queued_encoded_callbacks_.pop_front(); - cast_environment_->PostTask(CastEnvironment::MAIN, - FROM_HERE, + cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, base::Bind(&AudioReceiver::GetEncodedAudioFrame, - weak_factory_.GetWeakPtr(), - callback)); + weak_factory_.GetWeakPtr(), callback)); } void AudioReceiver::GetRawAudioFrame( - int number_of_10ms_blocks, - int desired_frequency, + int number_of_10ms_blocks, int desired_frequency, const AudioFrameDecodedCallback& callback) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); DCHECK(audio_decoder_) << "Invalid function call in this configuration"; // TODO(pwestin): we can skip this function by posting direct to the decoder. - cast_environment_->PostTask(CastEnvironment::AUDIO_DECODER, - FROM_HERE, - base::Bind(&AudioReceiver::DecodeAudioFrameThread, - base::Unretained(this), - number_of_10ms_blocks, - desired_frequency, - callback)); + cast_environment_->PostTask( + CastEnvironment::AUDIO_DECODER, FROM_HERE, + base::Bind(&AudioReceiver::DecodeAudioFrameThread, base::Unretained(this), + number_of_10ms_blocks, desired_frequency, callback)); } void AudioReceiver::DecodeAudioFrameThread( - int number_of_10ms_blocks, - int desired_frequency, + int number_of_10ms_blocks, int desired_frequency, const AudioFrameDecodedCallback callback) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::AUDIO_DECODER)); // TODO(mikhal): Allow the application to allocate this memory. @@ -243,8 +236,7 @@ void AudioReceiver::DecodeAudioFrameThread( uint32 rtp_timestamp = 0; if (!audio_decoder_->GetRawAudioFrame(number_of_10ms_blocks, - desired_frequency, - audio_frame.get(), + desired_frequency, audio_frame.get(), &rtp_timestamp)) { DecodedAudioCallbackData callback_data; callback_data.number_of_10ms_blocks = number_of_10ms_blocks; @@ -255,18 +247,14 @@ void AudioReceiver::DecodeAudioFrameThread( } cast_environment_->PostTask( - CastEnvironment::MAIN, - FROM_HERE, + CastEnvironment::MAIN, FROM_HERE, base::Bind(&AudioReceiver::ReturnDecodedFrameWithPlayoutDelay, - base::Unretained(this), - base::Passed(&audio_frame), - rtp_timestamp, - callback)); + base::Unretained(this), base::Passed(&audio_frame), + rtp_timestamp, callback)); } void AudioReceiver::ReturnDecodedFrameWithPlayoutDelay( - scoped_ptr audio_frame, - uint32 rtp_timestamp, + scoped_ptr audio_frame, uint32 rtp_timestamp, const AudioFrameDecodedCallback callback) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); base::TimeTicks now = cast_environment_->Clock()->NowTicks(); @@ -275,16 +263,13 @@ void AudioReceiver::ReturnDecodedFrameWithPlayoutDelay( base::TimeTicks playout_time = GetPlayoutTime(now, rtp_timestamp); - cast_environment_->Logging()->InsertFrameEventWithDelay(now, - kAudioPlayoutDelay, - rtp_timestamp, - kFrameIdUnknown, - playout_time - now); + cast_environment_->Logging()->InsertFrameEventWithDelay( + now, kAudioPlayoutDelay, rtp_timestamp, kFrameIdUnknown, + playout_time - now); // Frame is ready - Send back to the caller. cast_environment_->PostTask( - CastEnvironment::MAIN, - FROM_HERE, + CastEnvironment::MAIN, FROM_HERE, base::Bind(callback, base::Passed(&audio_frame), playout_time)); } @@ -365,8 +350,7 @@ bool AudioReceiver::PostEncodedAudioFrame( if (!next_frame && (time_until_playout > min_wait_delta)) { base::TimeDelta time_until_release = time_until_playout - min_wait_delta; cast_environment_->PostDelayedTask( - CastEnvironment::MAIN, - FROM_HERE, + CastEnvironment::MAIN, FROM_HERE, base::Bind(&AudioReceiver::PlayoutTimeout, weak_factory_.GetWeakPtr()), time_until_release); VLOG(1) << "Wait until time to playout:" @@ -377,8 +361,7 @@ bool AudioReceiver::PostEncodedAudioFrame( audio_buffer_->ReleaseFrame((*encoded_frame)->frame_id); cast_environment_->PostTask( - CastEnvironment::MAIN, - FROM_HERE, + CastEnvironment::MAIN, FROM_HERE, base::Bind(callback, base::Passed(encoded_frame), playout_time)); return true; } @@ -395,33 +378,11 @@ void AudioReceiver::IncomingPacket(scoped_ptr packet) { void AudioReceiver::CastFeedback(const RtcpCastMessage& cast_message) { RtcpReceiverLogMessage receiver_log; - AudioRtcpRawMap audio_logs = - cast_environment_->Logging()->GetAndResetAudioRtcpRawData(); - - while (!audio_logs.empty()) { - AudioRtcpRawMap::iterator it = audio_logs.begin(); - uint32 rtp_timestamp = it->first; - std::pair - frame_range = audio_logs.equal_range(rtp_timestamp); - - RtcpReceiverFrameLogMessage frame_log(rtp_timestamp); - - AudioRtcpRawMap::const_iterator event_it = frame_range.first; - for (; event_it != frame_range.second; ++event_it) { - RtcpReceiverEventLogMessage event_log_message; - event_log_message.type = event_it->second.type; - event_log_message.event_timestamp = event_it->second.timestamp; - event_log_message.delay_delta = event_it->second.delay_delta; - event_log_message.packet_id = event_it->second.packet_id; - frame_log.event_log_messages_.push_back(event_log_message); - } - receiver_log.push_back(frame_log); - audio_logs.erase(rtp_timestamp); - } + event_subscriber_.GetReceiverLogMessageAndReset(&receiver_log); base::TimeTicks now = cast_environment_->Clock()->NowTicks(); - cast_environment_->Logging()->InsertGenericEvent( - now, kAudioAckSent, cast_message.ack_frame_id_); + cast_environment_->Logging()->InsertGenericEvent(now, kAudioAckSent, + cast_message.ack_frame_id_); rtcp_->SendRtcpFromRtpReceiver(&cast_message, &receiver_log); } @@ -454,8 +415,8 @@ base::TimeTicks AudioReceiver::GetPlayoutTime(base::TimeTicks now, } if (playout_time.is_null()) { // This can fail if we have not received any RTCP packets in a long time. - if (rtcp_->RtpTimestampInSenderTime( - frequency_, rtp_timestamp, &rtp_timestamp_in_ticks)) { + if (rtcp_->RtpTimestampInSenderTime(frequency_, rtp_timestamp, + &rtp_timestamp_in_ticks)) { playout_time = rtp_timestamp_in_ticks + time_offset_ + target_delay_delta_; } else { @@ -463,8 +424,7 @@ base::TimeTicks AudioReceiver::GetPlayoutTime(base::TimeTicks now, } } // Don't allow the playout time to go backwards. - if (last_playout_time_ > playout_time) - playout_time = last_playout_time_; + if (last_playout_time_ > playout_time) playout_time = last_playout_time_; last_playout_time_ = playout_time; return playout_time; } @@ -495,8 +455,7 @@ void AudioReceiver::ScheduleNextRtcpReport() { time_to_send, base::TimeDelta::FromMilliseconds(kMinSchedulingDelayMs)); cast_environment_->PostDelayedTask( - CastEnvironment::MAIN, - FROM_HERE, + CastEnvironment::MAIN, FROM_HERE, base::Bind(&AudioReceiver::SendNextRtcpReport, weak_factory_.GetWeakPtr()), time_to_send); @@ -526,8 +485,7 @@ void AudioReceiver::ScheduleNextCastMessage() { time_to_send = std::max( time_to_send, base::TimeDelta::FromMilliseconds(kMinSchedulingDelayMs)); cast_environment_->PostDelayedTask( - CastEnvironment::MAIN, - FROM_HERE, + CastEnvironment::MAIN, FROM_HERE, base::Bind(&AudioReceiver::SendNextCastMessage, weak_factory_.GetWeakPtr()), time_to_send); diff --git a/media/cast/audio_receiver/audio_receiver.h b/media/cast/audio_receiver/audio_receiver.h index 944387e..23c318f 100644 --- a/media/cast/audio_receiver/audio_receiver.h +++ b/media/cast/audio_receiver/audio_receiver.h @@ -7,6 +7,7 @@ #include "base/basictypes.h" #include "base/callback.h" +#include "base/macros.h" #include "base/memory/ref_counted.h" #include "base/memory/scoped_ptr.h" #include "base/memory/weak_ptr.h" @@ -16,6 +17,7 @@ #include "media/cast/cast_config.h" #include "media/cast/cast_environment.h" #include "media/cast/cast_receiver.h" +#include "media/cast/rtcp/receiver_rtcp_event_subscriber.h" #include "media/cast/rtcp/rtcp.h" // RtcpCastMessage #include "media/cast/rtp_receiver/rtp_receiver_defines.h" // RtpCastHeader #include "media/cast/transport/utility/transport_encryption_handler.h" @@ -51,8 +53,7 @@ class AudioReceiver : public base::NonThreadSafe, // Extract a raw audio frame from the cast receiver. // Actual decoding will be preformed on a designated audio_decoder thread. - void GetRawAudioFrame(int number_of_10ms_blocks, - int desired_frequency, + void GetRawAudioFrame(int number_of_10ms_blocks, int desired_frequency, const AudioFrameDecodedCallback& callback); // Extract an encoded audio frame from the cast receiver. @@ -62,8 +63,7 @@ class AudioReceiver : public base::NonThreadSafe, void IncomingPacket(scoped_ptr packet); protected: - void IncomingParsedRtpPacket(const uint8* payload_data, - size_t payload_size, + void IncomingParsedRtpPacket(const uint8* payload_data, size_t payload_size, const RtpCastHeader& rtp_header); private: @@ -82,12 +82,10 @@ class AudioReceiver : public base::NonThreadSafe, // Actual decoding implementation - should be called under the audio decoder // thread. - void DecodeAudioFrameThread(int number_of_10ms_blocks, - int desired_frequency, + void DecodeAudioFrameThread(int number_of_10ms_blocks, int desired_frequency, const AudioFrameDecodedCallback callback); void ReturnDecodedFrameWithPlayoutDelay( - scoped_ptr audio_frame, - uint32 rtp_timestamp, + scoped_ptr audio_frame, uint32 rtp_timestamp, const AudioFrameDecodedCallback callback); // Return the playout time based on the current time and rtp timestamp. @@ -112,6 +110,11 @@ class AudioReceiver : public base::NonThreadSafe, void SendNextCastMessage(); scoped_refptr cast_environment_; + + // Subscribes to raw events. + // Processes raw audio events to be sent over to the cast sender via RTCP. + ReceiverRtcpEventSubscriber event_subscriber_; + base::WeakPtrFactory weak_factory_; const transport::AudioCodec codec_; @@ -132,6 +135,8 @@ class AudioReceiver : public base::NonThreadSafe, std::list queued_encoded_callbacks_; std::list queued_decoded_callbacks_; + + DISALLOW_COPY_AND_ASSIGN(AudioReceiver); }; } // namespace cast diff --git a/media/cast/audio_receiver/audio_receiver_unittest.cc b/media/cast/audio_receiver/audio_receiver_unittest.cc index 9aaa9fd..4edd635 100644 --- a/media/cast/audio_receiver/audio_receiver_unittest.cc +++ b/media/cast/audio_receiver/audio_receiver_unittest.cc @@ -80,22 +80,22 @@ class AudioReceiverTest : public ::testing::Test { testing_clock_->Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); task_runner_ = new test::FakeSingleThreadTaskRunner(testing_clock_); - cast_environment_ = - new CastEnvironment(scoped_ptr(testing_clock_).Pass(), - task_runner_, - task_runner_, - task_runner_, - task_runner_, - task_runner_, - task_runner_, - GetDefaultCastReceiverLoggingConfig()); + + CastLoggingConfig logging_config(GetDefaultCastReceiverLoggingConfig()); + logging_config.enable_raw_data_collection = true; + + cast_environment_ = new CastEnvironment( + scoped_ptr(testing_clock_).Pass(), task_runner_, + task_runner_, task_runner_, task_runner_, task_runner_, task_runner_, + logging_config); + test_audio_encoder_callback_ = new TestAudioEncoderCallback(); } void Configure(bool use_external_decoder) { audio_config_.use_external_decoder = use_external_decoder; - receiver_.reset(new PeerAudioReceiver( - cast_environment_, audio_config_, &mock_transport_)); + receiver_.reset(new PeerAudioReceiver(cast_environment_, audio_config_, + &mock_transport_)); } virtual ~AudioReceiverTest() {} @@ -128,8 +128,8 @@ TEST_F(AudioReceiverTest, GetOnePacketEncodedframe) { Configure(true); EXPECT_CALL(mock_transport_, SendRtcpPacket(testing::_)).Times(1); - receiver_->IncomingParsedRtpPacket( - payload_.data(), payload_.size(), rtp_header_); + receiver_->IncomingParsedRtpPacket(payload_.data(), payload_.size(), + rtp_header_); transport::EncodedAudioFrame audio_frame; base::TimeTicks playout_time; test_audio_encoder_callback_->SetExpectedResult(0, @@ -155,8 +155,8 @@ TEST_F(AudioReceiverTest, MultiplePendingGetCalls) { receiver_->GetEncodedAudioFrame(frame_encoded_callback); - receiver_->IncomingParsedRtpPacket( - payload_.data(), payload_.size(), rtp_header_); + receiver_->IncomingParsedRtpPacket(payload_.data(), payload_.size(), + rtp_header_); transport::EncodedAudioFrame audio_frame; base::TimeTicks playout_time; @@ -171,9 +171,7 @@ TEST_F(AudioReceiverTest, MultiplePendingGetCalls) { uint32 ntp_high; uint32 ntp_low; ConvertTimeTicksToNtp(testing_clock_->NowTicks(), &ntp_high, &ntp_low); - rtcp_packet.AddSrWithNtp(audio_config_.feedback_ssrc, - ntp_high, - ntp_low, + rtcp_packet.AddSrWithNtp(audio_config_.feedback_ssrc, ntp_high, ntp_low, rtp_header_.webrtc.header.timestamp); testing_clock_->Advance(base::TimeDelta::FromMilliseconds(20)); @@ -190,8 +188,8 @@ TEST_F(AudioReceiverTest, MultiplePendingGetCalls) { test_audio_encoder_callback_->SetExpectedResult( 2, testing_clock_->NowTicks() + base::TimeDelta::FromMilliseconds(100)); - receiver_->IncomingParsedRtpPacket( - payload_.data(), payload_.size(), rtp_header_); + receiver_->IncomingParsedRtpPacket(payload_.data(), payload_.size(), + rtp_header_); receiver_->GetEncodedAudioFrame(frame_encoded_callback); task_runner_->RunTasks(); @@ -214,8 +212,8 @@ TEST_F(AudioReceiverTest, MultiplePendingGetCalls) { rtp_header_.is_reference = false; rtp_header_.reference_frame_id = 0; rtp_header_.webrtc.header.timestamp = 1280; - receiver_->IncomingParsedRtpPacket( - payload_.data(), payload_.size(), rtp_header_); + receiver_->IncomingParsedRtpPacket(payload_.data(), payload_.size(), + rtp_header_); receiver_->GetEncodedAudioFrame(frame_encoded_callback); task_runner_->RunTasks(); diff --git a/media/cast/cast.gyp b/media/cast/cast.gyp index feaa1a2..21e5e55 100644 --- a/media/cast/cast.gyp +++ b/media/cast/cast.gyp @@ -31,6 +31,9 @@ 'logging/logging_raw.h', 'logging/logging_stats.cc', 'logging/logging_stats.h', + 'logging/raw_event_subscriber.h', + 'logging/simple_event_subscriber.cc', + 'logging/simple_event_subscriber.h', ], # source }, ], # targets, @@ -66,7 +69,9 @@ 'framer/cast_message_builder_unittest.cc', 'framer/frame_buffer_unittest.cc', 'framer/framer_unittest.cc', - 'logging/logging_unittest.cc', + 'logging/logging_impl_unittest.cc', + 'logging/logging_raw_unittest.cc', + 'logging/simple_event_subscriber_unittest.cc', 'rtcp/mock_rtcp_receiver_feedback.cc', 'rtcp/mock_rtcp_receiver_feedback.h', 'rtcp/mock_rtcp_sender_feedback.cc', @@ -74,6 +79,8 @@ 'rtcp/rtcp_receiver_unittest.cc', 'rtcp/rtcp_sender_unittest.cc', 'rtcp/rtcp_unittest.cc', + 'rtcp/receiver_rtcp_event_subscriber_unittest.cc', + 'rtcp/sender_rtcp_event_subscriber_unittest.cc', 'rtp_receiver/rtp_receiver_defines.h', 'rtp_receiver/mock_rtp_payload_feedback.cc', 'rtp_receiver/mock_rtp_payload_feedback.h', diff --git a/media/cast/logging/logging_defines.cc b/media/cast/logging/logging_defines.cc index 0eb57bf..9febc3a 100644 --- a/media/cast/logging/logging_defines.cc +++ b/media/cast/logging/logging_defines.cc @@ -6,6 +6,10 @@ #include "base/logging.h" +#define ENUM_TO_STRING(enum) \ + case k##enum: \ + return #enum + namespace media { namespace cast { @@ -28,86 +32,66 @@ CastLoggingConfig GetDefaultCastReceiverLoggingConfig() { return config; } +CastLoggingConfig GetLoggingConfigWithRawEventsAndStatsEnabled() { + CastLoggingConfig config(true); + config.enable_raw_data_collection = true; + config.enable_stats_data_collection = true; + return config; +} + std::string CastLoggingToString(CastLoggingEvent event) { switch (event) { - case(kUnknown): - // Can happen if the sender and receiver of RTCP log messages are not - // aligned. - return "Unknown"; - case(kRttMs): - return "RttMs"; - case(kPacketLoss): - return "PacketLoss"; - case(kJitterMs): - return "JitterMs"; - case(kVideoAckReceived): - return "VideoAckReceived"; - case(kRembBitrate): - return "RembBitrate"; - case(kAudioAckSent): - return "AudioAckSent"; - case(kVideoAckSent): - return "VideoAckSent"; - case(kAudioFrameReceived): - return "AudioFrameReceived"; - case(kAudioFrameCaptured): - return "AudioFrameCaptured"; - case(kAudioFrameEncoded): - return "AudioFrameEncoded"; - case(kAudioPlayoutDelay): - return "AudioPlayoutDelay"; - case(kAudioFrameDecoded): - return "AudioFrameDecoded"; - case(kVideoFrameCaptured): - return "VideoFrameCaptured"; - case(kVideoFrameReceived): - return "VideoFrameReceived"; - case(kVideoFrameSentToEncoder): - return "VideoFrameSentToEncoder"; - case(kVideoFrameEncoded): - return "VideoFrameEncoded"; - case(kVideoFrameDecoded): - return "VideoFrameDecoded"; - case(kVideoRenderDelay): - return "VideoRenderDelay"; - case(kPacketSentToPacer): - return "PacketSentToPacer"; - case(kPacketSentToNetwork): - return "PacketSentToNetwork"; - case(kPacketRetransmitted): - return "PacketRetransmited"; - case(kAudioPacketReceived): - return "AudioPacketReceived"; - case(kVideoPacketReceived): - return "VideoPacketReceived"; - case(kDuplicatePacketReceived): - return "DuplicatePacketReceived"; - default: + // Can happen if the sender and receiver of RTCP log messages are not + // aligned. + ENUM_TO_STRING(Unknown); + ENUM_TO_STRING(RttMs); + ENUM_TO_STRING(PacketLoss); + ENUM_TO_STRING(JitterMs); + ENUM_TO_STRING(VideoAckReceived); + ENUM_TO_STRING(RembBitrate); + ENUM_TO_STRING(AudioAckSent); + ENUM_TO_STRING(VideoAckSent); + ENUM_TO_STRING(AudioFrameReceived); + ENUM_TO_STRING(AudioFrameCaptured); + ENUM_TO_STRING(AudioFrameEncoded); + ENUM_TO_STRING(AudioPlayoutDelay); + ENUM_TO_STRING(AudioFrameDecoded); + ENUM_TO_STRING(VideoFrameCaptured); + ENUM_TO_STRING(VideoFrameReceived); + ENUM_TO_STRING(VideoFrameSentToEncoder); + ENUM_TO_STRING(VideoFrameEncoded); + ENUM_TO_STRING(VideoFrameDecoded); + ENUM_TO_STRING(VideoRenderDelay); + ENUM_TO_STRING(PacketSentToPacer); + ENUM_TO_STRING(PacketSentToNetwork); + ENUM_TO_STRING(PacketRetransmitted); + ENUM_TO_STRING(AudioPacketReceived); + ENUM_TO_STRING(VideoPacketReceived); + ENUM_TO_STRING(DuplicatePacketReceived); + case kNumOfLoggingEvents: NOTREACHED(); return ""; } + NOTREACHED(); + return ""; } FrameEvent::FrameEvent() - : frame_id(0u), - size(0u) {} + : rtp_timestamp(0u), frame_id(kFrameIdUnknown), size(0u), type(kUnknown) {} FrameEvent::~FrameEvent() {} -BasePacketInfo::BasePacketInfo() - : size(0u) {} -BasePacketInfo::~BasePacketInfo() {} - PacketEvent::PacketEvent() - : frame_id(0u), - max_packet_id(0) {} + : rtp_timestamp(0), + frame_id(kFrameIdUnknown), + max_packet_id(0), + packet_id(0), + size(0), + type(kUnknown) {} PacketEvent::~PacketEvent() {} -GenericEvent::GenericEvent() {} +GenericEvent::GenericEvent() : type(kUnknown), value(0) {} GenericEvent::~GenericEvent() {} -ReceiverRtcpEvent::ReceiverRtcpEvent() {} -ReceiverRtcpEvent::~ReceiverRtcpEvent() {} - FrameLogStats::FrameLogStats() : event_counter(0), sum_size(0) {} @@ -116,7 +100,6 @@ FrameLogStats::~FrameLogStats() {} PacketLogStats::PacketLogStats() : event_counter(0), sum_size(0) {} - PacketLogStats::~PacketLogStats() {} GenericLogStats::GenericLogStats() @@ -125,7 +108,7 @@ GenericLogStats::GenericLogStats() sum_squared(0), min(0), max(0) {} - GenericLogStats::~GenericLogStats() {} } // namespace cast } // namespace media + diff --git a/media/cast/logging/logging_defines.h b/media/cast/logging/logging_defines.h index 057f869..cb7f2c7 100644 --- a/media/cast/logging/logging_defines.h +++ b/media/cast/logging/logging_defines.h @@ -17,9 +17,10 @@ namespace cast { static const uint32 kFrameIdUnknown = 0xFFFFFFFF; struct CastLoggingConfig { - CastLoggingConfig(bool sender); + explicit CastLoggingConfig(bool sender); ~CastLoggingConfig(); + // TODO(imcheng): get rid of this field. bool is_sender; bool enable_raw_data_collection; bool enable_stats_data_collection; @@ -30,6 +31,7 @@ struct CastLoggingConfig { // By default, enable raw and stats data collection. Disable tracing and UMA. CastLoggingConfig GetDefaultCastSenderLoggingConfig(); CastLoggingConfig GetDefaultCastReceiverLoggingConfig(); +CastLoggingConfig GetLoggingConfigWithRawEventsAndStatsEnabled(); enum CastLoggingEvent { // Generic events. @@ -39,6 +41,8 @@ enum CastLoggingEvent { kJitterMs, kVideoAckReceived, kRembBitrate, + // TODO(imcheng): k{Audio,Video}AckSent may need to be FrameEvents + // (crbug.com/339590) kAudioAckSent, kVideoAckSent, // Audio sender. @@ -64,50 +68,63 @@ enum CastLoggingEvent { kAudioPacketReceived, kVideoPacketReceived, kDuplicatePacketReceived, - kNumOfLoggingEvents, }; std::string CastLoggingToString(CastLoggingEvent event); +typedef uint32 RtpTimestamp; + struct FrameEvent { FrameEvent(); ~FrameEvent(); + RtpTimestamp rtp_timestamp; uint32 frame_id; - // Size is set only for kAudioFrameEncoded and kVideoFrameEncoded. - size_t size; - std::vector timestamp; - std::vector type; - // Delay is only set for kAudioPlayoutDelay and kVideoRenderDelay. - base::TimeDelta delay_delta; // Render/playout delay. -}; + size_t size; // Encoded size only. -// Internal map sorted by packet id. -struct BasePacketInfo { - BasePacketInfo(); - ~BasePacketInfo(); + // Time of event logged. + base::TimeTicks timestamp; + CastLoggingEvent type; - size_t size; - std::vector timestamp; - std::vector type; + // Render / playout delay. Only set for kAudioPlayoutDelay and + // kVideoRenderDelay events. + base::TimeDelta delay_delta; }; -typedef std::map BasePacketMap; - struct PacketEvent { PacketEvent(); ~PacketEvent(); + + RtpTimestamp rtp_timestamp; uint32 frame_id; - int max_packet_id; - BasePacketMap packet_map; + uint16 max_packet_id; + uint16 packet_id; + size_t size; + + // Time of event logged. + base::TimeTicks timestamp; + CastLoggingEvent type; }; struct GenericEvent { GenericEvent(); ~GenericEvent(); - std::vector value; - std::vector timestamp; + + CastLoggingEvent type; + + // Depending on |type|, |value| can have different meanings: + // kRttMs - RTT in milliseconds + // kPacketLoss - Fraction of packet loss, denominated in 256 + // kJitterMs - Jitter in milliseconds + // kVideoAckReceived - Frame ID + // kRembBitrate - Receiver Estimated Maximum Bitrate + // kAudioAckSent - Frame ID + // kVideoAckSent - Frame ID + int value; + + // Time of event logged. + base::TimeTicks timestamp; }; // Generic statistics given the raw data. More specific data (e.g. frame rate @@ -146,23 +163,6 @@ struct GenericLogStats { int max; }; -struct ReceiverRtcpEvent { - ReceiverRtcpEvent(); - ~ReceiverRtcpEvent(); - - CastLoggingEvent type; - base::TimeTicks timestamp; - base::TimeDelta delay_delta; // Render/playout delay. - uint16 packet_id; -}; - -// Store all log types in a map based on the event. -typedef std::map FrameRawMap; -typedef std::map PacketRawMap; -typedef std::map GenericRawMap; - -typedef std::multimap AudioRtcpRawMap; -typedef std::multimap VideoRtcpRawMap; typedef std::map FrameStatsMap; typedef std::map PacketStatsMap; diff --git a/media/cast/logging/logging_impl.cc b/media/cast/logging/logging_impl.cc index 8f339ce..948bc8c 100644 --- a/media/cast/logging/logging_impl.cc +++ b/media/cast/logging/logging_impl.cc @@ -15,14 +15,13 @@ LoggingImpl::LoggingImpl( const CastLoggingConfig& config) : main_thread_proxy_(main_thread_proxy), config_(config), - raw_(config.is_sender), + raw_(), stats_() {} LoggingImpl::~LoggingImpl() {} void LoggingImpl::InsertFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id) { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); if (config_.enable_raw_data_collection) { @@ -33,17 +32,15 @@ void LoggingImpl::InsertFrameEvent(const base::TimeTicks& time_of_event, } if (config_.enable_tracing) { std::string event_string = CastLoggingToString(event); - TRACE_EVENT_INSTANT2(event_string.c_str(), "FE", - TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, "frame_id", - frame_id); + TRACE_EVENT_INSTANT2(event_string.c_str(), "FE", TRACE_EVENT_SCOPE_THREAD, + "rtp_timestamp", rtp_timestamp, "frame_id", frame_id); } } void LoggingImpl::InsertFrameEventWithSize(const base::TimeTicks& time_of_event, CastLoggingEvent event, uint32 rtp_timestamp, - uint32 frame_id, - int frame_size) { + uint32 frame_id, int frame_size) { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); if (config_.enable_raw_data_collection) { raw_.InsertFrameEventWithSize(time_of_event, event, rtp_timestamp, frame_id, @@ -63,18 +60,15 @@ void LoggingImpl::InsertFrameEventWithSize(const base::TimeTicks& time_of_event, if (config_.enable_tracing) { std::string event_string = CastLoggingToString(event); - TRACE_EVENT_INSTANT2(event_string.c_str(), "FES", - TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, "frame_size", - frame_size); + TRACE_EVENT_INSTANT2(event_string.c_str(), "FES", TRACE_EVENT_SCOPE_THREAD, + "rtp_timestamp", rtp_timestamp, "frame_size", + frame_size); } } void LoggingImpl::InsertFrameEventWithDelay( - const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - base::TimeDelta delay) { + const base::TimeTicks& time_of_event, CastLoggingEvent event, + uint32 rtp_timestamp, uint32 frame_id, base::TimeDelta delay) { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); if (config_.enable_raw_data_collection) { raw_.InsertFrameEventWithDelay(time_of_event, event, rtp_timestamp, @@ -93,9 +87,9 @@ void LoggingImpl::InsertFrameEventWithDelay( } if (config_.enable_tracing) { std::string event_string = CastLoggingToString(event); - TRACE_EVENT_INSTANT2(event_string.c_str(), "FED", - TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, "delay", - delay.InMilliseconds()); + TRACE_EVENT_INSTANT2(event_string.c_str(), "FED", TRACE_EVENT_SCOPE_THREAD, + "rtp_timestamp", rtp_timestamp, "delay", + delay.InMilliseconds()); } } @@ -122,10 +116,8 @@ void LoggingImpl::InsertPacketListEvent(const base::TimeTicks& time_of_event, void LoggingImpl::InsertPacketEvent(const base::TimeTicks& time_of_event, CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - uint16 packet_id, - uint16 max_packet_id, + uint32 rtp_timestamp, uint32 frame_id, + uint16 packet_id, uint16 max_packet_id, size_t size) { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); if (config_.enable_raw_data_collection) { @@ -138,9 +130,9 @@ void LoggingImpl::InsertPacketEvent(const base::TimeTicks& time_of_event, } if (config_.enable_tracing) { std::string event_string = CastLoggingToString(event); - TRACE_EVENT_INSTANT2(event_string.c_str(), "PE", - TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, - "packet_id", packet_id); + TRACE_EVENT_INSTANT2(event_string.c_str(), "PE", TRACE_EVENT_SCOPE_THREAD, + "rtp_timestamp", rtp_timestamp, "packet_id", + packet_id); } } @@ -158,55 +150,17 @@ void LoggingImpl::InsertGenericEvent(const base::TimeTicks& time_of_event, } if (config_.enable_tracing) { std::string event_string = CastLoggingToString(event); - TRACE_EVENT_INSTANT1(event_string.c_str(), "GE", - TRACE_EVENT_SCOPE_THREAD, "value", value); + TRACE_EVENT_INSTANT1(event_string.c_str(), "GE", TRACE_EVENT_SCOPE_THREAD, + "value", value); } } -void LoggingImpl::InsertGenericUmaEvent(CastLoggingEvent event, int value) { - switch(event) { - case kRttMs: - UMA_HISTOGRAM_COUNTS("Cast.RttMs", value); - break; - case kPacketLoss: - UMA_HISTOGRAM_COUNTS("Cast.PacketLossFraction", value); - break; - case kJitterMs: - UMA_HISTOGRAM_COUNTS("Cast.JitterMs", value); - break; - case kRembBitrate: - UMA_HISTOGRAM_COUNTS("Cast.RembBitrate", value); - break; - default: - // No-op - break; - } -} - -// should just get the entire class, would be much easier. -FrameRawMap LoggingImpl::GetFrameRawData() const { - DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); - return raw_.GetFrameData(); -} - -PacketRawMap LoggingImpl::GetPacketRawData() const { - DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); - return raw_.GetPacketData(); -} - -GenericRawMap LoggingImpl::GetGenericRawData() const { - DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); - return raw_.GetGenericData(); +void LoggingImpl::AddRawEventSubscriber(RawEventSubscriber* subscriber) { + raw_.AddSubscriber(subscriber); } -AudioRtcpRawMap LoggingImpl::GetAndResetAudioRtcpRawData() { - DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); - return raw_.GetAndResetAudioRtcpData(); -} - -VideoRtcpRawMap LoggingImpl::GetAndResetVideoRtcpRawData() { - DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); - return raw_.GetAndResetVideoRtcpData(); +void LoggingImpl::RemoveRawEventSubscriber(RawEventSubscriber* subscriber) { + raw_.RemoveSubscriber(subscriber); } FrameStatsMap LoggingImpl::GetFrameStatsData() const { @@ -224,15 +178,30 @@ GenericStatsMap LoggingImpl::GetGenericStatsData() const { return stats_.GetGenericStatsData(); } -void LoggingImpl::ResetRaw() { - DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); - raw_.Reset(); -} - void LoggingImpl::ResetStats() { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); stats_.Reset(); } +void LoggingImpl::InsertGenericUmaEvent(CastLoggingEvent event, int value) { + switch (event) { + case kRttMs: + UMA_HISTOGRAM_COUNTS("Cast.RttMs", value); + break; + case kPacketLoss: + UMA_HISTOGRAM_COUNTS("Cast.PacketLossFraction", value); + break; + case kJitterMs: + UMA_HISTOGRAM_COUNTS("Cast.JitterMs", value); + break; + case kRembBitrate: + UMA_HISTOGRAM_COUNTS("Cast.RembBitrate", value); + break; + default: + // No-op + break; + } +} + } // namespace cast } // namespace media diff --git a/media/cast/logging/logging_impl.h b/media/cast/logging/logging_impl.h index 3105199..e79d341 100644 --- a/media/cast/logging/logging_impl.h +++ b/media/cast/logging/logging_impl.h @@ -29,54 +29,40 @@ class LoggingImpl : public base::NonThreadSafe { ~LoggingImpl(); void InsertFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id); void InsertFrameEventWithSize(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - int frame_size); + CastLoggingEvent event, uint32 rtp_timestamp, + uint32 frame_id, int frame_size); void InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - base::TimeDelta delay); + CastLoggingEvent event, uint32 rtp_timestamp, + uint32 frame_id, base::TimeDelta delay); void InsertPacketListEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - const PacketList& packets); + CastLoggingEvent event, const PacketList& packets); void InsertPacketEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - uint16 packet_id, - uint16 max_packet_id, - size_t size); + CastLoggingEvent event, uint32 rtp_timestamp, + uint32 frame_id, uint16 packet_id, + uint16 max_packet_id, size_t size); void InsertGenericEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - int value); + CastLoggingEvent event, int value); - // Get raw data. - FrameRawMap GetFrameRawData() const; - PacketRawMap GetPacketRawData() const; - GenericRawMap GetGenericRawData() const; - // Get the RTCP data and reset the data. - AudioRtcpRawMap GetAndResetAudioRtcpRawData(); - VideoRtcpRawMap GetAndResetVideoRtcpRawData(); + // Delegates to |LoggingRaw::AddRawEventSubscriber()|. + void AddRawEventSubscriber(RawEventSubscriber* subscriber); + + // Delegates to |LoggingRaw::RemoveRawEventSubscriber()|. + void RemoveRawEventSubscriber(RawEventSubscriber* subscriber); // Get stats only. FrameStatsMap GetFrameStatsData() const; PacketStatsMap GetPacketStatsData() const; GenericStatsMap GetGenericStatsData() const; - // Reset raw logging data (this does not reset the RTCP raw data). - void ResetRaw(); // Reset stats logging data. void ResetStats(); diff --git a/media/cast/logging/logging_impl_unittest.cc b/media/cast/logging/logging_impl_unittest.cc new file mode 100644 index 0000000..ac72dc4 --- /dev/null +++ b/media/cast/logging/logging_impl_unittest.cc @@ -0,0 +1,350 @@ +// 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 + +#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 "media/cast/test/fake_single_thread_task_runner.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 = GG_INT64_C(12345678900000); + +class LoggingImplTest : public ::testing::Test { + protected: + LoggingImplTest() : config_(false) { + // Enable all logging types. + config_.enable_raw_data_collection = true; + config_.enable_stats_data_collection = true; + config_.enable_uma_stats = true; + config_.enable_tracing = true; + + testing_clock_.Advance( + base::TimeDelta::FromMilliseconds(kStartMillisecond)); + task_runner_ = new test::FakeSingleThreadTaskRunner(&testing_clock_); + logging_.reset(new LoggingImpl(task_runner_, config_)); + event_subscriber_.reset(new SimpleEventSubscriber(task_runner_)); + logging_->AddRawEventSubscriber(event_subscriber_.get()); + } + + virtual ~LoggingImplTest() { + logging_->RemoveRawEventSubscriber(event_subscriber_.get()); + } + + CastLoggingConfig config_; + scoped_refptr task_runner_; + scoped_ptr logging_; + base::SimpleTestTickClock testing_clock_; + scoped_ptr 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, kAudioFrameCaptured, 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); + base::TimeTicks end_time = now; + + // Get logging data. + std::vector 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()); + // Verify stats. + FrameStatsMap frame_stats = logging_->GetFrameStatsData(); + // Size of stats equals the number of events. + EXPECT_EQ(1u, frame_stats.size()); + FrameStatsMap::const_iterator it = frame_stats.find(kAudioFrameCaptured); + EXPECT_TRUE(it != frame_stats.end()); + EXPECT_EQ(0, it->second.max_delay.InMilliseconds()); + EXPECT_EQ(0, it->second.min_delay.InMilliseconds()); + EXPECT_EQ(start_time, it->second.first_event_time); + EXPECT_EQ(end_time, it->second.last_event_time); + EXPECT_EQ(0u, it->second.sum_size); + // Number of events is equal to the number of frames. + EXPECT_EQ(static_cast(frame_id), it->second.event_counter); +} + +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; + do { + int size = kBaseFrameSizeBytes + + base::RandInt(-kRandomSizeInterval, kRandomSizeInterval); + sum_size += static_cast(size); + logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(), + kAudioFrameCaptured, rtp_timestamp, + frame_id, 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 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()); + // Verify stats. + FrameStatsMap frame_stats = logging_->GetFrameStatsData(); + // Size of stats equals the number of events. + EXPECT_EQ(1u, frame_stats.size()); + FrameStatsMap::const_iterator it = frame_stats.find(kAudioFrameCaptured); + EXPECT_TRUE(it != frame_stats.end()); + EXPECT_EQ(0, it->second.max_delay.InMilliseconds()); + EXPECT_EQ(0, it->second.min_delay.InMilliseconds()); + EXPECT_EQ(0, it->second.sum_delay.InMilliseconds()); + EXPECT_EQ(sum_size, it->second.sum_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(), kAudioFrameCaptured, 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 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()); + // Verify stats. + FrameStatsMap frame_stats = logging_->GetFrameStatsData(); + // Size of stats equals the number of events. + EXPECT_EQ(1u, frame_stats.size()); + FrameStatsMap::const_iterator it = frame_stats.find(kAudioFrameCaptured); + EXPECT_TRUE(it != frame_stats.end()); + EXPECT_GE(kPlayoutDelayMs + kRandomSizeInterval, + it->second.max_delay.InMilliseconds()); + EXPECT_LE(kPlayoutDelayMs - kRandomSizeInterval, + it->second.min_delay.InMilliseconds()); +} + +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(), kAudioFrameCaptured, + rtp_timestamp, frame_id); + ++num_events; + if (frame_id % 2) { + logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(), + kAudioFrameEncoded, rtp_timestamp, + frame_id, 1500); + } else if (frame_id % 3) { + logging_->InsertFrameEvent(testing_clock_.NowTicks(), kVideoFrameDecoded, + rtp_timestamp, frame_id); + } else { + logging_->InsertFrameEventWithDelay( + testing_clock_.NowTicks(), kVideoRenderDelay, 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 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::TimeDelta time_interval = testing_clock_.NowTicks() - start_time; + uint32 rtp_timestamp = 0; + uint32 frame_id = 0; + do { + for (int i = 0; i < kNumPacketsPerFrame; ++i) { + int size = kBaseSize + base::RandInt(-kSizeInterval, kSizeInterval); + logging_->InsertPacketEvent(testing_clock_.NowTicks(), kPacketSentToPacer, + 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 packet_events; + event_subscriber_->GetPacketEventsAndReset(&packet_events); + // Size of vector should be equal to the number of packets logged. + EXPECT_EQ(frame_id * kNumPacketsPerFrame, packet_events.size()); + // Verify stats. + PacketStatsMap stats_map = logging_->GetPacketStatsData(); + // Size of stats equals the number of events. + EXPECT_EQ(1u, stats_map.size()); + PacketStatsMap::const_iterator it = stats_map.find(kPacketSentToPacer); + EXPECT_TRUE(it != stats_map.end()); +} + +TEST_F(LoggingImplTest, GenericLogging) { + // Insert multiple generic types. + const size_t kNumRuns = 20;//1000; + const int kBaseValue = 20; + int sum_value_rtt = 0; + int sum_value_pl = 0; + int sum_value_jitter = 0; + uint64 sumsq_value_rtt = 0; + uint64 sumsq_value_pl = 0; + uint64 sumsq_value_jitter = 0; + int min_value, max_value; + + uint32 num_events = 0u; + uint32 expected_rtt_count = 0u; + uint32 expected_packet_loss_count = 0u; + uint32 expected_jitter_count = 0u; + for (size_t i = 0; i < kNumRuns; ++i) { + int value = kBaseValue + base::RandInt(-5, 5); + sum_value_rtt += value; + sumsq_value_rtt += value * value; + logging_->InsertGenericEvent(testing_clock_.NowTicks(), kRttMs, value); + ++num_events; + ++expected_rtt_count; + if (i % 2) { + logging_->InsertGenericEvent(testing_clock_.NowTicks(), kPacketLoss, + value); + ++num_events; + ++expected_packet_loss_count; + sum_value_pl += value; + sumsq_value_pl += value * value; + } + if (!(i % 4)) { + logging_->InsertGenericEvent(testing_clock_.NowTicks(), kJitterMs, value); + ++num_events; + ++expected_jitter_count; + sum_value_jitter += value; + sumsq_value_jitter += value * value; + } + if (i == 0) { + min_value = value; + max_value = value; + } else if (min_value > value) { + min_value = value; + } else if (max_value < value) { + max_value = value; + } + } + + // Size of generic event vector = number of generic events logged. + std::vector generic_events; + event_subscriber_->GetGenericEventsAndReset(&generic_events); + EXPECT_EQ(num_events, generic_events.size()); + + // Verify each type of event has expected number of events logged. + uint32 rtt_event_count = 0u; + uint32 packet_loss_event_count = 0u; + uint32 jitter_event_count = 0u; + for (std::vector::iterator it = generic_events.begin(); + it != generic_events.end(); ++it) { + if (it->type == kRttMs) { + ++rtt_event_count; + } else if (it->type == kPacketLoss) { + ++packet_loss_event_count; + } else if (it->type == kJitterMs) { + ++jitter_event_count; + } + } + + // Size of generic stats map = number of different events. + // Stats - one value per all events. + GenericStatsMap stats_map = logging_->GetGenericStatsData(); + EXPECT_EQ(3u, stats_map.size()); + GenericStatsMap::const_iterator sit = stats_map.find(kRttMs); + EXPECT_EQ(sum_value_rtt, sit->second.sum); + EXPECT_EQ(sumsq_value_rtt, sit->second.sum_squared); + EXPECT_LE(min_value, sit->second.min); + EXPECT_GE(max_value, sit->second.max); + sit = stats_map.find(kPacketLoss); + EXPECT_EQ(sum_value_pl, sit->second.sum); + EXPECT_EQ(sumsq_value_pl, sit->second.sum_squared); + EXPECT_LE(min_value, sit->second.min); + EXPECT_GE(max_value, sit->second.max); + sit = stats_map.find(kJitterMs); + EXPECT_EQ(sumsq_value_jitter, sit->second.sum_squared); + EXPECT_LE(min_value, sit->second.min); + EXPECT_GE(max_value, sit->second.max); +} + +TEST_F(LoggingImplTest, MultipleRawEventSubscribers) { + SimpleEventSubscriber event_subscriber_2(task_runner_); + + // Now logging_ has two subscribers. + logging_->AddRawEventSubscriber(&event_subscriber_2); + + logging_->InsertFrameEvent(testing_clock_.NowTicks(), kAudioFrameCaptured, + /*rtp_timestamp*/ 0u, + /*frame_id*/ 0u); + + std::vector 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 index 626b330..6d56bf5 100644 --- a/media/cast/logging/logging_raw.cc +++ b/media/cast/logging/logging_raw.cc @@ -11,34 +11,23 @@ namespace media { namespace cast { -LoggingRaw::LoggingRaw(bool is_sender) - : is_sender_(is_sender), - frame_map_(), - packet_map_(), - generic_map_(), - weak_factory_(this) {} +LoggingRaw::LoggingRaw() {} LoggingRaw::~LoggingRaw() {} void LoggingRaw::InsertFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id) { - InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp); - - InsertRtcpFrameEvent(time_of_event, event, rtp_timestamp, base::TimeDelta()); + InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp, + base::TimeDelta(), 0); } void LoggingRaw::InsertFrameEventWithSize(const base::TimeTicks& time_of_event, CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, + uint32 rtp_timestamp, uint32 frame_id, int size) { - InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp); - // Now insert size. - FrameRawMap::iterator it = frame_map_.find(rtp_timestamp); - DCHECK(it != frame_map_.end()); - it->second.size = size; + InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp, + base::TimeDelta(), size); } void LoggingRaw::InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, @@ -46,188 +35,76 @@ void LoggingRaw::InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, uint32 rtp_timestamp, uint32 frame_id, base::TimeDelta delay) { - InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp); - // Now insert delay. - FrameRawMap::iterator it = frame_map_.find(rtp_timestamp); - DCHECK(it != frame_map_.end()); - it->second.delay_delta = delay; - - InsertRtcpFrameEvent(time_of_event, event, rtp_timestamp, delay); + InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp, delay, + 0); } void LoggingRaw::InsertBaseFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 frame_id, - uint32 rtp_timestamp) { - // Is this a new event? - FrameRawMap::iterator it = frame_map_.find(rtp_timestamp); - if (it == frame_map_.end()) { - // Create a new map entry. - FrameEvent info; - info.frame_id = frame_id; - info.timestamp.push_back(time_of_event); - info.type.push_back(event); - frame_map_.insert(std::make_pair(rtp_timestamp, info)); - } else { - // Insert to an existing entry. - it->second.timestamp.push_back(time_of_event); - it->second.type.push_back(event); - // Do we have a valid frame_id? - // Not all events have a valid frame id. - if (it->second.frame_id == kFrameIdUnknown && frame_id != kFrameIdUnknown) - it->second.frame_id = frame_id; + CastLoggingEvent event, uint32 frame_id, + uint32 rtp_timestamp, + base::TimeDelta delay, int size) { + FrameEvent frame_event; + frame_event.rtp_timestamp = rtp_timestamp; + frame_event.frame_id = frame_id; + frame_event.size = size; + frame_event.timestamp = time_of_event; + frame_event.type = event; + frame_event.delay_delta = delay; + for (std::vector::const_iterator it = + subscribers_.begin(); + it != subscribers_.end(); ++it) { + (*it)->OnReceiveFrameEvent(frame_event); } } void LoggingRaw::InsertPacketEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - uint16 packet_id, - uint16 max_packet_id, - size_t size) { - // Is this packet belonging to a new frame? - PacketRawMap::iterator it = packet_map_.find(rtp_timestamp); - if (it == packet_map_.end()) { - // Create a new entry - start with base packet map. - PacketEvent info; - info.frame_id = frame_id; - info.max_packet_id = max_packet_id; - BasePacketInfo base_info; - base_info.size = size; - base_info.timestamp.push_back(time_of_event); - base_info.type.push_back(event); - info.packet_map.insert(std::make_pair(packet_id, base_info)); - packet_map_.insert(std::make_pair(rtp_timestamp, info)); - } else { - // Is this a new packet? - BasePacketMap::iterator packet_it = it->second.packet_map.find(packet_id); - if (packet_it == it->second.packet_map.end()) { - BasePacketInfo base_info; - base_info.size = size; - base_info.timestamp.push_back(time_of_event); - base_info.type.push_back(event); - it->second.packet_map.insert(std::make_pair(packet_id, base_info)); - } else { - packet_it->second.timestamp.push_back(time_of_event); - packet_it->second.type.push_back(event); - } - } - if (event == kAudioPacketReceived) { - ReceiverRtcpEvent rtcp_event; - rtcp_event.type = event; - rtcp_event.timestamp = time_of_event; - rtcp_event.packet_id = packet_id; - audio_rtcp_map_.insert(std::make_pair(rtp_timestamp, rtcp_event)); - } else if (event == kVideoPacketReceived) { - ReceiverRtcpEvent rtcp_event; - rtcp_event.type = event; - rtcp_event.timestamp = time_of_event; - rtcp_event.packet_id = packet_id; - video_rtcp_map_.insert(std::make_pair(rtp_timestamp, rtcp_event)); + CastLoggingEvent event, 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; + for (std::vector::const_iterator it = + subscribers_.begin(); + it != subscribers_.end(); ++it) { + (*it)->OnReceivePacketEvent(packet_event); } } void LoggingRaw::InsertGenericEvent(const base::TimeTicks& time_of_event, CastLoggingEvent event, int value) { - GenericEvent event_data; - event_data.value.push_back(value); - event_data.timestamp.push_back(time_of_event); - // Is this a new event? - GenericRawMap::iterator it = generic_map_.find(event); - if (it == generic_map_.end()) { - // Create new entry. - generic_map_.insert(std::make_pair(event, event_data)); - } else { - // Insert to existing entry. - it->second.value.push_back(value); - it->second.timestamp.push_back(time_of_event); - } -} - -void LoggingRaw::InsertRtcpFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - base::TimeDelta delay) { - ReceiverRtcpEvent rtcp_event; - if (is_sender_) { - if (event != kVideoFrameCaptured && - event != kVideoFrameSentToEncoder && - event != kVideoFrameEncoded) { - // Not interested in other events. - return; - } - VideoRtcpRawMap::iterator it = video_rtcp_map_.find(rtp_timestamp); - if (it == video_rtcp_map_.end()) { - // We have not stored this frame (RTP timestamp) in our map. - rtcp_event.type = event; - video_rtcp_map_.insert(std::make_pair(rtp_timestamp, rtcp_event)); - } else { - // We already have this frame (RTP timestamp) in our map. - // Only update events that are later in the chain. - // This is due to that events can be reordered on the wire. - if (event == kVideoFrameCaptured) { - return; // First event in chain can not be late by definition. - } - if (it->second.type == kVideoFrameEncoded) { - return; // Last event in chain should not be updated. - } - // Update existing entry. - it->second.type = event; - } - } else { - // We are a cast receiver. - switch (event) { - case kAudioPlayoutDelay: - rtcp_event.delay_delta = delay; - case kAudioFrameDecoded: - case kAudioAckSent: - rtcp_event.type = event; - rtcp_event.timestamp = time_of_event; - audio_rtcp_map_.insert(std::make_pair(rtp_timestamp, rtcp_event)); - break; - case kVideoRenderDelay: - rtcp_event.delay_delta = delay; - case kVideoFrameDecoded: - case kVideoAckSent: - rtcp_event.type = event; - rtcp_event.timestamp = time_of_event; - video_rtcp_map_.insert(std::make_pair(rtp_timestamp, rtcp_event)); - break; - default: - break; - } + GenericEvent generic_event; + generic_event.type = event; + generic_event.value = value; + generic_event.timestamp = time_of_event; + for (std::vector::const_iterator it = + subscribers_.begin(); + it != subscribers_.end(); ++it) { + (*it)->OnReceiveGenericEvent(generic_event); } } -FrameRawMap LoggingRaw::GetFrameData() const { - return frame_map_; -} - -PacketRawMap LoggingRaw::GetPacketData() const { - return packet_map_; -} +void LoggingRaw::AddSubscriber(RawEventSubscriber* subscriber) { + DCHECK(subscriber); + DCHECK(std::find(subscribers_.begin(), subscribers_.end(), subscriber) == + subscribers_.end()); -GenericRawMap LoggingRaw::GetGenericData() const { - return generic_map_; + subscribers_.push_back(subscriber); } -AudioRtcpRawMap LoggingRaw::GetAndResetAudioRtcpData() { - AudioRtcpRawMap return_map; - audio_rtcp_map_.swap(return_map); - return return_map; -} - -VideoRtcpRawMap LoggingRaw::GetAndResetVideoRtcpData() { - VideoRtcpRawMap return_map; - video_rtcp_map_.swap(return_map); - return return_map; -} +void LoggingRaw::RemoveSubscriber(RawEventSubscriber* subscriber) { + DCHECK(subscriber); + DCHECK(std::find(subscribers_.begin(), subscribers_.end(), subscriber) != + subscribers_.end()); -void LoggingRaw::Reset() { - frame_map_.clear(); - packet_map_.clear(); - generic_map_.clear(); + subscribers_.erase( + std::remove(subscribers_.begin(), subscribers_.end(), subscriber), + subscribers_.end()); } } // namespace cast diff --git a/media/cast/logging/logging_raw.h b/media/cast/logging/logging_raw.h index 504a60c..29f203b 100644 --- a/media/cast/logging/logging_raw.h +++ b/media/cast/logging/logging_raw.h @@ -5,92 +5,75 @@ #ifndef MEDIA_CAST_LOGGING_LOGGING_RAW_H_ #define MEDIA_CAST_LOGGING_LOGGING_RAW_H_ -#include -#include #include #include "base/basictypes.h" #include "base/memory/linked_ptr.h" -#include "base/memory/weak_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 base::SupportsWeakPtr { +class LoggingRaw : public base::NonThreadSafe { public: - explicit LoggingRaw(bool is_sender); + LoggingRaw(); ~LoggingRaw(); // Inform of new event: three types of events: frame, packets and generic. // Frame events can be inserted with different parameters. void InsertFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id); // Size - Inserting the size implies that this is an encoded frame. + // This function is only applicable for the following frame events: + // kAudioFrameEncoded, kVideoFrameEncoded void InsertFrameEventWithSize(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - int frame_size); + CastLoggingEvent event, uint32 rtp_timestamp, + uint32 frame_id, int size); // Render/playout delay + // This function is only applicable for the following frame events: + // kAudioPlayoutDelay, kVideoRenderDelay void InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - base::TimeDelta delay); + CastLoggingEvent event, uint32 rtp_timestamp, + uint32 frame_id, base::TimeDelta delay); // Insert a packet event. void InsertPacketEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - uint16 packet_id, - uint16 max_packet_id, - size_t size); + CastLoggingEvent event, uint32 rtp_timestamp, + uint32 frame_id, uint16 packet_id, + uint16 max_packet_id, size_t size); + // Insert a generic event. The interpretation of |value| depends on + // type of |event|. void InsertGenericEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - int value); + CastLoggingEvent event, int value); - // Get raw log data. - FrameRawMap GetFrameData() const; - PacketRawMap GetPacketData() const; - GenericRawMap GetGenericData() const; + // 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); - AudioRtcpRawMap GetAndResetAudioRtcpData(); - VideoRtcpRawMap GetAndResetVideoRtcpData(); - - // Reset all log data; except the Rtcp copies. - void Reset(); + // 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, - uint32 frame_id, - uint32 rtp_timestamp); - - void InsertRtcpFrameEvent(const base::TimeTicks& time_of_event, - CastLoggingEvent event, - uint32 rtp_timestamp, - base::TimeDelta delay); + CastLoggingEvent event, uint32 frame_id, + uint32 rtp_timestamp, base::TimeDelta delay, + int size); - const bool is_sender_; - FrameRawMap frame_map_; - PacketRawMap packet_map_; - GenericRawMap generic_map_; - AudioRtcpRawMap audio_rtcp_map_; - VideoRtcpRawMap video_rtcp_map_; - - base::WeakPtrFactory weak_factory_; + // List of subscriber pointers. This class does not own the subscribers. + std::vector subscribers_; DISALLOW_COPY_AND_ASSIGN(LoggingRaw); }; @@ -99,4 +82,3 @@ class LoggingRaw : public base::NonThreadSafe, } // 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..4446070 --- /dev/null +++ b/media/cast/logging/logging_raw_unittest.cc @@ -0,0 +1,221 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "base/memory/scoped_ptr.h" +#include "base/test/simple_test_tick_clock.h" +#include "media/cast/logging/logging_defines.h" +#include "media/cast/logging/logging_raw.h" +#include "media/cast/logging/simple_event_subscriber.h" +#include "media/cast/test/fake_single_thread_task_runner.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace media { +namespace cast { + +class LoggingRawTest : public ::testing::Test { + protected: + LoggingRawTest() + : task_runner_(new test::FakeSingleThreadTaskRunner(&testing_clock_)), + event_subscriber_(task_runner_) { + raw_.AddSubscriber(&event_subscriber_); + } + + virtual ~LoggingRawTest() { raw_.RemoveSubscriber(&event_subscriber_); } + + LoggingRaw raw_; + base::SimpleTestTickClock testing_clock_; + scoped_refptr task_runner_; + SimpleEventSubscriber event_subscriber_; + std::vector frame_events_; + std::vector packet_events_; + std::vector generic_events_; +}; + +TEST_F(LoggingRawTest, FrameEvent) { + CastLoggingEvent event_type = kVideoFrameDecoded; + uint32 frame_id = 456u; + RtpTimestamp rtp_timestamp = 123u; + base::TimeTicks timestamp = base::TimeTicks(); + raw_.InsertFrameEvent(timestamp, event_type, rtp_timestamp, frame_id); + + event_subscriber_.GetPacketEventsAndReset(&packet_events_); + EXPECT_TRUE(packet_events_.empty()); + + event_subscriber_.GetGenericEventsAndReset(&generic_events_); + EXPECT_TRUE(generic_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(base::TimeDelta(), frame_events_[0].delay_delta); +} + +TEST_F(LoggingRawTest, FrameEventWithSize) { + CastLoggingEvent event_type = kVideoFrameEncoded; + uint32 frame_id = 456u; + RtpTimestamp rtp_timestamp = 123u; + base::TimeTicks timestamp = base::TimeTicks(); + int size = 1024; + raw_.InsertFrameEventWithSize(timestamp, event_type, rtp_timestamp, frame_id, + size); + + event_subscriber_.GetPacketEventsAndReset(&packet_events_); + EXPECT_TRUE(packet_events_.empty()); + + event_subscriber_.GetGenericEventsAndReset(&generic_events_); + EXPECT_TRUE(generic_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(frame_events_[0].size)); + EXPECT_EQ(timestamp, frame_events_[0].timestamp); + EXPECT_EQ(event_type, frame_events_[0].type); + EXPECT_EQ(base::TimeDelta(), frame_events_[0].delay_delta); +} + +TEST_F(LoggingRawTest, FrameEventWithDelay) { + CastLoggingEvent event_type = kVideoRenderDelay; + 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, rtp_timestamp, frame_id, + delay); + + event_subscriber_.GetPacketEventsAndReset(&packet_events_); + EXPECT_TRUE(packet_events_.empty()); + + event_subscriber_.GetGenericEventsAndReset(&generic_events_); + EXPECT_TRUE(generic_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(delay, frame_events_[0].delay_delta); +} + +TEST_F(LoggingRawTest, PacketEvent) { + CastLoggingEvent event_type = kVideoPacketReceived; + 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, rtp_timestamp, frame_id, + packet_id, max_packet_id, size); + + event_subscriber_.GetFrameEventsAndReset(&frame_events_); + EXPECT_TRUE(frame_events_.empty()); + + event_subscriber_.GetGenericEventsAndReset(&generic_events_); + EXPECT_TRUE(generic_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); +} + +TEST_F(LoggingRawTest, GenericEvent) { + CastLoggingEvent event_type = kRttMs; + base::TimeTicks timestamp = base::TimeTicks(); + int value = 100; + raw_.InsertGenericEvent(timestamp, event_type, value); + + event_subscriber_.GetFrameEventsAndReset(&frame_events_); + EXPECT_TRUE(frame_events_.empty()); + + event_subscriber_.GetPacketEventsAndReset(&packet_events_); + EXPECT_TRUE(packet_events_.empty()); + + event_subscriber_.GetGenericEventsAndReset(&generic_events_); + ASSERT_EQ(1u, generic_events_.size()); + EXPECT_EQ(event_type, generic_events_[0].type); + EXPECT_EQ(value, generic_events_[0].value); + EXPECT_EQ(timestamp, generic_events_[0].timestamp); +} + +TEST_F(LoggingRawTest, MultipleSubscribers) { + SimpleEventSubscriber event_subscriber_2(task_runner_); + + // Now raw_ has two subscribers. + raw_.AddSubscriber(&event_subscriber_2); + + CastLoggingEvent event_type = kVideoFrameDecoded; + uint32 frame_id = 456u; + RtpTimestamp rtp_timestamp = 123u; + base::TimeTicks timestamp = base::TimeTicks(); + raw_.InsertFrameEvent(timestamp, event_type, rtp_timestamp, frame_id); + + event_subscriber_.GetPacketEventsAndReset(&packet_events_); + EXPECT_TRUE(packet_events_.empty()); + + event_subscriber_.GetGenericEventsAndReset(&generic_events_); + EXPECT_TRUE(generic_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(base::TimeDelta(), frame_events_[0].delay_delta); + + event_subscriber_2.GetPacketEventsAndReset(&packet_events_); + EXPECT_TRUE(packet_events_.empty()); + + event_subscriber_2.GetGenericEventsAndReset(&generic_events_); + EXPECT_TRUE(generic_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(base::TimeDelta(), frame_events_[0].delay_delta); + + // Remove event_subscriber_2, so it shouldn't receive events after this. + raw_.RemoveSubscriber(&event_subscriber_2); + + event_type = kAudioFrameDecoded; + frame_id = 789; + rtp_timestamp = 456; + timestamp = base::TimeTicks(); + raw_.InsertFrameEvent(timestamp, event_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(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/logging_unittest.cc b/media/cast/logging/logging_unittest.cc deleted file mode 100644 index 256eaf1..0000000 --- a/media/cast/logging/logging_unittest.cc +++ /dev/null @@ -1,329 +0,0 @@ -// Copyright 2013 The Chromium Authors. All rights reserved. -// Use of this source code is governed by a BSD-style license that can be -// found in the LICENSE file. - -#include - -#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_impl.h" -#include "media/cast/test/fake_single_thread_task_runner.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 = GG_INT64_C(12345678900000); - -class TestLogging : public ::testing::Test { - protected: - TestLogging() : config_(false) { - // Enable all logging types. - config_.enable_raw_data_collection = true; - config_.enable_stats_data_collection = true; - config_.enable_uma_stats = true; - config_.enable_tracing = true; - - testing_clock_.Advance( - base::TimeDelta::FromMilliseconds(kStartMillisecond)); - task_runner_ = new test::FakeSingleThreadTaskRunner(&testing_clock_); - logging_.reset(new LoggingImpl(task_runner_, config_)); - } - - virtual ~TestLogging() {} - - CastLoggingConfig config_; - scoped_refptr task_runner_; - scoped_ptr logging_; - base::SimpleTestTickClock testing_clock_; - - DISALLOW_COPY_AND_ASSIGN(TestLogging); -}; - -TEST_F(TestLogging, 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, kAudioFrameCaptured, 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); - base::TimeTicks end_time = now; - // Get logging data. - FrameRawMap frame_map = logging_->GetFrameRawData(); - // Size of map should be equal to the number of frames logged. - EXPECT_EQ(frame_id, frame_map.size()); - // Verify stats. - FrameStatsMap frame_stats = logging_->GetFrameStatsData(); - // Size of stats equals the number of events. - EXPECT_EQ(1u, frame_stats.size()); - FrameStatsMap::const_iterator it = frame_stats.find(kAudioFrameCaptured); - EXPECT_TRUE(it != frame_stats.end()); - EXPECT_EQ(0, it->second.max_delay.InMilliseconds()); - EXPECT_EQ(0, it->second.min_delay.InMilliseconds()); - EXPECT_EQ(start_time, it->second.first_event_time); - EXPECT_EQ(end_time, it->second.last_event_time); - EXPECT_EQ(0u, it->second.sum_size); - // Number of events is equal to the number of frames. - EXPECT_EQ(static_cast(frame_id), it->second.event_counter); -} - -TEST_F(TestLogging, 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; - do { - int size = kBaseFrameSizeBytes + - base::RandInt(-kRandomSizeInterval, kRandomSizeInterval); - sum_size += static_cast(size); - logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(), - kAudioFrameCaptured, rtp_timestamp, frame_id, 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. - FrameRawMap frame_map = logging_->GetFrameRawData(); - // Size of map should be equal to the number of frames logged. - EXPECT_EQ(frame_id, frame_map.size()); - // Verify stats. - FrameStatsMap frame_stats = logging_->GetFrameStatsData(); - // Size of stats equals the number of events. - EXPECT_EQ(1u, frame_stats.size()); - FrameStatsMap::const_iterator it = frame_stats.find(kAudioFrameCaptured); - EXPECT_TRUE(it != frame_stats.end()); - EXPECT_EQ(0, it->second.max_delay.InMilliseconds()); - EXPECT_EQ(0, it->second.min_delay.InMilliseconds()); - EXPECT_EQ(0, it->second.sum_delay.InMilliseconds()); - EXPECT_EQ(sum_size, it->second.sum_size); -} - -TEST_F(TestLogging, 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(), - kAudioFrameCaptured, 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. - FrameRawMap frame_map = logging_->GetFrameRawData(); - // Size of map should be equal to the number of frames logged. - EXPECT_EQ(frame_id, frame_map.size()); - // Verify stats. - FrameStatsMap frame_stats = logging_->GetFrameStatsData(); - // Size of stats equals the number of events. - EXPECT_EQ(1u, frame_stats.size()); - FrameStatsMap::const_iterator it = frame_stats.find(kAudioFrameCaptured); - EXPECT_TRUE(it != frame_stats.end()); - EXPECT_GE(kPlayoutDelayMs + kRandomSizeInterval, - it->second.max_delay.InMilliseconds()); - EXPECT_LE(kPlayoutDelayMs - kRandomSizeInterval, - it->second.min_delay.InMilliseconds()); -} - -TEST_F(TestLogging, MultipleEventFrameLogging) { - 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 { - logging_->InsertFrameEvent(testing_clock_.NowTicks(), kAudioFrameCaptured, - rtp_timestamp, frame_id); - if (frame_id % 2) { - logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(), - kAudioFrameEncoded, rtp_timestamp, frame_id, 1500); - } else if (frame_id % 3) { - logging_->InsertFrameEvent(testing_clock_.NowTicks(), kVideoFrameDecoded, - rtp_timestamp, frame_id); - } else { - logging_->InsertFrameEventWithDelay(testing_clock_.NowTicks(), - kVideoRenderDelay, rtp_timestamp, frame_id, - base::TimeDelta::FromMilliseconds(20)); - } - 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. - FrameRawMap frame_map = logging_->GetFrameRawData(); - // Size of map should be equal to the number of frames logged. - EXPECT_EQ(frame_id, frame_map.size()); - // Multiple events captured per frame. -} - -TEST_F(TestLogging, PacketLogging) { - const int kNumPacketsPerFrame = 10; - const int kBaseSize = 2500; - const int kSizeInterval = 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; - do { - for (int i = 0; i < kNumPacketsPerFrame; ++i) { - int size = kBaseSize + base::RandInt(-kSizeInterval, kSizeInterval); - logging_->InsertPacketEvent(testing_clock_.NowTicks(), kPacketSentToPacer, - 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. - PacketRawMap raw_map = logging_->GetPacketRawData(); - // Size of map should be equal to the number of frames logged. - EXPECT_EQ(frame_id, raw_map.size()); - // Verify stats. - PacketStatsMap stats_map = logging_->GetPacketStatsData(); - // Size of stats equals the number of events. - EXPECT_EQ(1u, stats_map.size()); - PacketStatsMap::const_iterator it = stats_map.find(kPacketSentToPacer); - EXPECT_TRUE(it != stats_map.end()); -} - -TEST_F(TestLogging, GenericLogging) { - // Insert multiple generic types. - const size_t kNumRuns = 20;//1000; - const int kBaseValue = 20; - int sum_value_rtt = 0; - int sum_value_pl = 0; - int sum_value_jitter = 0; - uint64 sumsq_value_rtt = 0; - uint64 sumsq_value_pl = 0; - uint64 sumsq_value_jitter = 0; - int min_value, max_value; - for (size_t i = 0; i < kNumRuns; ++i) { - int value = kBaseValue + base::RandInt(-5, 5); - sum_value_rtt += value; - sumsq_value_rtt += value * value; - logging_->InsertGenericEvent(testing_clock_.NowTicks(), kRttMs, value); - if (i % 2) { - logging_->InsertGenericEvent(testing_clock_.NowTicks(), kPacketLoss, - value); - sum_value_pl += value; - sumsq_value_pl += value * value; - } - if (!(i % 4)) { - logging_->InsertGenericEvent(testing_clock_.NowTicks(), kJitterMs, value); - sum_value_jitter += value; - sumsq_value_jitter += value * value; - } - if (i == 0) { - min_value = value; - max_value = value; - } else if (min_value > value) { - min_value = value; - } else if (max_value < value) { - max_value = value; - } - } - GenericRawMap raw_map = logging_->GetGenericRawData(); - GenericStatsMap stats_map = logging_->GetGenericStatsData(); - // Size of generic map = number of different events. - EXPECT_EQ(3u, raw_map.size()); - EXPECT_EQ(3u, stats_map.size()); - // Raw events - size of internal map = number of calls. - GenericRawMap::iterator rit = raw_map.find(kRttMs); - EXPECT_EQ(kNumRuns, rit->second.value.size()); - EXPECT_EQ(kNumRuns, rit->second.timestamp.size()); - rit = raw_map.find(kPacketLoss); - EXPECT_EQ(kNumRuns / 2, rit->second.value.size()); - EXPECT_EQ(kNumRuns / 2, rit->second.timestamp.size()); - rit = raw_map.find(kJitterMs); - EXPECT_EQ(kNumRuns / 4, rit->second.value.size()); - EXPECT_EQ(kNumRuns / 4, rit->second.timestamp.size()); - // Stats - one value per all events. - GenericStatsMap::const_iterator sit = stats_map.find(kRttMs); - EXPECT_EQ(sum_value_rtt, sit->second.sum); - EXPECT_EQ(sumsq_value_rtt, sit->second.sum_squared); - EXPECT_LE(min_value, sit->second.min); - EXPECT_GE(max_value, sit->second.max); - sit = stats_map.find(kPacketLoss); - EXPECT_EQ(sum_value_pl, sit->second.sum); - EXPECT_EQ(sumsq_value_pl, sit->second.sum_squared); - EXPECT_LE(min_value, sit->second.min); - EXPECT_GE(max_value, sit->second.max); - sit = stats_map.find(kJitterMs); - EXPECT_EQ(sumsq_value_jitter, sit->second.sum_squared); - EXPECT_LE(min_value, sit->second.min); - EXPECT_GE(max_value, sit->second.max); -} - -TEST_F(TestLogging, RtcpMultipleEventFrameLogging) { - 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 { - logging_->InsertFrameEvent(testing_clock_.NowTicks(), kAudioFrameCaptured, - rtp_timestamp, frame_id); - if (frame_id % 2) { - logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(), - kAudioFrameEncoded, rtp_timestamp, frame_id, 1500); - } else if (frame_id % 3) { - logging_->InsertFrameEvent(testing_clock_.NowTicks(), kVideoFrameDecoded, - rtp_timestamp, frame_id); - } else { - logging_->InsertFrameEventWithDelay(testing_clock_.NowTicks(), - kVideoRenderDelay, rtp_timestamp, frame_id, - base::TimeDelta::FromMilliseconds(20)); - } - 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. - FrameRawMap frame_map = logging_->GetFrameRawData(); - // Size of map should be equal to the number of frames logged. - EXPECT_EQ(frame_id, frame_map.size()); - // Multiple events captured per frame. - - AudioRtcpRawMap audio_rtcp = logging_->GetAndResetAudioRtcpRawData(); - EXPECT_EQ(0u, audio_rtcp.size()); - - VideoRtcpRawMap video_rtcp = logging_->GetAndResetVideoRtcpRawData(); - EXPECT_EQ((frame_id + 1) / 2, video_rtcp.size()); -} - -} // namespace cast -} // namespace media diff --git a/media/cast/logging/raw_event_subscriber.h b/media/cast/logging/raw_event_subscriber.h new file mode 100644 index 0000000..8822364 --- /dev/null +++ b/media/cast/logging/raw_event_subscriber.h @@ -0,0 +1,36 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#ifndef MEDIA_CAST_LOGGING_RAW_EVENT_SUBSCRIBER_H_ +#define MEDIA_CAST_LOGGING_RAW_EVENT_SUBSCRIBER_H_ + +#include "media/cast/logging/logging_defines.h" + +namespace media { +namespace cast { + +// A subscriber interface to subscribe to cast raw event logs. +// Those who wish to subscribe to raw event logs must implement this interface, +// and call LoggingImpl::AddRawEventSubscriber() with the subscriber, in order +// to start receiving raw event logs. +class RawEventSubscriber { + public: + virtual ~RawEventSubscriber() {} + + // Called on main thread when a FrameEvent, given by |frame_event|, is logged. + virtual void OnReceiveFrameEvent(const FrameEvent& frame_event) = 0; + + // Called on main thread when a PacketEvent, given by |packet_event|, + // is logged. + virtual void OnReceivePacketEvent(const PacketEvent& packet_event) = 0; + + // Called on main thread when a GenericEvent, given by |generic_event|, + // is logged. + virtual void OnReceiveGenericEvent(const GenericEvent& generic_event) = 0; +}; + +} // namespace cast +} // namespace media + +#endif // MEDIA_CAST_LOGGING_RAW_EVENT_SUBSCRIBER_H_ diff --git a/media/cast/logging/simple_event_subscriber.cc b/media/cast/logging/simple_event_subscriber.cc new file mode 100644 index 0000000..f0b2250 --- /dev/null +++ b/media/cast/logging/simple_event_subscriber.cc @@ -0,0 +1,62 @@ +// 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/simple_event_subscriber.h" + +#include + +#include "base/logging.h" +#include "base/single_thread_task_runner.h" + +namespace media { +namespace cast { + +SimpleEventSubscriber::SimpleEventSubscriber( + const scoped_refptr& main_thread_proxy) { + DCHECK(main_thread_proxy->RunsTasksOnCurrentThread()); +} + +SimpleEventSubscriber::~SimpleEventSubscriber() { + thread_checker_.CalledOnValidThread(); +} + +void SimpleEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) { + thread_checker_.CalledOnValidThread(); + frame_events_.push_back(frame_event); +} + +void SimpleEventSubscriber::OnReceivePacketEvent( + const PacketEvent& packet_event) { + thread_checker_.CalledOnValidThread(); + packet_events_.push_back(packet_event); +} + +void SimpleEventSubscriber::OnReceiveGenericEvent( + const GenericEvent& generic_event) { + generic_events_.push_back(generic_event); +} + +void SimpleEventSubscriber::GetFrameEventsAndReset( + std::vector* frame_events) { + thread_checker_.CalledOnValidThread(); + frame_events->swap(frame_events_); + frame_events_.clear(); +} + +void SimpleEventSubscriber::GetPacketEventsAndReset( + std::vector* packet_events) { + thread_checker_.CalledOnValidThread(); + packet_events->swap(packet_events_); + packet_events_.clear(); +} + +void SimpleEventSubscriber::GetGenericEventsAndReset( + std::vector* generic_events) { + thread_checker_.CalledOnValidThread(); + generic_events->swap(generic_events_); + generic_events_.clear(); +} + +} // namespace cast +} // namespace media diff --git a/media/cast/logging/simple_event_subscriber.h b/media/cast/logging/simple_event_subscriber.h new file mode 100644 index 0000000..b8f0b49 --- /dev/null +++ b/media/cast/logging/simple_event_subscriber.h @@ -0,0 +1,64 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#ifndef MEDIA_CAST_LOGGING_SIMPLE_EVENT_SUBSCRIBER_H_ +#define MEDIA_CAST_LOGGING_SIMPLE_EVENT_SUBSCRIBER_H_ + +#include + +#include "base/memory/ref_counted.h" +#include "base/single_thread_task_runner.h" +#include "base/threading/thread_checker.h" +#include "media/cast/logging/raw_event_subscriber.h" + +namespace media { +namespace cast { + +// RawEventSubscriber implementation that records all incoming raw events +// in std::vector's. +// The user of this class can call the GetXXXEventsAndReset functions to get +// list of events that have acccumulated since last inovcation. +class SimpleEventSubscriber : public RawEventSubscriber { + public: + // |main_thread_proxy|: Only used for ensuring the subscriber is only called + // on the main thread. This object does not keep a reference on it. + explicit SimpleEventSubscriber( + const scoped_refptr& main_thread_proxy); + + virtual ~SimpleEventSubscriber(); + + virtual void OnReceiveFrameEvent(const FrameEvent& frame_event) OVERRIDE; + + virtual void OnReceivePacketEvent(const PacketEvent& packet_event) OVERRIDE; + + virtual void OnReceiveGenericEvent(const GenericEvent& generic_event) + OVERRIDE; + + // Assigns frame events received so far to |frame_events| and clears them + // from this object. + void GetFrameEventsAndReset(std::vector* frame_events); + + // Assigns packet events received so far to |packet_events| and clears them + // from this object. + void GetPacketEventsAndReset(std::vector* packet_events); + + // Assigns generic events received so far to |generic_events| and clears them + // from this object. + void GetGenericEventsAndReset(std::vector* generic_events); + + private: + std::vector frame_events_; + std::vector packet_events_; + std::vector generic_events_; + + // All functions must be called on the main thread. + base::ThreadChecker thread_checker_; + + DISALLOW_COPY_AND_ASSIGN(SimpleEventSubscriber); +}; + +} // namespace cast +} // namespace media + +#endif // MEDIA_CAST_LOGGING_SIMPLE_EVENT_SUBSCRIBER_H_ diff --git a/media/cast/logging/simple_event_subscriber_unittest.cc b/media/cast/logging/simple_event_subscriber_unittest.cc new file mode 100644 index 0000000..5a6b09d --- /dev/null +++ b/media/cast/logging/simple_event_subscriber_unittest.cc @@ -0,0 +1,91 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "base/memory/ref_counted.h" +#include "base/memory/scoped_ptr.h" +#include "base/test/simple_test_tick_clock.h" +#include "base/time/tick_clock.h" +#include "media/cast/cast_environment.h" +#include "media/cast/logging/logging_defines.h" +#include "media/cast/logging/simple_event_subscriber.h" +#include "media/cast/test/fake_single_thread_task_runner.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace media { +namespace cast { + +class SimpleEventSubscriberTest : public ::testing::Test { + protected: + SimpleEventSubscriberTest() + : testing_clock_(new base::SimpleTestTickClock()), + task_runner_(new test::FakeSingleThreadTaskRunner(testing_clock_)), + cast_environment_(new CastEnvironment( + scoped_ptr(testing_clock_).Pass(), task_runner_, + task_runner_, task_runner_, task_runner_, task_runner_, + task_runner_, GetLoggingConfigWithRawEventsAndStatsEnabled())), + event_subscriber_(task_runner_) { + cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_); + } + + virtual ~SimpleEventSubscriberTest() { + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); + } + + base::SimpleTestTickClock* testing_clock_; // Owned by CastEnvironment. + scoped_refptr task_runner_; + scoped_refptr cast_environment_; + SimpleEventSubscriber event_subscriber_; +}; + +TEST_F(SimpleEventSubscriberTest, GetAndResetEvents) { + // Log some frame events. + cast_environment_->Logging()->InsertFrameEventWithDelay( + testing_clock_->NowTicks(), kAudioFrameDecoded, /*rtp_timestamp*/ 100u, + /*frame_id*/ 0u, /*delay*/ base::TimeDelta::FromMilliseconds(100)); + cast_environment_->Logging()->InsertFrameEventWithDelay( + testing_clock_->NowTicks(), kAudioPlayoutDelay, /*rtp_timestamp*/ 100u, + /*frame_id*/ 0u, /*delay*/ base::TimeDelta::FromMilliseconds(100)); + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kAudioFrameDecoded, /*rtp_timestamp*/ 200u, + /*frame_id*/ 0u); + + // Log some packet events. + cast_environment_->Logging()->InsertPacketEvent( + testing_clock_->NowTicks(), kAudioPacketReceived, /*rtp_timestamp*/ 200u, + /*frame_id*/ 0u, /*packet_id*/ 1u, /*max_packet_id*/ 5u, /*size*/ 100u); + cast_environment_->Logging()->InsertPacketEvent( + testing_clock_->NowTicks(), kVideoFrameDecoded, /*rtp_timestamp*/ 200u, + /*frame_id*/ 0u, /*packet_id*/ 1u, /*max_packet_id*/ 5u, /*size*/ 100u); + cast_environment_->Logging()->InsertPacketEvent( + testing_clock_->NowTicks(), kVideoFrameDecoded, /*rtp_timestamp*/ 300u, + /*frame_id*/ 0u, /*packet_id*/ 1u, /*max_packet_id*/ 5u, /*size*/ 100u); + + // Log some generic events. + cast_environment_->Logging()->InsertGenericEvent(testing_clock_->NowTicks(), + kRttMs, /*value*/ 150); + + std::vector frame_events; + event_subscriber_.GetFrameEventsAndReset(&frame_events); + EXPECT_EQ(3u, frame_events.size()); + + std::vector packet_events; + event_subscriber_.GetPacketEventsAndReset(&packet_events); + EXPECT_EQ(3u, packet_events.size()); + + std::vector generic_events; + event_subscriber_.GetGenericEventsAndReset(&generic_events); + EXPECT_EQ(1u, generic_events.size()); + + // Calling this function again should result in empty vector because no events + // were logged since last call. + event_subscriber_.GetFrameEventsAndReset(&frame_events); + event_subscriber_.GetPacketEventsAndReset(&packet_events); + event_subscriber_.GetGenericEventsAndReset(&generic_events); + EXPECT_TRUE(frame_events.empty()); + EXPECT_TRUE(packet_events.empty()); + EXPECT_TRUE(generic_events.empty()); +} + +} // namespace cast +} // namespace media diff --git a/media/cast/rtcp/receiver_rtcp_event_subscriber.cc b/media/cast/rtcp/receiver_rtcp_event_subscriber.cc new file mode 100644 index 0000000..a5f963e --- /dev/null +++ b/media/cast/rtcp/receiver_rtcp_event_subscriber.cc @@ -0,0 +1,144 @@ +// 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/rtcp/receiver_rtcp_event_subscriber.h" + +#include + +#include "base/single_thread_task_runner.h" +#include "media/cast/cast_environment.h" + +namespace media { +namespace cast { + +ReceiverRtcpEventSubscriber::ReceiverRtcpEventSubscriber( + const scoped_refptr& main_thread_proxy, + const size_t max_size_to_retain, Type type) + : max_size_to_retain_(max_size_to_retain), type_(type) { + DCHECK(main_thread_proxy->RunsTasksOnCurrentThread()); + DCHECK(max_size_to_retain_ > 0u); + DCHECK(type_ == kAudioEventSubscriber || type_ == kVideoEventSubscriber); +} + +ReceiverRtcpEventSubscriber::~ReceiverRtcpEventSubscriber() { + thread_checker_.CalledOnValidThread(); +} + +void ReceiverRtcpEventSubscriber::OnReceiveFrameEvent( + const FrameEvent& frame_event) { + thread_checker_.CalledOnValidThread(); + + if (ShouldProcessEvent(frame_event.type)) { + RtcpEvent rtcp_event; + switch (frame_event.type) { + case kAudioPlayoutDelay: + case kVideoRenderDelay: + rtcp_event.delay_delta = frame_event.delay_delta; + case kAudioFrameDecoded: + case kVideoFrameDecoded: + // TODO(imcheng): This doesn't seem correct because kAudioAckSent and + // kVideoAckSent logged as generic events in AudioReceiver / + // VideoReceiver. (crbug.com/339590) + case kAudioAckSent: + case kVideoAckSent: + rtcp_event.type = frame_event.type; + rtcp_event.timestamp = frame_event.timestamp; + rtcp_events_.insert( + std::make_pair(frame_event.rtp_timestamp, rtcp_event)); + break; + default: + break; + } + } + + TruncateMapIfNeeded(); + + DCHECK(rtcp_events_.size() <= max_size_to_retain_); +} + +void ReceiverRtcpEventSubscriber::OnReceivePacketEvent( + const PacketEvent& packet_event) { + thread_checker_.CalledOnValidThread(); + + if (ShouldProcessEvent(packet_event.type)) { + RtcpEvent rtcp_event; + if (packet_event.type == kAudioPacketReceived || + packet_event.type == kVideoPacketReceived) { + rtcp_event.type = packet_event.type; + rtcp_event.timestamp = packet_event.timestamp; + rtcp_event.packet_id = packet_event.packet_id; + rtcp_events_.insert( + std::make_pair(packet_event.rtp_timestamp, rtcp_event)); + } + } + + TruncateMapIfNeeded(); + + DCHECK(rtcp_events_.size() <= max_size_to_retain_); +} + +void ReceiverRtcpEventSubscriber::OnReceiveGenericEvent( + const GenericEvent& generic_event) { + thread_checker_.CalledOnValidThread(); + // Do nothing as RTP receiver is not interested in generic events for RTCP. +} + +void ReceiverRtcpEventSubscriber::GetReceiverLogMessageAndReset( + RtcpReceiverLogMessage* receiver_log) { + thread_checker_.CalledOnValidThread(); + + receiver_log->clear(); + + typedef std::multimap RtcpEventMultiMap; + RtcpEventMultiMap::const_iterator it = rtcp_events_.begin(); + while (it != rtcp_events_.end()) { + // On each iteration, process all entries that have the same key (RTP + // timestamp) within the multimap, and generate a + // RtcpReceiverFrameLogMessage from them. + RtpTimestamp rtp_timestamp = it->first; + RtcpReceiverFrameLogMessage frame_log(rtp_timestamp); + do { + RtcpReceiverEventLogMessage event_log_message; + event_log_message.type = it->second.type; + event_log_message.event_timestamp = it->second.timestamp; + event_log_message.delay_delta = it->second.delay_delta; + event_log_message.packet_id = it->second.packet_id; + frame_log.event_log_messages_.push_back(event_log_message); + ++it; + } while (it != rtcp_events_.end() && it->first == rtp_timestamp); + + receiver_log->push_back(frame_log); + } + + rtcp_events_.clear(); +} + +void ReceiverRtcpEventSubscriber::TruncateMapIfNeeded() { + // If map size has exceeded |max_size_to_retain_|, remove entry with + // the smallest RTP timestamp. + if (rtcp_events_.size() > max_size_to_retain_) { + DVLOG(2) << "RTCP event map exceeded size limit; " + << "removing oldest entry"; + // This is fine since we only insert elements one at a time. + rtcp_events_.erase(rtcp_events_.begin()); + } +} + +bool ReceiverRtcpEventSubscriber::ShouldProcessEvent( + CastLoggingEvent event_type) { + if (type_ == kAudioEventSubscriber) { + return event_type == kAudioPlayoutDelay || + event_type == kAudioFrameDecoded || event_type == kAudioAckSent || + event_type == kAudioPacketReceived; + } else if (type_ == kVideoEventSubscriber) { + return event_type == kVideoRenderDelay || + event_type == kVideoFrameDecoded || event_type == kVideoAckSent || + event_type == kVideoPacketReceived; + } else { + return false; + } +} + +} // namespace cast +} // namespace media diff --git a/media/cast/rtcp/receiver_rtcp_event_subscriber.h b/media/cast/rtcp/receiver_rtcp_event_subscriber.h new file mode 100644 index 0000000..caf0bc7 --- /dev/null +++ b/media/cast/rtcp/receiver_rtcp_event_subscriber.h @@ -0,0 +1,94 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#ifndef MEDIA_CAST_RTCP_RECEIVER_RTCP_EVENT_SUBSCRIBER_H_ +#define MEDIA_CAST_RTCP_RECEIVER_RTCP_EVENT_SUBSCRIBER_H_ + +#include + +#include "base/memory/ref_counted.h" +#include "base/threading/thread_checker.h" +#include "media/cast/logging/logging_defines.h" +#include "media/cast/logging/raw_event_subscriber.h" +#include "media/cast/rtcp/rtcp_defines.h" + +namespace base { + +class SingleThreadTaskRunner; +} + +namespace media { +namespace cast { + +// A RawEventSubscriber implementation with the following properties: +// - Only processes raw event types that are relevant for sending from cast +// receiver to cast sender via RTCP. +// - Captures information to be sent over to RTCP from raw event logs into the +// more compact RtcpEvent struct. +// - Orders events by RTP timestamp with a multimap. +// - Internally, the map is capped at a maximum size configurable by the caller. +// The subscriber only keeps the most recent events (determined by RTP +// timestamp) up to the size limit. +class ReceiverRtcpEventSubscriber : public RawEventSubscriber { + public: + // Identifies whether the subscriber will process audio or video related + // frame events. + enum Type { + kAudioEventSubscriber, // Only processes audio events + kVideoEventSubscriber // Only processes video events + }; + + // |main_thread_proxy|: Check that the object is created in main thread. + // This object does not hold a reference on it. + // |max_size_to_retain|: The object will keep up to |max_size_to_retain| + // events + // in the map. Once threshold has been reached, an event with the smallest + // RTP timestamp will be removed. + // |type|: Determines whether the subscriber will process only audio or video + // events. + ReceiverRtcpEventSubscriber( + const scoped_refptr& main_thread_proxy, + const size_t max_size_to_retain, Type type); + + virtual ~ReceiverRtcpEventSubscriber(); + + // RawEventSubscriber implementation. + virtual void OnReceiveFrameEvent(const FrameEvent& frame_event) OVERRIDE; + virtual void OnReceivePacketEvent(const PacketEvent& packet_event) OVERRIDE; + virtual void OnReceiveGenericEvent(const GenericEvent& generic_event) + OVERRIDE; + + // Converts all collected events since last invocation into + // a RtcpReceiverFrameLogMessage, assigns it to |receiver_log|, and clears + // |rtcp_events_|. + void GetReceiverLogMessageAndReset(RtcpReceiverLogMessage* receiver_log); + + private: + // If |rtcp_events_.size()| exceeds |max_size_to_retain_|, remove an oldest + // entry (determined by RTP timestamp) so its size no greater than + // |max_size_to_retain_|. + void TruncateMapIfNeeded(); + + // Returns |true| if events of |event_type| should be processed. + bool ShouldProcessEvent(CastLoggingEvent event_type); + + const size_t max_size_to_retain_; + Type type_; + + // The key should really be something more than just a RTP timestamp in order + // to differentiate between video and audio frames, but since the + // implementation doesn't mix audio and video frame events, RTP timestamp + // only as key is fine. + std::multimap rtcp_events_; + + // Ensures methods are only called on the main thread. + base::ThreadChecker thread_checker_; + + DISALLOW_COPY_AND_ASSIGN(ReceiverRtcpEventSubscriber); +}; + +} // namespace cast +} // namespace media + +#endif // MEDIA_CAST_RTCP_RECEIVER_RTCP_EVENT_SUBSCRIBER_H_ diff --git a/media/cast/rtcp/receiver_rtcp_event_subscriber_unittest.cc b/media/cast/rtcp/receiver_rtcp_event_subscriber_unittest.cc new file mode 100644 index 0000000..8158f8d --- /dev/null +++ b/media/cast/rtcp/receiver_rtcp_event_subscriber_unittest.cc @@ -0,0 +1,185 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "base/memory/ref_counted.h" +#include "base/memory/scoped_ptr.h" +#include "base/test/simple_test_tick_clock.h" +#include "base/time/tick_clock.h" +#include "media/cast/cast_environment.h" +#include "media/cast/logging/logging_defines.h" +#include "media/cast/rtcp/receiver_rtcp_event_subscriber.h" +#include "media/cast/test/fake_single_thread_task_runner.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace media { +namespace cast { + +namespace { + +const size_t kSizeThreshold = 10u; +const int64 kDelayMs = 20L; + +} // namespace + +class ReceiverRtcpEventSubscriberTest : public ::testing::Test { + protected: + ReceiverRtcpEventSubscriberTest() + : testing_clock_(new base::SimpleTestTickClock()), + task_runner_(new test::FakeSingleThreadTaskRunner(testing_clock_)), + cast_environment_(new CastEnvironment( + scoped_ptr(testing_clock_).Pass(), task_runner_, + task_runner_, task_runner_, task_runner_, task_runner_, + task_runner_, GetLoggingConfigWithRawEventsAndStatsEnabled())) {} + + virtual ~ReceiverRtcpEventSubscriberTest() {} + + virtual void TearDown() OVERRIDE { + if (event_subscriber_) { + cast_environment_->Logging()->RemoveRawEventSubscriber( + event_subscriber_.get()); + } + } + + void Init(ReceiverRtcpEventSubscriber::Type type) { + event_subscriber_.reset( + new ReceiverRtcpEventSubscriber(task_runner_, kSizeThreshold, type)); + cast_environment_->Logging()->AddRawEventSubscriber( + event_subscriber_.get()); + } + + void InsertEvents() { + // Video events + cast_environment_->Logging()->InsertFrameEventWithDelay( + testing_clock_->NowTicks(), kVideoRenderDelay, /*rtp_timestamp*/ 100u, + /*frame_id*/ 2u, base::TimeDelta::FromMilliseconds(kDelayMs)); + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kVideoFrameDecoded, /*rtp_timestamp*/ 200u, + /*frame_id*/ 1u); + cast_environment_->Logging()->InsertPacketEvent( + testing_clock_->NowTicks(), kVideoPacketReceived, + /*rtp_timestamp */ 200u, /*frame_id*/ 2u, /*packet_id*/ 1u, + /*max_packet_id*/ 10u, /*size*/ 1024u); + + // Audio events + cast_environment_->Logging()->InsertFrameEventWithDelay( + testing_clock_->NowTicks(), kAudioPlayoutDelay, /*rtp_timestamp*/ 300u, + /*frame_id*/ 4u, base::TimeDelta::FromMilliseconds(kDelayMs)); + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kAudioFrameDecoded, /*rtp_timestamp*/ 400u, + /*frame_id*/ 3u); + cast_environment_->Logging()->InsertPacketEvent( + testing_clock_->NowTicks(), kAudioPacketReceived, + /*rtp_timestamp */ 400u, /*frame_id*/ 5u, /*packet_id*/ 1u, + /*max_packet_id*/ 10u, /*size*/ 128u); + + // Unrelated events + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kVideoFrameReceived, /*rtp_timestamp*/ 100u, + /*frame_id*/ 1u); + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kAudioFrameReceived, /*rtp_timestamp*/ 100u, + /*frame_id*/ 1u); + cast_environment_->Logging()->InsertGenericEvent(testing_clock_->NowTicks(), + kRttMs, /*value*/ 100); + } + + base::SimpleTestTickClock* testing_clock_; // Owned by CastEnvironment. + scoped_refptr task_runner_; + scoped_refptr cast_environment_; + scoped_ptr event_subscriber_; +}; + +TEST_F(ReceiverRtcpEventSubscriberTest, LogVideoEvents) { + Init(ReceiverRtcpEventSubscriber::kVideoEventSubscriber); + + InsertEvents(); + + RtcpReceiverLogMessage receiver_log; + event_subscriber_->GetReceiverLogMessageAndReset(&receiver_log); + + ASSERT_EQ(2u, receiver_log.size()); + RtcpReceiverLogMessage::iterator log_it = receiver_log.begin(); + EXPECT_EQ(100u, log_it->rtp_timestamp_); + ASSERT_EQ(1u, log_it->event_log_messages_.size()); + RtcpReceiverEventLogMessages::iterator event_it = + log_it->event_log_messages_.begin(); + EXPECT_EQ(kVideoRenderDelay, event_it->type); + EXPECT_EQ(kDelayMs, event_it->delay_delta.InMilliseconds()); + + ++log_it; + EXPECT_EQ(200u, log_it->rtp_timestamp_); + ASSERT_EQ(2u, log_it->event_log_messages_.size()); +} + +TEST_F(ReceiverRtcpEventSubscriberTest, LogAudioEvents) { + Init(ReceiverRtcpEventSubscriber::kAudioEventSubscriber); + + InsertEvents(); + + RtcpReceiverLogMessage receiver_log; + event_subscriber_->GetReceiverLogMessageAndReset(&receiver_log); + + ASSERT_EQ(2u, receiver_log.size()); + RtcpReceiverLogMessage::iterator log_it = receiver_log.begin(); + EXPECT_EQ(300u, log_it->rtp_timestamp_); + ASSERT_EQ(1u, log_it->event_log_messages_.size()); + RtcpReceiverEventLogMessages::iterator event_it = + log_it->event_log_messages_.begin(); + EXPECT_EQ(kAudioPlayoutDelay, event_it->type); + EXPECT_EQ(kDelayMs, event_it->delay_delta.InMilliseconds()); + + ++log_it; + EXPECT_EQ(400u, log_it->rtp_timestamp_); + ASSERT_EQ(2u, log_it->event_log_messages_.size()); +} + +TEST_F(ReceiverRtcpEventSubscriberTest, MapReset) { + Init(ReceiverRtcpEventSubscriber::kVideoEventSubscriber); + + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kVideoFrameDecoded, /*rtp_timestamp*/ 100u, + /*frame_id*/ 1u); + + RtcpReceiverLogMessage receiver_log; + event_subscriber_->GetReceiverLogMessageAndReset(&receiver_log); + + EXPECT_EQ(1u, receiver_log.size()); + + // Call again without any logging in between, should return empty log. + event_subscriber_->GetReceiverLogMessageAndReset(&receiver_log); + EXPECT_TRUE(receiver_log.empty()); +} + +TEST_F(ReceiverRtcpEventSubscriberTest, DropEventsWhenSizeExceeded) { + Init(ReceiverRtcpEventSubscriber::kVideoEventSubscriber); + + for (uint32 i = 1u; i <= 10u; ++i) { + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kVideoFrameDecoded, + /*rtp_timestamp*/ i * 10, /*frame_id*/ i); + } + + RtcpReceiverLogMessage receiver_log; + event_subscriber_->GetReceiverLogMessageAndReset(&receiver_log); + + ASSERT_EQ(10u, receiver_log.size()); + EXPECT_EQ(10u, receiver_log.begin()->rtp_timestamp_); + EXPECT_EQ(100u, receiver_log.rbegin()->rtp_timestamp_); + + for (uint32 i = 1u; i <= 11u; ++i) { + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kVideoFrameDecoded, + /*rtp_timestamp*/ i * 10, /*frame_id*/ i); + } + + event_subscriber_->GetReceiverLogMessageAndReset(&receiver_log); + + // Event with RTP timestamp 10 should have been dropped when 110 is inserted. + ASSERT_EQ(10u, receiver_log.size()); + EXPECT_EQ(20u, receiver_log.begin()->rtp_timestamp_); + EXPECT_EQ(110u, receiver_log.rbegin()->rtp_timestamp_); +} + +} // namespace cast +} // namespace media diff --git a/media/cast/rtcp/rtcp.cc b/media/cast/rtcp/rtcp.cc index b335d1c..a322448 100644 --- a/media/cast/rtcp/rtcp.cc +++ b/media/cast/rtcp/rtcp.cc @@ -27,39 +27,17 @@ class LocalRtcpRttFeedback : public RtcpRttFeedback { public: explicit LocalRtcpRttFeedback(Rtcp* rtcp) : rtcp_(rtcp) {} - virtual void OnReceivedDelaySinceLastReport(uint32 receivers_ssrc, - uint32 last_report, - uint32 delay_since_last_report) - OVERRIDE { - rtcp_->OnReceivedDelaySinceLastReport( - receivers_ssrc, last_report, delay_since_last_report); + virtual void OnReceivedDelaySinceLastReport( + uint32 receivers_ssrc, uint32 last_report, + uint32 delay_since_last_report) OVERRIDE { + rtcp_->OnReceivedDelaySinceLastReport(receivers_ssrc, last_report, + delay_since_last_report); } private: Rtcp* rtcp_; }; -RtcpCastMessage::RtcpCastMessage(uint32 media_ssrc) : media_ssrc_(media_ssrc) {} - -RtcpCastMessage::~RtcpCastMessage() {} - -void RtcpCastMessage::Copy(const RtcpCastMessage& cast_message) { - media_ssrc_ = cast_message.media_ssrc_; - ack_frame_id_ = cast_message.ack_frame_id_; - missing_frames_and_packets_ = cast_message.missing_frames_and_packets_; -} - -RtcpNackMessage::RtcpNackMessage() {} -RtcpNackMessage::~RtcpNackMessage() {} - -RtcpRembMessage::RtcpRembMessage() {} -RtcpRembMessage::~RtcpRembMessage() {} - -RtcpReceiverFrameLogMessage::RtcpReceiverFrameLogMessage(uint32 timestamp) - : rtp_timestamp_(timestamp) {} - -RtcpReceiverFrameLogMessage::~RtcpReceiverFrameLogMessage() {} - class LocalRtcpReceiverFeedback : public RtcpReceiverFeedback { public: LocalRtcpReceiverFeedback(Rtcp* rtcp, @@ -103,32 +81,22 @@ class LocalRtcpReceiverFeedback : public RtcpReceiverFeedback { case kVideoPacketReceived: case kDuplicatePacketReceived: cast_environment_->Logging()->InsertPacketEvent( - event_it->event_timestamp, - event_it->type, - rtp_timestamp, - kFrameIdUnknown, - event_it->packet_id, - 0, - 0); + event_it->event_timestamp, event_it->type, rtp_timestamp, + kFrameIdUnknown, event_it->packet_id, 0, 0); break; case kAudioAckSent: case kVideoAckSent: case kAudioFrameDecoded: case kVideoFrameDecoded: cast_environment_->Logging()->InsertFrameEvent( - event_it->event_timestamp, - event_it->type, - rtp_timestamp, + event_it->event_timestamp, event_it->type, rtp_timestamp, kFrameIdUnknown); break; case kAudioPlayoutDelay: case kVideoRenderDelay: cast_environment_->Logging()->InsertFrameEventWithDelay( - event_it->event_timestamp, - event_it->type, - rtp_timestamp, - kFrameIdUnknown, - event_it->delay_delta); + event_it->event_timestamp, event_it->type, rtp_timestamp, + kFrameIdUnknown, event_it->delay_delta); break; default: VLOG(2) << "Received log message via RTCP that we did not expect: " @@ -189,12 +157,9 @@ Rtcp::Rtcp(scoped_refptr cast_environment, transport::CastTransportSender* const transport_sender, transport::PacedPacketSender* paced_packet_sender, RtpSenderStatistics* rtp_sender_statistics, - RtpReceiverStatistics* rtp_receiver_statistics, - RtcpMode rtcp_mode, - const base::TimeDelta& rtcp_interval, - uint32 local_ssrc, - uint32 remote_ssrc, - const std::string& c_name) + RtpReceiverStatistics* rtp_receiver_statistics, RtcpMode rtcp_mode, + const base::TimeDelta& rtcp_interval, uint32 local_ssrc, + uint32 remote_ssrc, const std::string& c_name) : cast_environment_(cast_environment), transport_sender_(transport_sender), rtcp_interval_(rtcp_interval), @@ -206,21 +171,17 @@ Rtcp::Rtcp(scoped_refptr cast_environment, rtp_receiver_statistics_(rtp_receiver_statistics), receiver_feedback_(new LocalRtcpReceiverFeedback(this, cast_environment)), rtt_feedback_(new LocalRtcpRttFeedback(this)), - rtcp_sender_(new RtcpSender(cast_environment, - paced_packet_sender, - local_ssrc, - c_name)), + rtcp_sender_(new RtcpSender(cast_environment, paced_packet_sender, + local_ssrc, c_name)), last_report_received_(0), last_received_rtp_timestamp_(0), last_received_ntp_seconds_(0), last_received_ntp_fraction_(0), min_rtt_(base::TimeDelta::FromMilliseconds(kMaxRttMs)), number_of_rtt_in_avg_(0) { - rtcp_receiver_.reset(new RtcpReceiver(cast_environment, - sender_feedback, + rtcp_receiver_.reset(new RtcpReceiver(cast_environment, sender_feedback, receiver_feedback_.get(), - rtt_feedback_.get(), - local_ssrc)); + rtt_feedback_.get(), local_ssrc)); rtcp_receiver_->SetRemoteSSRC(remote_ssrc); } @@ -229,8 +190,7 @@ Rtcp::~Rtcp() {} // static bool Rtcp::IsRtcpPacket(const uint8* packet, size_t length) { DCHECK_GE(length, kMinLengthOfRtcp) << "Invalid RTCP packet"; - if (length < kMinLengthOfRtcp) - return false; + if (length < kMinLengthOfRtcp) return false; uint8 packet_type = packet[1]; if (packet_type >= transport::kPacketTypeLow && @@ -289,12 +249,10 @@ void Rtcp::SendRtcpFromRtpReceiver(const RtcpCastMessage* cast_message, report_block.media_ssrc = remote_ssrc_; // SSRC of the RTP packet sender. if (rtp_receiver_statistics_) { rtp_receiver_statistics_->GetStatistics( - &report_block.fraction_lost, - &report_block.cumulative_lost, - &report_block.extended_high_sequence_number, - &report_block.jitter); - cast_environment_->Logging()->InsertGenericEvent( - now, kJitterMs, report_block.jitter); + &report_block.fraction_lost, &report_block.cumulative_lost, + &report_block.extended_high_sequence_number, &report_block.jitter); + cast_environment_->Logging()->InsertGenericEvent(now, kJitterMs, + report_block.jitter); cast_environment_->Logging()->InsertGenericEvent( now, kPacketLoss, report_block.fraction_lost); } @@ -304,8 +262,8 @@ void Rtcp::SendRtcpFromRtpReceiver(const RtcpCastMessage* cast_message, uint32 delay_seconds = 0; uint32 delay_fraction = 0; base::TimeDelta delta = now - time_last_report_received_; - ConvertTimeToFractions( - delta.InMicroseconds(), &delay_seconds, &delay_fraction); + ConvertTimeToFractions(delta.InMicroseconds(), &delay_seconds, + &delay_fraction); report_block.delay_since_last_sr = ConvertToNtpDiff(delay_seconds, delay_fraction); } else { @@ -317,8 +275,8 @@ void Rtcp::SendRtcpFromRtpReceiver(const RtcpCastMessage* cast_message, SaveLastSentNtpTime(now, rrtr.ntp_seconds, rrtr.ntp_fraction); UpdateNextTimeToSendRtcp(); } - rtcp_sender_->SendRtcpFromRtpReceiver( - packet_type_flags, &report_block, &rrtr, cast_message, receiver_log); + rtcp_sender_->SendRtcpFromRtpReceiver(packet_type_flags, &report_block, &rrtr, + cast_message, receiver_log); } void Rtcp::SendRtcpFromRtpSender( @@ -346,36 +304,28 @@ void Rtcp::SendRtcpFromRtpSender( uint32 delay_seconds = 0; uint32 delay_fraction = 0; base::TimeDelta delta = now - time_last_report_received_; - ConvertTimeToFractions( - delta.InMicroseconds(), &delay_seconds, &delay_fraction); + ConvertTimeToFractions(delta.InMicroseconds(), &delay_seconds, + &delay_fraction); dlrr.delay_since_last_rr = ConvertToNtpDiff(delay_seconds, delay_fraction); } cast_environment_->PostTask( - CastEnvironment::TRANSPORT, - FROM_HERE, + CastEnvironment::TRANSPORT, FROM_HERE, base::Bind(&Rtcp::SendRtcpFromRtpSenderOnTransportThread, - base::Unretained(this), - packet_type_flags, - sender_info, - dlrr, - sender_log_message, - local_ssrc_, - c_name_)); + base::Unretained(this), packet_type_flags, sender_info, dlrr, + sender_log_message, local_ssrc_, c_name_)); UpdateNextTimeToSendRtcp(); } void Rtcp::SendRtcpFromRtpSenderOnTransportThread( - uint32 packet_type_flags, - const transport::RtcpSenderInfo& sender_info, + uint32 packet_type_flags, const transport::RtcpSenderInfo& sender_info, const transport::RtcpDlrrReportBlock& dlrr, - const transport::RtcpSenderLogMessage& sender_log, - uint32 sending_ssrc, + const transport::RtcpSenderLogMessage& sender_log, uint32 sending_ssrc, std::string c_name) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::TRANSPORT)); - transport_sender_->SendRtcpFromRtpSender( - packet_type_flags, sender_info, dlrr, sender_log, sending_ssrc, c_name); + transport_sender_->SendRtcpFromRtpSender(packet_type_flags, sender_info, dlrr, + sender_log, sending_ssrc, c_name); } void Rtcp::OnReceivedNtp(uint32 ntp_seconds, uint32 ntp_fraction) { @@ -385,8 +335,7 @@ void Rtcp::OnReceivedNtp(uint32 ntp_seconds, uint32 ntp_fraction) { time_last_report_received_ = now; } -void Rtcp::OnReceivedLipSyncInfo(uint32 rtp_timestamp, - uint32 ntp_seconds, +void Rtcp::OnReceivedLipSyncInfo(uint32 rtp_timestamp, uint32 ntp_seconds, uint32 ntp_fraction) { last_received_rtp_timestamp_ = rtp_timestamp; last_received_ntp_seconds_ = ntp_seconds; @@ -400,13 +349,11 @@ void Rtcp::OnReceivedSendReportRequest() { next_time_to_send_rtcp_ = now; } -bool Rtcp::RtpTimestampInSenderTime(int frequency, - uint32 rtp_timestamp, +bool Rtcp::RtpTimestampInSenderTime(int frequency, uint32 rtp_timestamp, base::TimeTicks* rtp_timestamp_in_ticks) const { - if (last_received_ntp_seconds_ == 0) { + if (last_received_ntp_seconds_ == 0) return false; - } int wrap = CheckForWrapAround(rtp_timestamp, last_received_rtp_timestamp_); int64 rtp_timestamp_int64 = rtp_timestamp; @@ -427,9 +374,8 @@ bool Rtcp::RtpTimestampInSenderTime(int frequency, int64 rtp_time_diff_ms = rtp_timestamp_diff / frequency_khz; // Sanity check. - if (abs(rtp_time_diff_ms) > kMaxDiffSinceReceivedRtcpMs) { + if (abs(rtp_time_diff_ms) > kMaxDiffSinceReceivedRtcpMs) return false; - } *rtp_timestamp_in_ticks = ConvertNtpToTimeTicks(last_received_ntp_seconds_, last_received_ntp_fraction_) + @@ -455,9 +401,8 @@ void Rtcp::SaveLastSentNtpTime(const base::TimeTicks& now, uint32 last_ntp_fraction) { // Make sure |now| is always greater than the last element in // |last_reports_sent_queue_|. - if (!last_reports_sent_queue_.empty()) { + if (!last_reports_sent_queue_.empty()) DCHECK(now >= last_reports_sent_queue_.back().second); - } uint32 last_report = ConvertToNtpDiff(last_ntp_seconds, last_ntp_fraction); last_reports_sent_map_[last_report] = now; @@ -495,21 +440,18 @@ void Rtcp::UpdateRtt(const base::TimeDelta& sender_delay, number_of_rtt_in_avg_++; } -bool Rtcp::Rtt(base::TimeDelta* rtt, - base::TimeDelta* avg_rtt, - base::TimeDelta* min_rtt, - base::TimeDelta* max_rtt) const { +bool Rtcp::Rtt(base::TimeDelta* rtt, base::TimeDelta* avg_rtt, + base::TimeDelta* min_rtt, base::TimeDelta* max_rtt) const { DCHECK(rtt) << "Invalid argument"; DCHECK(avg_rtt) << "Invalid argument"; DCHECK(min_rtt) << "Invalid argument"; DCHECK(max_rtt) << "Invalid argument"; - if (number_of_rtt_in_avg_ == 0) - return false; + if (number_of_rtt_in_avg_ == 0) return false; base::TimeTicks now = cast_environment_->Clock()->NowTicks(); - cast_environment_->Logging()->InsertGenericEvent( - now, kRttMs, rtt->InMilliseconds()); + cast_environment_->Logging()->InsertGenericEvent(now, kRttMs, + rtt->InMilliseconds()); *rtt = rtt_; *avg_rtt = base::TimeDelta::FromMilliseconds(avg_rtt_ms_); diff --git a/media/cast/rtcp/rtcp.gyp b/media/cast/rtcp/rtcp.gyp index 0d556800..8ce90d4 100644 --- a/media/cast/rtcp/rtcp.gyp +++ b/media/cast/rtcp/rtcp.gyp @@ -11,6 +11,7 @@ '<(DEPTH)/', ], 'sources': [ + 'rtcp_defines.cc', 'rtcp_defines.h', 'rtcp.h', 'rtcp.cc', @@ -20,6 +21,10 @@ 'rtcp_sender.h', 'rtcp_utility.cc', 'rtcp_utility.h', + 'sender_rtcp_event_subscriber.cc', + 'sender_rtcp_event_subscriber.h', + 'receiver_rtcp_event_subscriber.cc', + 'receiver_rtcp_event_subscriber.cc', ], # source 'dependencies': [ '<(DEPTH)/base/base.gyp:base', diff --git a/media/cast/rtcp/rtcp_defines.cc b/media/cast/rtcp/rtcp_defines.cc new file mode 100644 index 0000000..c1ad8fc --- /dev/null +++ b/media/cast/rtcp/rtcp_defines.cc @@ -0,0 +1,48 @@ +// 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/rtcp/rtcp_defines.h" + +#include "media/cast/logging/logging_defines.h" + +namespace media { +namespace cast { + +RtcpCastMessage::RtcpCastMessage(uint32 media_ssrc) + : media_ssrc_(media_ssrc), ack_frame_id_(0u) {} +RtcpCastMessage::~RtcpCastMessage() {} + +void RtcpCastMessage::Copy(const RtcpCastMessage& cast_message) { + media_ssrc_ = cast_message.media_ssrc_; + ack_frame_id_ = cast_message.ack_frame_id_; + missing_frames_and_packets_ = cast_message.missing_frames_and_packets_; +} + +RtcpReceiverEventLogMessage::RtcpReceiverEventLogMessage() + : type(kUnknown), packet_id(0u) {} +RtcpReceiverEventLogMessage::~RtcpReceiverEventLogMessage() {} + +RtcpReceiverFrameLogMessage::RtcpReceiverFrameLogMessage(uint32 timestamp) + : rtp_timestamp_(timestamp) {} +RtcpReceiverFrameLogMessage::~RtcpReceiverFrameLogMessage() {} + +RtcpRpsiMessage::RtcpRpsiMessage() + : remote_ssrc(0u), payload_type(0u), picture_id(0u) {} +RtcpRpsiMessage::~RtcpRpsiMessage() {} + +RtcpNackMessage::RtcpNackMessage() : remote_ssrc(0u) {} +RtcpNackMessage::~RtcpNackMessage() {} + +RtcpRembMessage::RtcpRembMessage() : remb_bitrate(0u) {} +RtcpRembMessage::~RtcpRembMessage() {} + +RtcpReceiverReferenceTimeReport::RtcpReceiverReferenceTimeReport() + : remote_ssrc(0u), ntp_seconds(0u), ntp_fraction(0u) {} +RtcpReceiverReferenceTimeReport::~RtcpReceiverReferenceTimeReport() {} + +RtcpEvent::RtcpEvent() : type(kUnknown), packet_id(0u) {} +RtcpEvent::~RtcpEvent() {} + +} // namespace cast +} // namespace media diff --git a/media/cast/rtcp/rtcp_defines.h b/media/cast/rtcp/rtcp_defines.h index 74e76c2..40f4a0d 100644 --- a/media/cast/rtcp/rtcp_defines.h +++ b/media/cast/rtcp/rtcp_defines.h @@ -17,6 +17,11 @@ namespace media { namespace cast { +static const size_t kRtcpCastLogHeaderSize = 12; +static const size_t kRtcpSenderFrameLogSize = 4; +static const size_t kRtcpReceiverFrameLogSize = 8; +static const size_t kRtcpReceiverEventLogSize = 4; + // Handle the per frame ACK and NACK messages. class RtcpCastMessage { public: @@ -34,6 +39,9 @@ class RtcpCastMessage { // Log messages from receiver to sender. struct RtcpReceiverEventLogMessage { + RtcpReceiverEventLogMessage(); + ~RtcpReceiverEventLogMessage(); + CastLoggingEvent type; base::TimeTicks event_timestamp; base::TimeDelta delay_delta; @@ -42,8 +50,7 @@ struct RtcpReceiverEventLogMessage { typedef std::list RtcpReceiverEventLogMessages; -class RtcpReceiverFrameLogMessage { - public: +struct RtcpReceiverFrameLogMessage { explicit RtcpReceiverFrameLogMessage(uint32 rtp_timestamp); ~RtcpReceiverFrameLogMessage(); @@ -58,13 +65,15 @@ class RtcpReceiverFrameLogMessage { typedef std::list RtcpReceiverLogMessage; struct RtcpRpsiMessage { + RtcpRpsiMessage(); + ~RtcpRpsiMessage(); + uint32 remote_ssrc; uint8 payload_type; uint64 picture_id; }; -class RtcpNackMessage { - public: +struct RtcpNackMessage { RtcpNackMessage(); ~RtcpNackMessage(); @@ -74,8 +83,7 @@ class RtcpNackMessage { DISALLOW_COPY_AND_ASSIGN(RtcpNackMessage); }; -class RtcpRembMessage { - public: +struct RtcpRembMessage { RtcpRembMessage(); ~RtcpRembMessage(); @@ -86,6 +94,9 @@ class RtcpRembMessage { }; struct RtcpReceiverReferenceTimeReport { + RtcpReceiverReferenceTimeReport(); + ~RtcpReceiverReferenceTimeReport(); + uint32 remote_ssrc; uint32 ntp_seconds; uint32 ntp_fraction; @@ -98,6 +109,26 @@ inline bool operator==(RtcpReceiverReferenceTimeReport lhs, lhs.ntp_fraction == rhs.ntp_fraction; } +// Struct used by raw event subscribers as an intermediate format before +// sending off to the other side via RTCP. +// (i.e., WindowedRtcpEventRtp{Sender,Receiver}Subscriber) +struct RtcpEvent { + RtcpEvent(); + ~RtcpEvent(); + + CastLoggingEvent type; + + // Time of event logged. + base::TimeTicks timestamp; + + // Render/playout delay. Only set for kAudioPlayoutDelay and + // kVideoRenderDelay events. + base::TimeDelta delay_delta; + + // Only set for packet events. (kAudioPacketReceived, kVideoPacketReceived) + uint16 packet_id; +}; + } // namespace cast } // namespace media diff --git a/media/cast/rtcp/rtcp_sender.cc b/media/cast/rtcp/rtcp_sender.cc index efe0a3b..b11e60a 100644 --- a/media/cast/rtcp/rtcp_sender.cc +++ b/media/cast/rtcp/rtcp_sender.cc @@ -9,18 +9,19 @@ #include "base/logging.h" #include "media/cast/cast_environment.h" +#include "media/cast/rtcp/rtcp_defines.h" #include "media/cast/rtcp/rtcp_utility.h" #include "media/cast/transport/cast_transport_defines.h" #include "media/cast/transport/pacing/paced_sender.h" #include "net/base/big_endian.h" -static const size_t kRtcpCastLogHeaderSize = 12; -static const size_t kRtcpSenderFrameLogSize = 4; -static const size_t kRtcpReceiverFrameLogSize = 8; -static const size_t kRtcpReceiverEventLogSize = 4; - namespace { +using media::cast::kRtcpCastLogHeaderSize; +using media::cast::kRtcpSenderFrameLogSize; +using media::cast::kRtcpReceiverFrameLogSize; +using media::cast::kRtcpReceiverEventLogSize; + // Converts a log event type to an integer value. int ConvertEventTypeToWireFormat(const media::cast::CastLoggingEvent& event) { switch (event) { @@ -65,19 +66,16 @@ uint16 MergeEventTypeAndTimestampForWireFormat( bool ScanRtcpReceiverLogMessage( const media::cast::RtcpReceiverLogMessage& receiver_log_message, - size_t start_size, - size_t* number_of_frames, - size_t* total_number_of_messages_to_send, - size_t* rtcp_log_size) { - if (receiver_log_message.empty()) - return false; + size_t start_size, size_t* number_of_frames, + size_t* total_number_of_messages_to_send, size_t* rtcp_log_size) { + if (receiver_log_message.empty()) return false; size_t remaining_space = media::cast::kMaxIpPacketSize - start_size; // We must have space for at least one message - DCHECK_GE(remaining_space, - kRtcpCastLogHeaderSize + kRtcpReceiverFrameLogSize + - kRtcpReceiverEventLogSize) + DCHECK_GE(remaining_space, kRtcpCastLogHeaderSize + + kRtcpReceiverFrameLogSize + + kRtcpReceiverEventLogSize) << "Not enough buffer space"; if (remaining_space < kRtcpCastLogHeaderSize + kRtcpReceiverFrameLogSize + @@ -135,8 +133,7 @@ namespace cast { // TODO(mikhal): This is only used by the receiver. Consider renaming. RtcpSender::RtcpSender(scoped_refptr cast_environment, transport::PacedPacketSender* outgoing_transport, - uint32 sending_ssrc, - const std::string& c_name) + uint32 sending_ssrc, const std::string& c_name) : ssrc_(sending_ssrc), c_name_(c_name), transport_(outgoing_transport), @@ -152,11 +149,9 @@ bool RtcpSender::IsReceiverEvent(const media::cast::CastLoggingEvent& event) { } void RtcpSender::SendRtcpFromRtpReceiver( - uint32 packet_type_flags, - const transport::RtcpReportBlock* report_block, + uint32 packet_type_flags, const transport::RtcpReportBlock* report_block, const RtcpReceiverReferenceTimeReport* rrtr, - const RtcpCastMessage* cast_message, - RtcpReceiverLogMessage* receiver_log) { + const RtcpCastMessage* cast_message, RtcpReceiverLogMessage* receiver_log) { if (packet_type_flags & kRtcpSr || packet_type_flags & kRtcpDlrr || packet_type_flags & kRtcpSenderLog) { NOTREACHED() << "Invalid argument"; @@ -190,8 +185,7 @@ void RtcpSender::SendRtcpFromRtpReceiver( DCHECK(receiver_log) << "Invalid argument"; BuildReceiverLog(receiver_log, &packet); } - if (packet.empty()) - return; // Sanity don't send empty packets. + if (packet.empty()) return; // Sanity don't send empty packets. transport_->SendRtcpPacket(packet); } @@ -200,8 +194,7 @@ void RtcpSender::BuildRR(const transport::RtcpReportBlock* report_block, Packet* packet) const { size_t start_size = packet->size(); DCHECK_LT(start_size + 32, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 32 > kMaxIpPacketSize) - return; + if (start_size + 32 > kMaxIpPacketSize) return; uint16 number_of_rows = (report_block) ? 7 : 1; packet->resize(start_size + 8); @@ -221,8 +214,7 @@ void RtcpSender::AddReportBlocks(const transport::RtcpReportBlock& report_block, Packet* packet) const { size_t start_size = packet->size(); DCHECK_LT(start_size + 24, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 24 > kMaxIpPacketSize) - return; + if (start_size + 24 > kMaxIpPacketSize) return; packet->resize(start_size + 24); @@ -250,8 +242,7 @@ void RtcpSender::BuildSdec(Packet* packet) const { size_t start_size = packet->size(); DCHECK_LT(start_size + 12 + c_name_.length(), kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 12 > kMaxIpPacketSize) - return; + if (start_size + 12 > kMaxIpPacketSize) return; // SDES Source Description. packet->resize(start_size + 10); @@ -269,8 +260,8 @@ void RtcpSender::BuildSdec(Packet* packet) const { big_endian_writer.WriteU8(static_cast(c_name_.length())); size_t sdes_length = 10 + c_name_.length(); - packet->insert( - packet->end(), c_name_.c_str(), c_name_.c_str() + c_name_.length()); + packet->insert(packet->end(), c_name_.c_str(), + c_name_.c_str() + c_name_.length()); size_t padding = 0; @@ -293,8 +284,7 @@ void RtcpSender::BuildSdec(Packet* packet) const { void RtcpSender::BuildPli(uint32 remote_ssrc, Packet* packet) const { size_t start_size = packet->size(); DCHECK_LT(start_size + 12, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 12 > kMaxIpPacketSize) - return; + if (start_size + 12 > kMaxIpPacketSize) return; packet->resize(start_size + 12); @@ -319,8 +309,7 @@ void RtcpSender::BuildPli(uint32 remote_ssrc, Packet* packet) const { void RtcpSender::BuildRpsi(const RtcpRpsiMessage* rpsi, Packet* packet) const { size_t start_size = packet->size(); DCHECK_LT(start_size + 24, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 24 > kMaxIpPacketSize) - return; + if (start_size + 24 > kMaxIpPacketSize) return; packet->resize(start_size + 24); @@ -374,8 +363,7 @@ void RtcpSender::BuildRemb(const RtcpRembMessage* remb, Packet* packet) const { size_t remb_size = 20 + 4 * remb->remb_ssrcs.size(); DCHECK_LT(start_size + remb_size, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + remb_size > kMaxIpPacketSize) - return; + if (start_size + remb_size > kMaxIpPacketSize) return; packet->resize(start_size + remb_size); @@ -395,8 +383,8 @@ void RtcpSender::BuildRemb(const RtcpRembMessage* remb, Packet* packet) const { // 6 bit exponent and a 18 bit mantissa. uint8 bitrate_exponent; uint32 bitrate_mantissa; - BitrateToRembExponentBitrate( - remb->remb_bitrate, &bitrate_exponent, &bitrate_mantissa); + BitrateToRembExponentBitrate(remb->remb_bitrate, &bitrate_exponent, + &bitrate_mantissa); big_endian_writer.WriteU8(static_cast( (bitrate_exponent << 2) + ((bitrate_mantissa >> 16) & 0x03))); @@ -408,15 +396,14 @@ void RtcpSender::BuildRemb(const RtcpRembMessage* remb, Packet* packet) const { big_endian_writer.WriteU32(*it); } base::TimeTicks now = cast_environment_->Clock()->NowTicks(); - cast_environment_->Logging()->InsertGenericEvent( - now, kRembBitrate, remb->remb_bitrate); + cast_environment_->Logging()->InsertGenericEvent(now, kRembBitrate, + remb->remb_bitrate); } void RtcpSender::BuildNack(const RtcpNackMessage* nack, Packet* packet) const { size_t start_size = packet->size(); DCHECK_LT(start_size + 16, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 16 > kMaxIpPacketSize) - return; + if (start_size + 16 > kMaxIpPacketSize) return; packet->resize(start_size + 16); @@ -455,8 +442,7 @@ void RtcpSender::BuildNack(const RtcpNackMessage* nack, Packet* packet) const { // Write the sequence number and the bitmask to the packet. start_size = packet->size(); DCHECK_LT(start_size + 4, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 4 > kMaxIpPacketSize) - return; + if (start_size + 4 > kMaxIpPacketSize) return; packet->resize(start_size + 4); net::BigEndianWriter big_endian_nack_writer(&((*packet)[start_size]), 4); @@ -471,8 +457,7 @@ void RtcpSender::BuildNack(const RtcpNackMessage* nack, Packet* packet) const { void RtcpSender::BuildBye(Packet* packet) const { size_t start_size = packet->size(); DCHECK_LT(start_size + 8, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 8 > kMaxIpPacketSize) - return; + if (start_size + 8 > kMaxIpPacketSize) return; packet->resize(start_size + 8); @@ -487,8 +472,7 @@ void RtcpSender::BuildRrtr(const RtcpReceiverReferenceTimeReport* rrtr, Packet* packet) const { size_t start_size = packet->size(); DCHECK_LT(start_size + 20, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 20 > kMaxIpPacketSize) - return; + if (start_size + 20 > kMaxIpPacketSize) return; packet->resize(start_size + 20); @@ -510,8 +494,7 @@ void RtcpSender::BuildRrtr(const RtcpReceiverReferenceTimeReport* rrtr, void RtcpSender::BuildCast(const RtcpCastMessage* cast, Packet* packet) const { size_t start_size = packet->size(); DCHECK_LT(start_size + 20, kMaxIpPacketSize) << "Not enough buffer space"; - if (start_size + 20 > kMaxIpPacketSize) - return; + if (start_size + 20 > kMaxIpPacketSize) return; packet->resize(start_size + 20); @@ -594,11 +577,9 @@ void RtcpSender::BuildReceiverLog(RtcpReceiverLogMessage* receiver_log_message, size_t total_number_of_messages_to_send = 0; size_t rtcp_log_size = 0; - if (!ScanRtcpReceiverLogMessage(*receiver_log_message, - packet_start_size, - &number_of_frames, - &total_number_of_messages_to_send, - &rtcp_log_size)) { + if (!ScanRtcpReceiverLogMessage( + *receiver_log_message, packet_start_size, &number_of_frames, + &total_number_of_messages_to_send, &rtcp_log_size)) { return; } packet->resize(packet_start_size + rtcp_log_size); diff --git a/media/cast/rtcp/sender_rtcp_event_subscriber.cc b/media/cast/rtcp/sender_rtcp_event_subscriber.cc new file mode 100644 index 0000000..f16ff01 --- /dev/null +++ b/media/cast/rtcp/sender_rtcp_event_subscriber.cc @@ -0,0 +1,100 @@ +// 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/rtcp/sender_rtcp_event_subscriber.h" + +#include + +#include "base/single_thread_task_runner.h" +#include "media/cast/cast_environment.h" +#include "media/cast/rtcp/rtcp_defines.h" + +namespace media { +namespace cast { + +SenderRtcpEventSubscriber::SenderRtcpEventSubscriber( + const scoped_refptr& main_thread_proxy, + const size_t max_size_to_retain) + : max_size_to_retain_(max_size_to_retain) { + DCHECK(main_thread_proxy->RunsTasksOnCurrentThread()); + DCHECK(max_size_to_retain_ > 0u); +} + +SenderRtcpEventSubscriber::~SenderRtcpEventSubscriber() { + thread_checker_.CalledOnValidThread(); +} + +void SenderRtcpEventSubscriber::OnReceiveFrameEvent( + const FrameEvent& frame_event) { + thread_checker_.CalledOnValidThread(); + if (frame_event.type != kVideoFrameCaptured && + frame_event.type != kVideoFrameSentToEncoder && + frame_event.type != kVideoFrameEncoded) { + // Not interested in other events. + return; + } + + RtcpEventMap::iterator it = rtcp_events_.find(frame_event.rtp_timestamp); + if (it == rtcp_events_.end()) { + // We have not stored this frame (RTP timestamp) in our map. + RtcpEvent rtcp_event; + rtcp_event.type = frame_event.type; + rtcp_event.timestamp = frame_event.timestamp; + + // Do not need to fill out rtcp_event.delay_delta or rtcp_event.packet_id + // as they are not set in frame events we are interested in. + rtcp_events_.insert(std::make_pair(frame_event.rtp_timestamp, rtcp_event)); + + TruncateMapIfNeeded(); + } else { + // We already have this frame (RTP timestamp) in our map. + // Only update events that are later in the chain. + // This is due to that events can be reordered on the wire. + if (frame_event.type == kVideoFrameCaptured) { + return; // First event in chain can not be late by definition. + } + + if (it->second.type == kVideoFrameEncoded) { + return; // Last event in chain should not be updated. + } + + // Update existing entry. + it->second.type = frame_event.type; + } + + DCHECK(rtcp_events_.size() <= max_size_to_retain_); +} + +void SenderRtcpEventSubscriber::OnReceivePacketEvent( + const PacketEvent& packet_event) { + thread_checker_.CalledOnValidThread(); + // Do nothing as RTP sender is not interested in packet events for RTCP. +} + +void SenderRtcpEventSubscriber::OnReceiveGenericEvent( + const GenericEvent& generic_event) { + thread_checker_.CalledOnValidThread(); + // Do nothing as RTP sender is not interested in generic events for RTCP. +} + +void SenderRtcpEventSubscriber::GetRtcpEventsAndReset( + RtcpEventMap* rtcp_events) { + thread_checker_.CalledOnValidThread(); + rtcp_events->swap(rtcp_events_); + rtcp_events_.clear(); +} + +void SenderRtcpEventSubscriber::TruncateMapIfNeeded() { + // If map size has exceeded |max_size_to_retain_|, remove entry with + // the smallest RTP timestamp. + if (rtcp_events_.size() > max_size_to_retain_) { + DVLOG(2) << "RTCP event map exceeded size limit; " + << "removing oldest entry"; + // This is fine since we only insert elements one at a time. + rtcp_events_.erase(rtcp_events_.begin()); + } +} + +} // namespace cast +} // namespace media diff --git a/media/cast/rtcp/sender_rtcp_event_subscriber.h b/media/cast/rtcp/sender_rtcp_event_subscriber.h new file mode 100644 index 0000000..fc57cbf --- /dev/null +++ b/media/cast/rtcp/sender_rtcp_event_subscriber.h @@ -0,0 +1,80 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#ifndef MEDIA_CAST_RTCP_SENDER_RTCP_EVENT_SUBSCRIBER_H_ +#define MEDIA_CAST_RTCP_SENDER_RTCP_EVENT_SUBSCRIBER_H_ + +#include + +#include "base/memory/ref_counted.h" +#include "base/threading/thread_checker.h" +#include "media/cast/logging/logging_defines.h" +#include "media/cast/logging/raw_event_subscriber.h" +#include "media/cast/rtcp/rtcp_defines.h" + +namespace base { + +class SingleThreadTaskRunner; +} + +namespace media { +namespace cast { + +// The key should really be something more than just a RTP timestamp in order +// to differentiate between video and audio frames, but since the implementation +// only process video frame events, RTP timestamp only as key is fine. +typedef std::map RtcpEventMap; + +// A RawEventSubscriber implementation with the following properties: +// - Only processes raw event types that are relevant for sending from cast +// sender to cast receiver via RTCP. +// - Captures information to be sent over to RTCP from raw event logs into the +// more compact RtcpEvent struct. +// - Orders events by RTP timestamp with a map. +// - Internally, the map is capped at a maximum size configurable by the caller. +// The subscriber only keeps the most recent events (determined by RTP +// timestamp) up to the size limit. +class SenderRtcpEventSubscriber : public RawEventSubscriber { + public: + // |main_thread_proxy|: Check that the object is created in main thread. + // This object does not hold a reference on it. + // |max_size_to_retain|: The object will keep up to |max_size_to_retain| + // events + // in the map. Once threshold has been reached, an event with the smallest + // RTP timestamp will be removed. + SenderRtcpEventSubscriber( + const scoped_refptr& main_thread_proxy, + const size_t max_size_to_retain); + virtual ~SenderRtcpEventSubscriber(); + + // RawEventSubscriber implementation. + virtual void OnReceiveFrameEvent(const FrameEvent& frame_event) OVERRIDE; + virtual void OnReceivePacketEvent(const PacketEvent& packet_event) OVERRIDE; + virtual void OnReceiveGenericEvent(const GenericEvent& generic_event) + OVERRIDE; + + // Assigns all collected events since last invocation to |rtcp_events|, and + // clears |rtcp_events_|. + void GetRtcpEventsAndReset(RtcpEventMap* rtcp_events); + + private: + // If |rtcp_events_.size()| exceeds |max_size_to_retain_|, remove an oldest + // entry + // (determined by RTP timestamp) so its size no greater than + // |max_size_to_retain_|. + void TruncateMapIfNeeded(); + + const size_t max_size_to_retain_; + RtcpEventMap rtcp_events_; + + // Ensures methods are only called on the main thread. + base::ThreadChecker thread_checker_; + + DISALLOW_COPY_AND_ASSIGN(SenderRtcpEventSubscriber); +}; + +} // namespace cast +} // namespace media + +#endif // MEDIA_CAST_RTCP_SENDER_RTCP_EVENT_SUBSCRIBER_H_ diff --git a/media/cast/rtcp/sender_rtcp_event_subscriber_unittest.cc b/media/cast/rtcp/sender_rtcp_event_subscriber_unittest.cc new file mode 100644 index 0000000..a9a24a1 --- /dev/null +++ b/media/cast/rtcp/sender_rtcp_event_subscriber_unittest.cc @@ -0,0 +1,122 @@ +// Copyright 2014 The Chromium Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +#include "base/memory/ref_counted.h" +#include "base/memory/scoped_ptr.h" +#include "base/test/simple_test_tick_clock.h" +#include "base/time/tick_clock.h" +#include "media/cast/cast_environment.h" +#include "media/cast/logging/logging_defines.h" +#include "media/cast/rtcp/sender_rtcp_event_subscriber.h" +#include "media/cast/test/fake_single_thread_task_runner.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace media { +namespace cast { + +namespace { + +const size_t kSizeThreshold = 10u; + +} // namespace + +class SenderRtcpEventSubscriberTest : public ::testing::Test { + protected: + SenderRtcpEventSubscriberTest() + : testing_clock_(new base::SimpleTestTickClock()), + task_runner_(new test::FakeSingleThreadTaskRunner(testing_clock_)), + cast_environment_(new CastEnvironment( + scoped_ptr(testing_clock_).Pass(), task_runner_, + task_runner_, task_runner_, task_runner_, task_runner_, + task_runner_, GetLoggingConfigWithRawEventsAndStatsEnabled())), + event_subscriber_( + new SenderRtcpEventSubscriber(task_runner_, kSizeThreshold)) { + cast_environment_->Logging()->AddRawEventSubscriber( + event_subscriber_.get()); + } + + virtual ~SenderRtcpEventSubscriberTest() { + cast_environment_->Logging()->RemoveRawEventSubscriber( + event_subscriber_.get()); + } + + base::SimpleTestTickClock* testing_clock_; // Owned by CastEnvironment. + scoped_refptr task_runner_; + scoped_refptr cast_environment_; + scoped_ptr event_subscriber_; +}; + +TEST_F(SenderRtcpEventSubscriberTest, InsertEntry) { + cast_environment_->Logging()->InsertFrameEvent(testing_clock_->NowTicks(), + kVideoFrameCaptured, 100u, 1u); + cast_environment_->Logging()->InsertFrameEvent(testing_clock_->NowTicks(), + kVideoFrameCaptured, 200u, 2u); + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kVideoFrameSentToEncoder, 100u, 1u); + cast_environment_->Logging()->InsertFrameEvent(testing_clock_->NowTicks(), + kVideoFrameEncoded, 100u, 1u); + cast_environment_->Logging()->InsertFrameEvent(testing_clock_->NowTicks(), + kVideoFrameEncoded, 300u, 3u); + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kVideoFrameSentToEncoder, 300u, 3u); + + RtcpEventMap events; + event_subscriber_->GetRtcpEventsAndReset(&events); + + ASSERT_EQ(3u, events.size()); + + RtcpEventMap::iterator it = events.begin(); + EXPECT_EQ(100u, it->first); + EXPECT_EQ(kVideoFrameEncoded, it->second.type); + + ++it; + EXPECT_EQ(200u, it->first); + EXPECT_EQ(kVideoFrameCaptured, it->second.type); + + ++it; + EXPECT_EQ(300u, it->first); + EXPECT_EQ(kVideoFrameEncoded, it->second.type); +} + +TEST_F(SenderRtcpEventSubscriberTest, MapReset) { + cast_environment_->Logging()->InsertFrameEvent(testing_clock_->NowTicks(), + kVideoFrameCaptured, 100u, 1u); + + RtcpEventMap events; + event_subscriber_->GetRtcpEventsAndReset(&events); + EXPECT_EQ(1u, events.size()); + + // Call again without any logging in between, should return empty map. + event_subscriber_->GetRtcpEventsAndReset(&events); + EXPECT_TRUE(events.empty()); +} + +TEST_F(SenderRtcpEventSubscriberTest, DropEventsWhenSizeExceeded) { + for (uint32 i = 1u; i <= 10u; ++i) { + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kVideoFrameCaptured, i * 10, i); + } + + RtcpEventMap events; + event_subscriber_->GetRtcpEventsAndReset(&events); + + ASSERT_EQ(10u, events.size()); + EXPECT_EQ(10u, events.begin()->first); + EXPECT_EQ(100u, events.rbegin()->first); + + for (uint32 i = 1u; i <= 11u; ++i) { + cast_environment_->Logging()->InsertFrameEvent( + testing_clock_->NowTicks(), kVideoFrameCaptured, i * 10, i); + } + + event_subscriber_->GetRtcpEventsAndReset(&events); + + // Event with RTP timestamp 10 should have been dropped when 110 is inserted. + ASSERT_EQ(10u, events.size()); + EXPECT_EQ(20u, events.begin()->first); + EXPECT_EQ(110u, events.rbegin()->first); +} + +} // namespace cast +} // namespace media diff --git a/media/cast/test/end2end_unittest.cc b/media/cast/test/end2end_unittest.cc index f2e62c6..1b88dec 100644 --- a/media/cast/test/end2end_unittest.cc +++ b/media/cast/test/end2end_unittest.cc @@ -11,7 +11,9 @@ #include +#include #include +#include #include "base/bind.h" #include "base/bind_helpers.h" @@ -23,6 +25,7 @@ #include "media/cast/cast_environment.h" #include "media/cast/cast_receiver.h" #include "media/cast/cast_sender.h" +#include "media/cast/logging/simple_event_subscriber.h" #include "media/cast/test/fake_single_thread_task_runner.h" #include "media/cast/test/utility/audio_utility.h" #include "media/cast/test/utility/video_utility.h" @@ -76,9 +79,60 @@ std::string ConvertFromBase16String(const std::string base_16) { // Dummy callback function that does nothing except to accept ownership of // |audio_bus| for destruction. void OwnThatAudioBus(scoped_ptr audio_bus) {} + void UpdateCastTransportStatus(transport::CastTransportStatus status) { EXPECT_EQ(status, transport::TRANSPORT_INITIALIZED); } + +// This is wrapped in a struct because it needs to be put into a std::map. +typedef struct { + int counter[kNumOfLoggingEvents]; +} LoggingEventCounts; + +// Constructs a map from each frame (RTP timestamp) to counts of each event +// type logged for that frame. +std::map GetEventCountForFrameEvents( + const std::vector& frame_events) { + std::map event_counter_for_frame; + for (std::vector::const_iterator it = frame_events.begin(); + it != frame_events.end(); ++it) { + std::map::iterator map_it = + event_counter_for_frame.find(it->rtp_timestamp); + if (map_it == event_counter_for_frame.end()) { + LoggingEventCounts new_counter; + memset(&new_counter, 0, sizeof(new_counter)); + ++(new_counter.counter[it->type]); + event_counter_for_frame.insert( + std::make_pair(it->rtp_timestamp, new_counter)); + } else { + ++(map_it->second.counter[it->type]); + } + } + return event_counter_for_frame; +} + +// Constructs a map from each packet (Packet ID) to counts of each event +// type logged for that packet. +std::map GetEventCountForPacketEvents( + const std::vector& packet_events) { + std::map event_counter_for_packet; + for (std::vector::const_iterator it = packet_events.begin(); + it != packet_events.end(); ++it) { + std::map::iterator map_it = + event_counter_for_packet.find(it->packet_id); + if (map_it == event_counter_for_packet.end()) { + LoggingEventCounts new_counter; + memset(&new_counter, 0, sizeof(new_counter)); + ++(new_counter.counter[it->type]); + event_counter_for_packet.insert( + std::make_pair(it->packet_id, new_counter)); + } else { + ++(map_it->second.counter[it->type]); + } + } + return event_counter_for_packet; +} + } // namespace // Class that sends the packet direct from sender into the receiver with the @@ -199,8 +253,7 @@ class TestReceiverAudioCallback return; // No more checks needed. EXPECT_NEAR(CountZeroCrossings(expected_audio_frame.audio_frame.samples), - CountZeroCrossings(audio_frame->samples), - 1); + CountZeroCrossings(audio_frame->samples), 1); } void CheckCodedPcmAudioFrame( @@ -238,8 +291,7 @@ class TestReceiverAudioCallback } EXPECT_NEAR(CountZeroCrossings(expected_audio_frame.audio_frame.samples), - CountZeroCrossings(output_audio_samples), - 1); + CountZeroCrossings(output_audio_samples), 1); } int number_times_called() const { return num_called_; } @@ -268,9 +320,7 @@ class TestReceiverVideoCallback TestReceiverVideoCallback() : num_called_(0) {} - void AddExpectedResult(int start_value, - int width, - int height, + void AddExpectedResult(int start_value, int width, int height, const base::TimeTicks& capture_time) { ExpectedVideoFrame expected_video_frame; expected_video_frame.start_value = start_value; @@ -309,7 +359,7 @@ class TestReceiverVideoCallback EXPECT_GE(I420PSNR(expected_I420_frame, video_frame), kVideoAcceptedPSNR); } - int number_times_called() { return num_called_; } + int number_times_called() const { return num_called_; } protected: virtual ~TestReceiverVideoCallback() {} @@ -321,13 +371,6 @@ class TestReceiverVideoCallback std::list expected_frame_; }; -CastLoggingConfig EnableCastLoggingConfig(bool sender) { - CastLoggingConfig config(sender); - config.enable_raw_data_collection = true; - config.enable_stats_data_collection = true; - return config; -} - // The actual test class, generate synthetic data for both audio and video and // send those through the sender and receiver and analyzes the result. class End2EndTest : public ::testing::Test { @@ -346,13 +389,15 @@ class End2EndTest : public ::testing::Test { task_runner_, task_runner_, task_runner_, - EnableCastLoggingConfig(true))), + GetLoggingConfigWithRawEventsAndStatsEnabled())), receiver_to_sender_(cast_environment_), sender_to_receiver_(cast_environment_), test_receiver_audio_callback_(new TestReceiverAudioCallback()), - test_receiver_video_callback_(new TestReceiverVideoCallback()) { + test_receiver_video_callback_(new TestReceiverVideoCallback()), + event_subscriber_(task_runner_) { testing_clock_->Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); + cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_); } void SetupConfig(transport::AudioCodec audio_codec, @@ -431,10 +476,7 @@ class End2EndTest : public ::testing::Test { &sender_to_receiver_)); cast_sender_.reset(CastSender::CreateCastSender( - cast_environment_, - audio_sender_config_, - video_sender_config_, - NULL, + cast_environment_, audio_sender_config_, video_sender_config_, NULL, base::Bind(&End2EndTest::InitializationResult, base::Unretained(this)), transport_sender_.get())); @@ -451,9 +493,12 @@ class End2EndTest : public ::testing::Test { kSoundVolume)); } - virtual ~End2EndTest() {} + virtual ~End2EndTest() { + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); + } virtual void TearDown() OVERRIDE { + cast_sender_.reset(); cast_receiver_.reset(); task_runner_->RunTasks(); @@ -512,6 +557,11 @@ class End2EndTest : public ::testing::Test { scoped_refptr test_receiver_video_callback_; scoped_ptr audio_bus_factory_; + + SimpleEventSubscriber event_subscriber_; + std::vector frame_events_; + std::vector packet_events_; + std::vector generic_events_; }; // Audio and video test without packet loss using raw PCM 16 audio "codec"; @@ -579,7 +629,6 @@ TEST_F(End2EndTest, DISABLED_LoopNoLossPcm16) { video_start++; } - std::cout << std::endl; RunTasks(2 * kFrameTimerMs + 1); // Empty the receiver pipeline. EXPECT_EQ(i - 1, test_receiver_audio_callback_->number_times_called()); @@ -856,7 +905,7 @@ TEST_F(End2EndTest, DropEveryOtherFrame3Buffers) { RunTasks(kFrameTimerMs); video_start++; } - std::cout << std::endl; + RunTasks(2 * kFrameTimerMs + 1); // Empty the pipeline. EXPECT_EQ(i / 2, test_receiver_video_callback_->number_times_called()); } @@ -999,8 +1048,8 @@ TEST_F(End2EndTest, VideoLogging) { Create(); int video_start = 1; - int i = 0; - for (; i < 1; ++i) { + const int num_frames = 1; + for (int i = 0; i < num_frames; ++i) { base::TimeTicks send_time = testing_clock_->NowTicks(); test_receiver_video_callback_->AddExpectedResult( video_start, @@ -1020,76 +1069,84 @@ TEST_F(End2EndTest, VideoLogging) { // Basic tests. RunTasks(2 * kFrameTimerMs + 1); // Empty the receiver pipeline. - EXPECT_EQ(i, test_receiver_video_callback_->number_times_called()); + int num_callbacks_called = + test_receiver_video_callback_->number_times_called(); + EXPECT_EQ(num_frames, num_callbacks_called); - // Sender logging tests. - LoggingImpl* sender_log = cast_environment_->Logging(); + RunTasks(750); // Make sure that we send a RTCP message with the log. + // Logging tests. + // Frame logging. // Verify that all frames and all required events were logged. - FrameRawMap frame_raw_log = sender_log->GetFrameRawData(); + event_subscriber_.GetFrameEventsAndReset(&frame_events_); + + // For each frame, count the number of events that occurred for each event + // for that frame. + std::map event_counter_for_frame = + GetEventCountForFrameEvents(frame_events_); + + // Verify that there are logs for expected number of frames. + EXPECT_EQ(num_frames, static_cast(event_counter_for_frame.size())); + + // Verify that each frame have the expected types of events logged. + for (std::map::iterator map_it = + event_counter_for_frame.begin(); + map_it != event_counter_for_frame.end(); ++map_it) { + int total_event_count_for_frame = 0; + for (int i = 0; i < kNumOfLoggingEvents; ++i) { + total_event_count_for_frame += map_it->second.counter[i]; + } - // Every frame should have only one entry. - EXPECT_EQ(static_cast(i), frame_raw_log.size()); - FrameRawMap::const_iterator frame_it = frame_raw_log.begin(); + int expected_event_count_for_frame = 0; - // Choose a video frame, and verify that all events were logged. - std::vector event_log = frame_it->second.type; - std::vector::iterator event_it; - event_it = - std::find(event_log.begin(), event_log.end(), kVideoFrameSentToEncoder); - EXPECT_TRUE(event_it != event_log.end()); - event_log.erase(event_it); + EXPECT_GT(map_it->second.counter[kVideoFrameSentToEncoder], 0); + expected_event_count_for_frame += + map_it->second.counter[kVideoFrameSentToEncoder]; - event_it = std::find(event_log.begin(), event_log.end(), kVideoFrameEncoded); - EXPECT_TRUE(event_it != event_log.end()); - event_log.erase(event_it); + EXPECT_GT(map_it->second.counter[kVideoFrameEncoded], 0); + expected_event_count_for_frame += + map_it->second.counter[kVideoFrameEncoded]; - event_it = std::find(event_log.begin(), event_log.end(), kVideoFrameReceived); - EXPECT_TRUE(event_it != event_log.end()); - event_log.erase(event_it); + EXPECT_GT(map_it->second.counter[kVideoFrameReceived], 0); + expected_event_count_for_frame += + map_it->second.counter[kVideoFrameReceived]; - event_it = std::find(event_log.begin(), event_log.end(), kVideoRenderDelay); - EXPECT_TRUE(event_it != event_log.end()); - event_log.erase(event_it); + EXPECT_GT(map_it->second.counter[kVideoRenderDelay], 0); + expected_event_count_for_frame += map_it->second.counter[kVideoRenderDelay]; - event_it = std::find(event_log.begin(), event_log.end(), kVideoFrameDecoded); - EXPECT_TRUE(event_it != event_log.end()); - event_log.erase(event_it); + EXPECT_GT(map_it->second.counter[kVideoFrameDecoded], 0); + expected_event_count_for_frame += + map_it->second.counter[kVideoFrameDecoded]; - // Verify that there were no other events logged with respect to this frame. - EXPECT_EQ(0u, event_log.size()); + // Verify that there were no other events logged with respect to this frame. + // (i.e. Total event count = expected event count) + EXPECT_EQ(total_event_count_for_frame, expected_event_count_for_frame); + } // Packet logging. // Verify that all packet related events were logged. - PacketRawMap packet_raw_log = sender_log->GetPacketRawData(); - // Every rtp_timestamp should have only one entry. - EXPECT_EQ(static_cast(i), packet_raw_log.size()); - PacketRawMap::const_iterator packet_it = packet_raw_log.begin(); - // Choose a packet, and verify that all events were logged. - event_log = (++(packet_it->second.packet_map.begin()))->second.type; - EXPECT_TRUE( - (std::find(event_log.begin(), event_log.end(), kVideoPacketReceived)) != - event_log.end()); - - RunTasks(750); // Make sure that we send a RTCP message with the log. - - // Receiver logging tests. - LoggingImpl* receiver_log = cast_environment_->Logging(); - - // Verify that all frames and all required events were logged. - frame_raw_log = receiver_log->GetFrameRawData(); - EXPECT_EQ(static_cast(i), frame_raw_log.size()); - frame_it = frame_raw_log.begin(); - - // Choose a video frame, and verify that all events were logged. - event_log = frame_it->second.type; - - event_it = std::find(event_log.begin(), event_log.end(), kVideoFrameEncoded); - EXPECT_TRUE(event_it != event_log.end()); + event_subscriber_.GetPacketEventsAndReset(&packet_events_); + std::map event_count_for_packet = + GetEventCountForPacketEvents(packet_events_); + + // Verify that each packet have the expected types of events logged. + for (std::map::iterator map_it = + event_count_for_packet.begin(); + map_it != event_count_for_packet.end(); ++map_it) { + int total_event_count_for_packet = 0; + for (int i = 0; i < kNumOfLoggingEvents; ++i) { + total_event_count_for_packet += map_it->second.counter[i]; + } - event_it = std::find(event_log.begin(), event_log.end(), kVideoRenderDelay); + int expected_event_count_for_packet = 0; + EXPECT_GT(map_it->second.counter[kVideoPacketReceived], 0); + expected_event_count_for_packet += + map_it->second.counter[kVideoPacketReceived]; - EXPECT_TRUE(event_it != event_log.end()); + // Verify that there were no other events logged with respect to this + // packet. (i.e. Total event count = expected event count) + EXPECT_EQ(total_event_count_for_packet, expected_event_count_for_packet); + } } // TODO(mikhal): Crashes on the bots. Re-enable. http://crbug.com/329563 @@ -1105,9 +1162,8 @@ TEST_F(End2EndTest, MAYBE_AudioLogging) { Create(); int audio_diff = kFrameTimerMs; - int i = 0; - - for (; i < 10; ++i) { + const int num_frames = 10; + for (int i = 0; i < num_frames; ++i) { int num_10ms_blocks = audio_diff / 10; audio_diff -= num_10ms_blocks * 10; base::TimeTicks send_time = testing_clock_->NowTicks(); @@ -1151,29 +1207,62 @@ TEST_F(End2EndTest, MAYBE_AudioLogging) { // Basic tests. RunTasks(2 * kFrameTimerMs + 1); // Empty the receiver pipeline. - EXPECT_EQ(i - 1, test_receiver_audio_callback_->number_times_called()); - EXPECT_EQ(i - 1, test_receiver_audio_callback_->number_times_called()); + + int num_times_called = test_receiver_audio_callback_->number_times_called(); + EXPECT_EQ(num_frames - 1, num_times_called); + // Logging tests. - LoggingImpl* sender_log = cast_environment_->Logging(); // Verify that all frames and all required events were logged. - FrameRawMap frame_raw_log = sender_log->GetFrameRawData(); - FrameRawMap::const_iterator frame_it = frame_raw_log.begin(); - // Choose a video frame, and verify that all events were logged. - std::vector event_log = frame_it->second.type; - EXPECT_TRUE( - (std::find(event_log.begin(), event_log.end(), kAudioFrameReceived)) != - event_log.end()); - EXPECT_TRUE( - (std::find(event_log.begin(), event_log.end(), kAudioFrameEncoded)) != - event_log.end()); - EXPECT_TRUE( - (std::find(event_log.begin(), event_log.end(), kAudioPlayoutDelay)) != - event_log.end()); - EXPECT_TRUE( - (std::find(event_log.begin(), event_log.end(), kAudioFrameDecoded)) != - event_log.end()); + event_subscriber_.GetFrameEventsAndReset(&frame_events_); + + // Construct a map from each frame (RTP timestamp) to a count of each event + // type logged for that frame. + std::map event_counter_for_frame = + GetEventCountForFrameEvents(frame_events_); + + // Verify that each frame have the expected types of events logged. + std::map::iterator map_it = + event_counter_for_frame.begin(); + + // TODO(imcheng): This only checks the first frame. This doesn't work + // properly for all frames for two reasons: + // 1. There is a loopback of kAudioPlayoutDelay and kAudioFrameDecoded events + // due to shared CastEnvironment between sender and + // receiver in the test setup. We will need to create separate CastEnvironment + // once again to fix this. + // 2. kAudioPlayoutDelay and kAudioFrameDecoded RTP timestamps aren't exactly + // aligned with those of kAudioFrameReceived and kAudioFrameEncoded. Note that + // these RTP timestamps are output from webrtc::AudioCodingModule which are + // different from RTP timestamps that the cast library generates during the + // encode step (and which are sent to receiver). The first frame just happen + // to be aligned. + int total_event_count_for_frame = 0; + for (int j = 0; j < kNumOfLoggingEvents; ++j) + total_event_count_for_frame += map_it->second.counter[j]; + + + int expected_event_count_for_frame = 0; + + EXPECT_GT(map_it->second.counter[kAudioFrameReceived], 0); + expected_event_count_for_frame += + map_it->second.counter[kAudioFrameReceived]; + + EXPECT_GT(map_it->second.counter[kAudioFrameEncoded], 0); + expected_event_count_for_frame += + map_it->second.counter[kAudioFrameEncoded]; + + // Note that this is a big positive number instead of just 1 due to loopback + // described in TODO above. + EXPECT_GT(map_it->second.counter[kAudioPlayoutDelay], 0); + expected_event_count_for_frame += + map_it->second.counter[kAudioPlayoutDelay]; + EXPECT_GT(map_it->second.counter[kAudioFrameDecoded], 0); + expected_event_count_for_frame += + map_it->second.counter[kAudioFrameDecoded]; + // Verify that there were no other events logged with respect to this frame. - EXPECT_EQ(4u, event_log.size()); + // (i.e. Total event count = expected event count) + EXPECT_EQ(total_event_count_for_frame, expected_event_count_for_frame); } // TODO(pwestin): Add repeatable packet loss test. diff --git a/media/cast/video_receiver/video_receiver.cc b/media/cast/video_receiver/video_receiver.cc index 172964a..2862b22 100644 --- a/media/cast/video_receiver/video_receiver.cc +++ b/media/cast/video_receiver/video_receiver.cc @@ -11,18 +11,32 @@ #include "base/message_loop/message_loop.h" #include "media/cast/cast_defines.h" #include "media/cast/framer/framer.h" +#include "media/cast/rtcp/receiver_rtcp_event_subscriber.h" #include "media/cast/rtcp/rtcp_sender.h" #include "media/cast/video_receiver/video_decoder.h" -namespace media { -namespace cast { +namespace { + +using media::cast::kMaxIpPacketSize; +using media::cast::kRtcpCastLogHeaderSize; +using media::cast::kRtcpReceiverEventLogSize; -const int64 kMinSchedulingDelayMs = 1; +static const int64 kMinSchedulingDelayMs = 1; static const int64 kMinTimeBetweenOffsetUpdatesMs = 2000; static const int kTimeOffsetFilter = 8; static const int64_t kMinProcessIntervalMs = 5; +// This is an upper bound on number of events that can fit into a single RTCP +// packet. +static const int64 kMaxEventSubscriberEntries = + (kMaxIpPacketSize - kRtcpCastLogHeaderSize) / kRtcpReceiverEventLogSize; + +} // namespace + +namespace media { +namespace cast { + // Local implementation of RtpData (defined in rtp_rtcp_defines.h). // Used to pass payload data into the video receiver. class LocalRtpVideoData : public RtpData { @@ -49,8 +63,7 @@ class LocalRtpVideoData : public RtpData { class LocalRtpVideoFeedback : public RtpPayloadFeedback { public: explicit LocalRtpVideoFeedback(VideoReceiver* video_receiver) - : video_receiver_(video_receiver) { - } + : video_receiver_(video_receiver) {} virtual void CastFeedback(const RtcpCastMessage& cast_message) OVERRIDE { video_receiver_->CastFeedback(cast_message); @@ -65,17 +78,14 @@ class LocalRtpVideoFeedback : public RtpPayloadFeedback { class LocalRtpReceiverStatistics : public RtpReceiverStatistics { public: explicit LocalRtpReceiverStatistics(RtpReceiver* rtp_receiver) - : rtp_receiver_(rtp_receiver) { - } + : rtp_receiver_(rtp_receiver) {} virtual void GetStatistics(uint8* fraction_lost, uint32* cumulative_lost, // 24 bits valid. uint32* extended_high_sequence_number, uint32* jitter) OVERRIDE { - rtp_receiver_->GetStatistics(fraction_lost, - cumulative_lost, - extended_high_sequence_number, - jitter); + rtp_receiver_->GetStatistics(fraction_lost, cumulative_lost, + extended_high_sequence_number, jitter); } private: @@ -87,6 +97,11 @@ VideoReceiver::VideoReceiver( const VideoReceiverConfig& video_config, transport::PacedPacketSender* const packet_sender) : cast_environment_(cast_environment), + event_subscriber_( + cast_environment->GetMessageSingleThreadTaskRunnerForThread( + CastEnvironment::MAIN), + kMaxEventSubscriberEntries, + ReceiverRtcpEventSubscriber::kVideoEventSubscriber), codec_(video_config.codec), target_delay_delta_( base::TimeDelta::FromMilliseconds(video_config.rtp_max_delay_ms)), @@ -112,25 +127,23 @@ VideoReceiver::VideoReceiver( video_config.incoming_ssrc, video_config.decoder_faster_than_max_frame_rate, max_unacked_frames)); + if (!video_config.use_external_decoder) { video_decoder_.reset(new VideoDecoder(video_config, cast_environment)); } - rtcp_.reset(new Rtcp( - cast_environment_, - NULL, - NULL, - packet_sender, - NULL, - rtp_video_receiver_statistics_.get(), - video_config.rtcp_mode, - base::TimeDelta::FromMilliseconds(video_config.rtcp_interval), - video_config.feedback_ssrc, - video_config.incoming_ssrc, - video_config.rtcp_c_name)); + rtcp_.reset( + new Rtcp(cast_environment_, NULL, NULL, packet_sender, NULL, + rtp_video_receiver_statistics_.get(), video_config.rtcp_mode, + base::TimeDelta::FromMilliseconds(video_config.rtcp_interval), + video_config.feedback_ssrc, video_config.incoming_ssrc, + video_config.rtcp_c_name)); + cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_); } -VideoReceiver::~VideoReceiver() {} +VideoReceiver::~VideoReceiver() { + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); +} void VideoReceiver::InitializeTimers() { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); @@ -170,9 +183,10 @@ void VideoReceiver::DecodeVideoFrameThread( DCHECK(video_decoder_); if (!(video_decoder_->DecodeVideoFrame(encoded_frame.get(), render_time, - frame_decoded_callback))) { + frame_decoded_callback))) { // This will happen if we decide to decode but not show a frame. - cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, + cast_environment_->PostTask( + CastEnvironment::MAIN, FROM_HERE, base::Bind(&VideoReceiver::GetRawVideoFrame, base::Unretained(this), frame_decoded_callback)); } @@ -264,12 +278,13 @@ bool VideoReceiver::PullEncodedVideoFrame( // will wait for 2 to arrive, however if 2 never show up this timer will hit // and we will pull out frame 3 for decoding and rendering. base::TimeDelta time_until_release = time_until_render - min_wait_delta; - cast_environment_->PostDelayedTask(CastEnvironment::MAIN, FROM_HERE, + cast_environment_->PostDelayedTask( + CastEnvironment::MAIN, FROM_HERE, base::Bind(&VideoReceiver::PlayoutTimeout, weak_factory_.GetWeakPtr()), time_until_release); VLOG(1) << "Wait before releasing frame " - << static_cast((*encoded_frame)->frame_id) - << " time " << time_until_release.InMilliseconds(); + << static_cast((*encoded_frame)->frame_id) << " time " + << time_until_release.InMilliseconds(); return false; } @@ -282,8 +297,7 @@ bool VideoReceiver::PullEncodedVideoFrame( << static_cast((*encoded_frame)->frame_id) << " time_until_render:" << time_until_render.InMilliseconds(); } else { - VLOG(1) << "Show frame " - << static_cast((*encoded_frame)->frame_id) + VLOG(1) << "Show frame " << static_cast((*encoded_frame)->frame_id) << " time_until_render:" << time_until_render.InMilliseconds(); } // We have a copy of the frame, release this one. @@ -321,7 +335,8 @@ void VideoReceiver::PlayoutTimeout() { if (!queued_encoded_callbacks_.empty()) { VideoFrameEncodedCallback callback = queued_encoded_callbacks_.front(); queued_encoded_callbacks_.pop_front(); - cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, + cast_environment_->PostTask( + CastEnvironment::MAIN, FROM_HERE, base::Bind(callback, base::Passed(&encoded_frame), render_time)); } } @@ -352,22 +367,20 @@ base::TimeTicks VideoReceiver::GetRenderTime(base::TimeTicks now, // Time to update the time_offset. base::TimeDelta time_offset = time_incoming_packet_ - rtp_timestamp_in_ticks; - time_offset_ = ((kTimeOffsetFilter - 1) * time_offset_ + time_offset) - / kTimeOffsetFilter; + time_offset_ = ((kTimeOffsetFilter - 1) * time_offset_ + time_offset) / + kTimeOffsetFilter; } } // Reset |time_incoming_packet_updated_| to enable a future measurement. time_incoming_packet_updated_ = false; - if (!rtcp_->RtpTimestampInSenderTime(kVideoFrequency, - rtp_timestamp, + if (!rtcp_->RtpTimestampInSenderTime(kVideoFrequency, rtp_timestamp, &rtp_timestamp_in_ticks)) { // This can fail if we have not received any RTCP packets in a long time. return now; } base::TimeTicks render_time = rtp_timestamp_in_ticks + time_offset_ + target_delay_delta_; - if (last_render_time_ > render_time) - render_time = last_render_time_; + if (last_render_time_ > render_time) render_time = last_render_time_; last_render_time_ = render_time; return render_time; } @@ -387,27 +400,29 @@ void VideoReceiver::IncomingParsedRtpPacket(const uint8* payload_data, DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); base::TimeTicks now = cast_environment_->Clock()->NowTicks(); - if (time_incoming_packet_.is_null() || now - time_incoming_packet_ > - base::TimeDelta::FromMilliseconds(kMinTimeBetweenOffsetUpdatesMs)) { + if (time_incoming_packet_.is_null() || + now - time_incoming_packet_ > + base::TimeDelta::FromMilliseconds(kMinTimeBetweenOffsetUpdatesMs)) { if (time_incoming_packet_.is_null()) InitializeTimers(); incoming_rtp_timestamp_ = rtp_header.webrtc.header.timestamp; time_incoming_packet_ = now; time_incoming_packet_updated_ = true; } - cast_environment_->Logging()->InsertPacketEvent(now, kVideoPacketReceived, - rtp_header.webrtc.header.timestamp, rtp_header.frame_id, - rtp_header.packet_id, rtp_header.max_packet_id, payload_size); + cast_environment_->Logging()->InsertPacketEvent( + now, kVideoPacketReceived, rtp_header.webrtc.header.timestamp, + rtp_header.frame_id, rtp_header.packet_id, rtp_header.max_packet_id, + payload_size); bool duplicate = false; - bool complete = framer_->InsertPacket(payload_data, payload_size, rtp_header, - &duplicate); + bool complete = + framer_->InsertPacket(payload_data, payload_size, rtp_header, &duplicate); if (duplicate) { - cast_environment_->Logging()->InsertPacketEvent(now, - kDuplicatePacketReceived, - rtp_header.webrtc.header.timestamp, rtp_header.frame_id, - rtp_header.packet_id, rtp_header.max_packet_id, payload_size); + cast_environment_->Logging()->InsertPacketEvent( + now, kDuplicatePacketReceived, rtp_header.webrtc.header.timestamp, + rtp_header.frame_id, rtp_header.packet_id, rtp_header.max_packet_id, + payload_size); // Duplicate packets are ignored. return; } @@ -417,8 +432,8 @@ void VideoReceiver::IncomingParsedRtpPacket(const uint8* payload_data, VideoFrameEncodedCallback callback = queued_encoded_callbacks_.front(); queued_encoded_callbacks_.pop_front(); cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, - base::Bind(&VideoReceiver::GetEncodedVideoFrame, - weak_factory_.GetWeakPtr(), callback)); + base::Bind(&VideoReceiver::GetEncodedVideoFrame, + weak_factory_.GetWeakPtr(), callback)); } // Send a cast feedback message. Actual message created in the framer (cast @@ -427,38 +442,13 @@ void VideoReceiver::CastFeedback(const RtcpCastMessage& cast_message) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); RtcpReceiverLogMessage receiver_log; - VideoRtcpRawMap video_logs = - cast_environment_->Logging()->GetAndResetVideoRtcpRawData(); - - while (!video_logs.empty()) { - // TODO(hclam): Avoid calling begin() within a loop. - VideoRtcpRawMap::iterator it = video_logs.begin(); - uint32 rtp_timestamp = it->first; - std::pair - frame_range = video_logs.equal_range(rtp_timestamp); - - RtcpReceiverFrameLogMessage frame_log(rtp_timestamp); - - VideoRtcpRawMap::const_iterator event_it = frame_range.first; - for (; event_it != frame_range.second; ++event_it) { - if (!RtcpSender::IsReceiverEvent(event_it->second.type)) - continue; - RtcpReceiverEventLogMessage event_log_message; - event_log_message.type = event_it->second.type; - event_log_message.event_timestamp = event_it->second.timestamp; - event_log_message.delay_delta = event_it->second.delay_delta; - event_log_message.packet_id = event_it->second.packet_id; - frame_log.event_log_messages_.push_back(event_log_message); - } - receiver_log.push_back(frame_log); - video_logs.erase(rtp_timestamp); - } + event_subscriber_.GetReceiverLogMessageAndReset(&receiver_log); + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); cast_environment_->Logging()->InsertGenericEvent(now, kVideoAckSent, - cast_message.ack_frame_id_); + cast_message.ack_frame_id_); rtcp_->SendRtcpFromRtpReceiver(&cast_message, &receiver_log); - time_last_sent_cast_message_= now; } // Cast messages should be sent within a maximum interval. Schedule a call @@ -468,13 +458,15 @@ void VideoReceiver::ScheduleNextCastMessage() { base::TimeTicks send_time; framer_->TimeToSendNextCastMessage(&send_time); - base::TimeDelta time_to_send = send_time - - cast_environment_->Clock()->NowTicks(); - time_to_send = std::max(time_to_send, - base::TimeDelta::FromMilliseconds(kMinSchedulingDelayMs)); - cast_environment_->PostDelayedTask(CastEnvironment::MAIN, FROM_HERE, + base::TimeDelta time_to_send = + send_time - cast_environment_->Clock()->NowTicks(); + time_to_send = std::max( + time_to_send, base::TimeDelta::FromMilliseconds(kMinSchedulingDelayMs)); + cast_environment_->PostDelayedTask( + CastEnvironment::MAIN, FROM_HERE, base::Bind(&VideoReceiver::SendNextCastMessage, - weak_factory_.GetWeakPtr()), time_to_send); + weak_factory_.GetWeakPtr()), + time_to_send); } void VideoReceiver::SendNextCastMessage() { @@ -487,14 +479,16 @@ void VideoReceiver::SendNextCastMessage() { void VideoReceiver::ScheduleNextRtcpReport() { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); base::TimeDelta time_to_next = rtcp_->TimeToSendNextRtcpReport() - - cast_environment_->Clock()->NowTicks(); + cast_environment_->Clock()->NowTicks(); - time_to_next = std::max(time_to_next, - base::TimeDelta::FromMilliseconds(kMinSchedulingDelayMs)); + time_to_next = std::max( + time_to_next, base::TimeDelta::FromMilliseconds(kMinSchedulingDelayMs)); - cast_environment_->PostDelayedTask(CastEnvironment::MAIN, FROM_HERE, + cast_environment_->PostDelayedTask( + CastEnvironment::MAIN, FROM_HERE, base::Bind(&VideoReceiver::SendNextRtcpReport, - weak_factory_.GetWeakPtr()), time_to_next); + weak_factory_.GetWeakPtr()), + time_to_next); } void VideoReceiver::SendNextRtcpReport() { diff --git a/media/cast/video_receiver/video_receiver.h b/media/cast/video_receiver/video_receiver.h index 414e9b7..c4a0cdf 100644 --- a/media/cast/video_receiver/video_receiver.h +++ b/media/cast/video_receiver/video_receiver.h @@ -16,6 +16,7 @@ #include "media/cast/cast_config.h" #include "media/cast/cast_environment.h" #include "media/cast/cast_receiver.h" +#include "media/cast/rtcp/receiver_rtcp_event_subscriber.h" #include "media/cast/rtcp/rtcp.h" #include "media/cast/rtp_receiver/rtp_receiver.h" #include "media/cast/rtp_receiver/rtp_receiver_defines.h" @@ -23,6 +24,7 @@ namespace media { namespace cast { + class Framer; class LocalRtpVideoData; class LocalRtpVideoFeedback; @@ -51,8 +53,7 @@ class VideoReceiver : public base::NonThreadSafe, void IncomingPacket(scoped_ptr packet); protected: - void IncomingParsedRtpPacket(const uint8* payload_data, - size_t payload_size, + void IncomingParsedRtpPacket(const uint8* payload_data, size_t payload_size, const RtpCastHeader& rtp_header); void DecodeVideoFrameThread( @@ -98,6 +99,11 @@ class VideoReceiver : public base::NonThreadSafe, scoped_ptr video_decoder_; scoped_refptr cast_environment_; + + // Subscribes to raw events. + // Processes raw audio events to be sent over to the cast sender via RTCP. + ReceiverRtcpEventSubscriber event_subscriber_; + scoped_ptr framer_; const transport::VideoCodec codec_; base::TimeDelta target_delay_delta_; @@ -107,7 +113,6 @@ class VideoReceiver : public base::NonThreadSafe, RtpReceiver rtp_receiver_; scoped_ptr rtcp_; scoped_ptr rtp_video_receiver_statistics_; - base::TimeTicks time_last_sent_cast_message_; base::TimeDelta time_offset_; // Sender-receiver offset estimation. transport::TransportEncryptionHandler decryptor_; std::list queued_encoded_callbacks_; diff --git a/media/cast/video_sender/video_sender.cc b/media/cast/video_sender/video_sender.cc index a390a44..3081422 100644 --- a/media/cast/video_sender/video_sender.cc +++ b/media/cast/video_sender/video_sender.cc @@ -10,6 +10,8 @@ #include "base/logging.h" #include "base/message_loop/message_loop.h" #include "media/cast/cast_defines.h" +#include "media/cast/rtcp/rtcp_defines.h" +#include "media/cast/rtcp/sender_rtcp_event_subscriber.h" #include "media/cast/transport/cast_transport_config.h" #include "media/cast/video_sender/external_video_encoder.h" #include "media/cast/video_sender/video_encoder_impl.h" @@ -19,6 +21,11 @@ namespace cast { const int64 kMinSchedulingDelayMs = 1; +// This is the maxmimum number of sender frame log messages that can fit in a +// single RTCP packet. +const int64 kMaxEventSubscriberEntries = + (kMaxIpPacketSize - kRtcpCastLogHeaderSize) / kRtcpSenderFrameLogSize; + class LocalRtcpVideoSenderFeedback : public RtcpSenderFeedback { public: explicit LocalRtcpVideoSenderFeedback(VideoSender* video_sender) @@ -87,6 +94,10 @@ VideoSender::VideoSender( max_frame_rate_(video_config.max_frame_rate), cast_environment_(cast_environment), transport_sender_(transport_sender), + event_subscriber_( + cast_environment_->GetMessageSingleThreadTaskRunnerForThread( + CastEnvironment::MAIN), + kMaxEventSubscriberEntries), rtcp_feedback_(new LocalRtcpVideoSenderFeedback(this)), last_acked_frame_id_(-1), last_sent_frame_id_(-1), @@ -94,8 +105,7 @@ VideoSender::VideoSender( last_skip_count_(0), congestion_control_(cast_environment->Clock(), video_config.congestion_control_back_off, - video_config.max_bitrate, - video_config.min_bitrate, + video_config.max_bitrate, video_config.min_bitrate, video_config.start_bitrate), initialized_(false), weak_factory_(this) { @@ -132,13 +142,15 @@ VideoSender::VideoSender( // TODO(pwestin): pass cast_initialization to |video_encoder_| // and remove this call. - cast_environment->PostTask( - CastEnvironment::MAIN, - FROM_HERE, + cast_environment_->PostTask( + CastEnvironment::MAIN, FROM_HERE, base::Bind(initialization_status, STATUS_INITIALIZED)); + cast_environment_->Logging()->AddRawEventSubscriber(&event_subscriber_); } -VideoSender::~VideoSender() {} +VideoSender::~VideoSender() { + cast_environment_->Logging()->RemoveRawEventSubscriber(&event_subscriber_); +} void VideoSender::InitializeTimers() { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); @@ -230,38 +242,40 @@ void VideoSender::SendRtcpReport() { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); transport::RtcpSenderLogMessage sender_log_message; - VideoRtcpRawMap video_logs = - cast_environment_->Logging()->GetAndResetVideoRtcpRawData(); - - while (!video_logs.empty()) { - // TODO(hclam): Avoid calling begin() within a loop. - VideoRtcpRawMap::iterator it = video_logs.begin(); - uint32 rtp_timestamp = it->first; - - transport::RtcpSenderFrameLogMessage frame_message; - frame_message.rtp_timestamp = rtp_timestamp; - frame_message.frame_status = transport::kRtcpSenderFrameStatusUnknown; - bool ignore_event = false; - - switch (it->second.type) { - case kVideoFrameCaptured: - frame_message.frame_status = - transport::kRtcpSenderFrameStatusDroppedByFlowControl; - break; - case kVideoFrameSentToEncoder: - frame_message.frame_status = - transport::kRtcpSenderFrameStatusDroppedByEncoder; - break; - case kVideoFrameEncoded: - frame_message.frame_status = - transport::kRtcpSenderFrameStatusSentToNetwork; - break; - default: - ignore_event = true; - } - video_logs.erase(rtp_timestamp); - if (!ignore_event) + RtcpEventMap rtcp_events; + event_subscriber_.GetRtcpEventsAndReset(&rtcp_events); + + for (RtcpEventMap::iterator it = rtcp_events.begin(); it != rtcp_events.end(); + ++it) { + CastLoggingEvent event_type = it->second.type; + if (event_type == kVideoFrameCaptured || + event_type == kVideoFrameSentToEncoder || + event_type == kVideoFrameEncoded) { + transport::RtcpSenderFrameLogMessage frame_message; + frame_message.rtp_timestamp = it->first; + switch (event_type) { + case kVideoFrameCaptured: + frame_message.frame_status = + transport::kRtcpSenderFrameStatusDroppedByFlowControl; + break; + case kVideoFrameSentToEncoder: + frame_message.frame_status = + transport::kRtcpSenderFrameStatusDroppedByEncoder; + break; + case kVideoFrameEncoded: + frame_message.frame_status = + transport::kRtcpSenderFrameStatusSentToNetwork; + break; + default: + NOTREACHED(); + break; + } sender_log_message.push_back(frame_message); + } else { + // This shouldn't happen because RtcpEventMap isn't supposed to contain + // other event types. + NOTREACHED() << "Got unknown event type in RtcpEventMap: " << event_type; + } } rtcp_->SendRtcpFromRtpSender(sender_log_message); diff --git a/media/cast/video_sender/video_sender.h b/media/cast/video_sender/video_sender.h index 15688fe..c20ed64 100644 --- a/media/cast/video_sender/video_sender.h +++ b/media/cast/video_sender/video_sender.h @@ -16,6 +16,7 @@ #include "media/cast/cast_environment.h" #include "media/cast/congestion_control/congestion_control.h" #include "media/cast/rtcp/rtcp.h" +#include "media/cast/rtcp/sender_rtcp_event_subscriber.h" #include "media/filters/gpu_video_accelerator_factories.h" #include "media/video/video_encode_accelerator.h" @@ -24,10 +25,10 @@ class VideoFrame; namespace cast { -class VideoEncoder; class LocalRtcpVideoSenderFeedback; class LocalRtpVideoSenderStatistics; class LocalVideoEncoderCallback; +class VideoEncoder; namespace transport { class CastTransportSender; @@ -110,6 +111,11 @@ class VideoSender : public base::NonThreadSafe, scoped_refptr cast_environment_; transport::CastTransportSender* const transport_sender_; + + // Subscribes to raw events. + // Processes raw audio events to be sent over to the cast receiver via RTCP. + SenderRtcpEventSubscriber event_subscriber_; + scoped_ptr rtcp_feedback_; scoped_ptr rtp_video_sender_statistics_; scoped_ptr video_encoder_; -- cgit v1.1