diff options
author | mikhal@google.com <mikhal@google.com@0039d316-1c4b-4281-b951-d872f2087c98> | 2013-11-19 19:51:56 +0000 |
---|---|---|
committer | mikhal@google.com <mikhal@google.com@0039d316-1c4b-4281-b951-d872f2087c98> | 2013-11-19 19:51:56 +0000 |
commit | 58bc947c9f63ecd1070ef4dffdd88e7658615258 (patch) | |
tree | a3f52f698f023718abeda63d41c0962b2343c3b4 /media | |
parent | 6787c5d9afc8fe956e8a85a07a1a85d7954f5fb0 (diff) | |
download | chromium_src-58bc947c9f63ecd1070ef4dffdd88e7658615258.zip chromium_src-58bc947c9f63ecd1070ef4dffdd88e7658615258.tar.gz chromium_src-58bc947c9f63ecd1070ef4dffdd88e7658615258.tar.bz2 |
Incorporating logging into Cast:
1. Adding logging to CastEnvironment.
2. Actually triggering logging within the cast library.
3. Adding thread checks.
4. Removing trace calls outside of the logging class.
Open issues:
1.Use of rtp_timestamp and frame id is not consistent.
In addition, the AudioBus does not include these values.
2. There is a pending cl to switch frame_id to int. This cl does not include that.
3. There are a few more places to add logging.
As this cl is already big enough, all of the above will come in a follow-up cl.
Review URL: https://codereview.chromium.org/69603002
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@236034 0039d316-1c4b-4281-b951-d872f2087c98
Diffstat (limited to 'media')
48 files changed, 383 insertions, 199 deletions
diff --git a/media/base/audio_bus.h b/media/base/audio_bus.h index dbb49ca..d1106f5 100644 --- a/media/base/audio_bus.h +++ b/media/base/audio_bus.h @@ -47,7 +47,6 @@ class MEDIA_EXPORT AudioBus { static scoped_ptr<AudioBus> WrapMemory(int channels, int frames, void* data); static scoped_ptr<AudioBus> WrapMemory(const AudioParameters& params, void* data); - // Returns the required memory size to use the WrapMemory() method. static int CalculateMemorySize(const AudioParameters& params); // Calculates the required size for an AudioBus given the number of channels diff --git a/media/cast/audio_receiver/audio_receiver.cc b/media/cast/audio_receiver/audio_receiver.cc index 3b6361d..b5b9acf 100644 --- a/media/cast/audio_receiver/audio_receiver.cc +++ b/media/cast/audio_receiver/audio_receiver.cc @@ -119,7 +119,7 @@ AudioReceiver::AudioReceiver(scoped_refptr<CastEnvironment> 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->Clock(), + rtcp_.reset(new Rtcp(cast_environment, NULL, packet_sender, NULL, @@ -142,6 +142,10 @@ void AudioReceiver::InitializeTimers() { void AudioReceiver::IncomingParsedRtpPacket(const uint8* payload_data, size_t payload_size, const RtpCastHeader& rtp_header) { + cast_environment_->Logging()->InsertPacketEvent(kPacketReceived, + 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. DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); if (time_first_incoming_packet_.is_null()) { @@ -216,6 +220,10 @@ void AudioReceiver::DecodeAudioFrameThread( base::TimeTicks now = cast_environment_->Clock()->NowTicks(); base::TimeTicks playout_time; playout_time = GetPlayoutTime(now, rtp_timestamp); + base::TimeDelta diff = playout_time - now; + + cast_environment_->Logging()->InsertFrameEvent(kAudioPlayoutDelay, + rtp_timestamp, diff.InMilliseconds()); // Frame is ready - Send back to the main thread. cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, diff --git a/media/cast/audio_receiver/audio_receiver_unittest.cc b/media/cast/audio_receiver/audio_receiver_unittest.cc index 474e8b2..427a832 100644 --- a/media/cast/audio_receiver/audio_receiver_unittest.cc +++ b/media/cast/audio_receiver/audio_receiver_unittest.cc @@ -77,7 +77,8 @@ class AudioReceiverTest : public ::testing::Test { base::TimeDelta::FromMilliseconds(kStartMillisecond)); task_runner_ = new test::FakeTaskRunner(&testing_clock_); cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_, - task_runner_, task_runner_, task_runner_, task_runner_); + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig()); test_audio_encoder_callback_ = new TestAudioEncoderCallback(); } diff --git a/media/cast/audio_sender/audio_encoder_unittest.cc b/media/cast/audio_sender/audio_encoder_unittest.cc index 20f9edb..d721f71 100644 --- a/media/cast/audio_sender/audio_encoder_unittest.cc +++ b/media/cast/audio_sender/audio_encoder_unittest.cc @@ -97,7 +97,8 @@ class AudioEncoderTest : public ::testing::TestWithParam<TestScenario> { virtual void SetUp() { task_runner_ = new test::FakeTaskRunner(&testing_clock_); cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_, - task_runner_, task_runner_, task_runner_, task_runner_); + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig()); } virtual ~AudioEncoderTest() {} diff --git a/media/cast/audio_sender/audio_sender.cc b/media/cast/audio_sender/audio_sender.cc index e1c5bc4..66133f1 100644 --- a/media/cast/audio_sender/audio_sender.cc +++ b/media/cast/audio_sender/audio_sender.cc @@ -10,6 +10,7 @@ #include "crypto/encryptor.h" #include "crypto/symmetric_key.h" #include "media/cast/audio_sender/audio_encoder.h" +#include "media/cast/cast_environment.h" #include "media/cast/rtcp/rtcp.h" #include "media/cast/rtp_sender/rtp_sender.h" @@ -56,12 +57,12 @@ AudioSender::AudioSender(scoped_refptr<CastEnvironment> cast_environment, const AudioSenderConfig& audio_config, PacedPacketSender* const paced_packet_sender) : cast_environment_(cast_environment), - rtp_sender_(cast_environment->Clock(), &audio_config, NULL, + rtp_sender_(cast_environment, &audio_config, NULL, paced_packet_sender), rtcp_feedback_(new LocalRtcpAudioSenderFeedback(this)), rtp_audio_sender_statistics_( new LocalRtpSenderStatistics(&rtp_sender_)), - rtcp_(cast_environment->Clock(), + rtcp_(cast_environment, rtcp_feedback_.get(), paced_packet_sender, rtp_audio_sender_statistics_.get(), diff --git a/media/cast/audio_sender/audio_sender_unittest.cc b/media/cast/audio_sender/audio_sender_unittest.cc index 92f51a3..5b632bf 100644 --- a/media/cast/audio_sender/audio_sender_unittest.cc +++ b/media/cast/audio_sender/audio_sender_unittest.cc @@ -34,7 +34,8 @@ class AudioSenderTest : public ::testing::Test { virtual void SetUp() { task_runner_ = new test::FakeTaskRunner(&testing_clock_); cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_, - task_runner_, task_runner_, task_runner_, task_runner_); + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig()); audio_config_.codec = kOpus; audio_config_.use_external_encoder = false; audio_config_.frequency = kDefaultAudioSamplingRate; diff --git a/media/cast/cast.gyp b/media/cast/cast.gyp index e9a7461..520d830 100644 --- a/media/cast/cast.gyp +++ b/media/cast/cast.gyp @@ -14,11 +14,23 @@ 'include_dirs': [ '<(DEPTH)/', ], + 'dependencies': [ + '<(DEPTH)/base/base.gyp:base', + # '<(DEPTH)/base/base.gyp:test_support_base', + ], 'sources': [ 'cast_config.cc', 'cast_config.h', 'cast_environment.cc', 'cast_environment.h', + 'logging/logging_defines.cc', + 'logging/logging_defines.h', + 'logging/logging_impl.cc', + 'logging/logging_impl.h', + 'logging/logging_raw.cc', + 'logging/logging_raw.h', + 'logging/logging_stats.cc', + 'logging/logging_stats.h', ], # source }, ], # targets, @@ -32,7 +44,6 @@ 'cast_config', 'cast_receiver.gyp:cast_receiver', 'cast_sender.gyp:cast_sender', - 'logging/logging.gyp:cast_logging', 'test/utility/utility.gyp:cast_test_utility', '<(DEPTH)/base/base.gyp:run_all_unittests', '<(DEPTH)/crypto/crypto.gyp:crypto', diff --git a/media/cast/cast_defines.h b/media/cast/cast_defines.h index a49ce20..5eff0d7 100644 --- a/media/cast/cast_defines.h +++ b/media/cast/cast_defines.h @@ -186,6 +186,13 @@ inline std::string GetAesNonce(uint32 frame_id, const std::string& iv_mask) { return aes_nonce; } +inline uint32 GetVideoRtpTimestamp(const base::TimeTicks& time_ticks) { + base::TimeTicks zero_time; + base::TimeDelta recorded_delta = time_ticks - zero_time; + // Timestamp is in 90 KHz for video. + return static_cast<uint32>(recorded_delta.InMilliseconds() * 90); +} + } // namespace cast } // namespace media diff --git a/media/cast/cast_environment.cc b/media/cast/cast_environment.cc index dddec16..be636bb 100644 --- a/media/cast/cast_environment.cc +++ b/media/cast/cast_environment.cc @@ -17,13 +17,15 @@ CastEnvironment::CastEnvironment( scoped_refptr<TaskRunner> audio_encode_thread_proxy, scoped_refptr<TaskRunner> audio_decode_thread_proxy, scoped_refptr<TaskRunner> video_encode_thread_proxy, - scoped_refptr<TaskRunner> video_decode_thread_proxy) + scoped_refptr<TaskRunner> video_decode_thread_proxy, + const CastLoggingConfig& config) : clock_(clock), main_thread_proxy_(main_thread_proxy), audio_encode_thread_proxy_(audio_encode_thread_proxy), audio_decode_thread_proxy_(audio_decode_thread_proxy), video_encode_thread_proxy_(video_encode_thread_proxy), - video_decode_thread_proxy_(video_decode_thread_proxy) { + video_decode_thread_proxy_(video_decode_thread_proxy), + logging_(new LoggingImpl(clock, main_thread_proxy, config)) { DCHECK(main_thread_proxy) << "Main thread required"; } @@ -62,7 +64,7 @@ scoped_refptr<TaskRunner> CastEnvironment::GetMessageTaskRunnerForThread( case CastEnvironment::VIDEO_DECODER: return video_decode_thread_proxy_; default: - NOTREACHED() << "Invalid Thread ID."; + NOTREACHED() << "Invalid Thread identifier"; return NULL; } } @@ -80,14 +82,20 @@ bool CastEnvironment::CurrentlyOn(ThreadId identifier) { case CastEnvironment::VIDEO_DECODER: return video_decode_thread_proxy_->RunsTasksOnCurrentThread(); default: - NOTREACHED() << "Wrong thread identifier"; + NOTREACHED() << "Invalid thread identifier"; return false; } } -base::TickClock* CastEnvironment::Clock() { +base::TickClock* CastEnvironment::Clock() const { return clock_; } +LoggingImpl* CastEnvironment::Logging() { + DCHECK(CurrentlyOn(CastEnvironment::MAIN)) << + "Must be called from main thread"; + return logging_.get(); +} + } // namespace cast } // namespace media diff --git a/media/cast/cast_environment.h b/media/cast/cast_environment.h index 1129091..1f68a2d 100644 --- a/media/cast/cast_environment.h +++ b/media/cast/cast_environment.h @@ -10,6 +10,8 @@ #include "base/task_runner.h" #include "base/time/tick_clock.h" #include "base/time/time.h" +#include "media/cast/logging/logging_defines.h" +#include "media/cast/logging/logging_impl.h" namespace media { namespace cast { @@ -38,7 +40,8 @@ class CastEnvironment : public base::RefCountedThreadSafe<CastEnvironment> { scoped_refptr<base::TaskRunner> audio_encode_thread_proxy, scoped_refptr<base::TaskRunner> audio_decode_thread_proxy, scoped_refptr<base::TaskRunner> video_encode_thread_proxy, - scoped_refptr<base::TaskRunner> video_decode_thread_proxy); + scoped_refptr<base::TaskRunner> video_decode_thread_proxy, + const CastLoggingConfig& config); // These are the same methods in message_loop.h, but are guaranteed to either // get posted to the MessageLoop if it's still alive, or be deleted otherwise. @@ -56,7 +59,10 @@ class CastEnvironment : public base::RefCountedThreadSafe<CastEnvironment> { bool CurrentlyOn(ThreadId identifier); - base::TickClock* Clock(); + base::TickClock* Clock() const; + + // Logging is not thread safe. Should always be called from the main thread. + LoggingImpl* Logging(); protected: virtual ~CastEnvironment(); @@ -74,6 +80,8 @@ class CastEnvironment : public base::RefCountedThreadSafe<CastEnvironment> { scoped_refptr<base::TaskRunner> video_encode_thread_proxy_; scoped_refptr<base::TaskRunner> video_decode_thread_proxy_; + scoped_ptr<LoggingImpl> logging_; + DISALLOW_COPY_AND_ASSIGN(CastEnvironment); }; diff --git a/media/cast/cast_sender_impl.cc b/media/cast/cast_sender_impl.cc index 1bdd7c5..d1a83d3 100644 --- a/media/cast/cast_sender_impl.cc +++ b/media/cast/cast_sender_impl.cc @@ -34,6 +34,9 @@ class LocalFrameInput : public FrameInput { virtual void InsertRawVideoFrame(const I420VideoFrame* video_frame, const base::TimeTicks& capture_time, const base::Closure callback) OVERRIDE { + cast_environment_->Logging()->InsertFrameEvent(kVideoFrameReceived, + GetVideoRtpTimestamp(capture_time), kFrameIdUnknown); + cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, base::Bind(&VideoSender::InsertRawVideoFrame, video_sender_, video_frame, capture_time, callback)); @@ -50,6 +53,8 @@ class LocalFrameInput : public FrameInput { virtual void InsertAudio(const AudioBus* audio_bus, const base::TimeTicks& recorded_time, const base::Closure& done_callback) OVERRIDE { + cast_environment_->Logging()->InsertFrameEvent(kAudioFrameReceived, + GetVideoRtpTimestamp(recorded_time), kFrameIdUnknown); cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, base::Bind(&AudioSender::InsertAudio, audio_sender_, audio_bus, recorded_time, done_callback)); diff --git a/media/cast/logging/logging.gyp b/media/cast/logging/logging.gyp deleted file mode 100644 index 9140e3a..0000000 --- a/media/cast/logging/logging.gyp +++ /dev/null @@ -1,30 +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. - - -{ - 'targets': [ - { - 'target_name': 'cast_logging', - 'type': 'static_library', - 'include_dirs': [ - '<(DEPTH)/', - ], - 'sources': [ - 'logging_defines.cc', - 'logging_defines.h', - 'logging_impl.cc', - 'logging_impl.h', - 'logging_raw.cc', - 'logging_raw.h', - 'logging_stats.cc', - 'logging_stats.h', - ], - 'dependencies': [ - '<(DEPTH)/base/base.gyp:base', - '<(DEPTH)/base/base.gyp:test_support_base', - ], - }, - ], # targets -} diff --git a/media/cast/logging/logging_defines.cc b/media/cast/logging/logging_defines.cc index 3f502f9..d70fc63 100644 --- a/media/cast/logging/logging_defines.cc +++ b/media/cast/logging/logging_defines.cc @@ -9,20 +9,36 @@ namespace media { namespace cast { +CastLoggingConfig::CastLoggingConfig() + : enable_data_collection(false), + enable_uma_stats(false), + enable_tracing(false) {} + +CastLoggingConfig::~CastLoggingConfig() {} + +CastLoggingConfig GetDefaultCastLoggingConfig() { + CastLoggingConfig config; + return config; +} + std::string CastLoggingToString(CastLoggingEvent event) { switch (event) { - case(kRtt): - return "Rtt"; + case(kRttMs): + return "RttMs"; case(kPacketLoss): return "PacketLoss"; - case(kJitter): - return "Jitter"; + case(kJitterMs): + return "JitterMs"; case(kAckReceived): return "AckReceived"; + case(kRembBitrate): + return "RembBitrate"; case(kAckSent): return "AckSent"; case(kLastEvent): return "LastEvent"; + case(kAudioFrameReceived): + return "AudioFrameReceived"; case(kAudioFrameCaptured): return "AudioFrameCaptured"; case(kAudioFrameEncoded): @@ -33,6 +49,8 @@ std::string CastLoggingToString(CastLoggingEvent event) { return "AudioFrameDecoded"; case(kVideoFrameCaptured): return "VideoFrameCaptured"; + case(kVideoFrameReceived): + return "VideoFrameReceived"; case(kVideoFrameSentToEncoder): return "VideoFrameSentToEncoder"; case(kVideoFrameEncoded): diff --git a/media/cast/logging/logging_defines.h b/media/cast/logging/logging_defines.h index 6388a12..1a64e23 100644 --- a/media/cast/logging/logging_defines.h +++ b/media/cast/logging/logging_defines.h @@ -15,15 +15,29 @@ namespace media { namespace cast { +struct CastLoggingConfig { + CastLoggingConfig(); + ~CastLoggingConfig(); + + bool enable_data_collection; + bool enable_uma_stats; + bool enable_tracing; +}; + +// By default, enable raw and stats data collection. Disable tracing and UMA. +CastLoggingConfig GetDefaultCastLoggingConfig(); + enum CastLoggingEvent { // Generic events. - kRtt, + kRttMs, kPacketLoss, - kJitter, + kJitterMs, kAckReceived, + kRembBitrate, kAckSent, kLastEvent, // Audio sender. + kAudioFrameReceived, kAudioFrameCaptured, kAudioFrameEncoded, // Audio receiver. @@ -31,6 +45,7 @@ enum CastLoggingEvent { kAudioFrameDecoded, // Video sender. kVideoFrameCaptured, + kVideoFrameReceived, kVideoFrameSentToEncoder, kVideoFrameEncoded, // Video receiver. @@ -42,6 +57,8 @@ enum CastLoggingEvent { kPacketRetransmited, // Receive-side packet events. kPacketReceived, + + kNumOfLoggingEvents, }; std::string CastLoggingToString(CastLoggingEvent event); @@ -51,7 +68,7 @@ struct FrameEvent { ~FrameEvent(); uint32 frame_id; - int size; // Encoded size only. + size_t size; // Encoded size only. std::vector<base::TimeTicks> timestamp; std::vector<CastLoggingEvent> type; base::TimeDelta delay_delta; // Render/playout delay. @@ -62,7 +79,7 @@ struct BasePacketInfo { BasePacketInfo(); ~BasePacketInfo(); - int size; + size_t size; std::vector<base::TimeTicks> timestamp; std::vector<CastLoggingEvent> type; }; diff --git a/media/cast/logging/logging_impl.cc b/media/cast/logging/logging_impl.cc index ed189a9..97c9277 100644 --- a/media/cast/logging/logging_impl.cc +++ b/media/cast/logging/logging_impl.cc @@ -10,12 +10,10 @@ namespace media { namespace cast { LoggingImpl::LoggingImpl(base::TickClock* clock, - bool enable_data_collection, - bool enable_uma_stats, - bool enable_tracing) - : enable_data_collection_(enable_data_collection), - enable_uma_stats_(enable_uma_stats), - enable_tracing_(enable_tracing), + scoped_refptr<base::TaskRunner> main_thread_proxy, + const CastLoggingConfig& config) + : main_thread_proxy_(main_thread_proxy), + config_(config), raw_(clock), stats_(clock) {} @@ -24,11 +22,12 @@ LoggingImpl::~LoggingImpl() {} void LoggingImpl::InsertFrameEvent(CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id) { - if (enable_data_collection_) { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); + if (config_.enable_data_collection) { raw_.InsertFrameEvent(event, rtp_timestamp, frame_id); stats_.InsertFrameEvent(event, rtp_timestamp, frame_id); } - if (enable_tracing_) { + 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", @@ -40,14 +39,15 @@ void LoggingImpl::InsertFrameEventWithSize(CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, int frame_size) { - if (enable_data_collection_) { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); + if (config_.enable_data_collection) { raw_.InsertFrameEventWithSize(event, rtp_timestamp, frame_id, frame_size); stats_.InsertFrameEventWithSize(event, rtp_timestamp, frame_id, frame_size); } - if (enable_uma_stats_) { + if (config_.enable_uma_stats) { UMA_HISTOGRAM_COUNTS(CastLoggingToString(event), frame_size); } - if (enable_tracing_) { + 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", @@ -60,14 +60,15 @@ void LoggingImpl::InsertFrameEventWithDelay(CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, base::TimeDelta delay) { - if (enable_data_collection_) { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); + if (config_.enable_data_collection) { raw_.InsertFrameEventWithDelay(event, rtp_timestamp, frame_id, delay); stats_.InsertFrameEventWithDelay(event, rtp_timestamp, frame_id, delay); } - if (enable_uma_stats_) { + if (config_.enable_uma_stats) { UMA_HISTOGRAM_TIMES(CastLoggingToString(event), delay); } - if (enable_tracing_) { + 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", @@ -80,14 +81,15 @@ void LoggingImpl::InsertPacketEvent(CastLoggingEvent event, uint32 frame_id, uint16 packet_id, uint16 max_packet_id, - int size) { - if (enable_data_collection_) { + size_t size) { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); + if (config_.enable_data_collection) { raw_.InsertPacketEvent(event, rtp_timestamp, frame_id, packet_id, max_packet_id, size); stats_.InsertPacketEvent(event, rtp_timestamp, frame_id, packet_id, max_packet_id, size); } - if (enable_tracing_) { + 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, @@ -96,14 +98,15 @@ void LoggingImpl::InsertPacketEvent(CastLoggingEvent event, } void LoggingImpl::InsertGenericEvent(CastLoggingEvent event, int value) { - if (enable_data_collection_) { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); + if (config_.enable_data_collection) { raw_.InsertGenericEvent(event, value); stats_.InsertGenericEvent(event, value); } - if (enable_uma_stats_) { + if (config_.enable_uma_stats) { UMA_HISTOGRAM_COUNTS(CastLoggingToString(event), value); } - if (enable_tracing_) { + if (config_.enable_tracing) { std::string event_string = CastLoggingToString(event); TRACE_EVENT_INSTANT1(event_string.c_str(), "GE", TRACE_EVENT_SCOPE_THREAD, "value", value); @@ -113,21 +116,25 @@ void LoggingImpl::InsertGenericEvent(CastLoggingEvent event, int value) { // should just get the entire class, would be much easier. FrameRawMap LoggingImpl::GetFrameRawData() { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); return raw_.GetFrameData(); } PacketRawMap LoggingImpl::GetPacketRawData() { - return raw_.GetPacketData(); + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); + return raw_.GetPacketData(); } GenericRawMap LoggingImpl::GetGenericRawData() { - return raw_.GetGenericData(); + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); + return raw_.GetGenericData(); } const FrameStatsMap* LoggingImpl::GetFrameStatsData() { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); // Get stats data. const FrameStatsMap* stats = stats_.GetFrameStatsData(); - if (enable_uma_stats_) { + if (config_.enable_uma_stats) { FrameStatsMap::const_iterator it; for (it = stats->begin(); it != stats->end(); ++it) { // Check for an active event. @@ -159,9 +166,10 @@ const FrameStatsMap* LoggingImpl::GetFrameStatsData() { } const PacketStatsMap* LoggingImpl::GetPacketStatsData() { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); // Get stats data. const PacketStatsMap* stats = stats_.GetPacketStatsData(); - if (enable_uma_stats_) { + if (config_.enable_uma_stats) { PacketStatsMap::const_iterator it; for (it = stats->begin(); it != stats->end(); ++it) { if (it->second > 0) { @@ -174,9 +182,10 @@ const PacketStatsMap* LoggingImpl::GetPacketStatsData() { } const GenericStatsMap* LoggingImpl::GetGenericStatsData() { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); // Get stats data. const GenericStatsMap* stats = stats_.GetGenericStatsData(); - if (enable_uma_stats_) { + if (config_.enable_uma_stats) { GenericStatsMap::const_iterator it; for (it = stats->begin(); it != stats->end(); ++it) { if (it->second > 0) { @@ -188,6 +197,7 @@ const GenericStatsMap* LoggingImpl::GetGenericStatsData() { } void LoggingImpl::Reset() { + DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); raw_.Reset(); stats_.Reset(); } diff --git a/media/cast/logging/logging_impl.h b/media/cast/logging/logging_impl.h index 5e724e0..628f346 100644 --- a/media/cast/logging/logging_impl.h +++ b/media/cast/logging/logging_impl.h @@ -10,6 +10,8 @@ // 2. UMA stats. // 3. Tracing of raw events. +#include "base/memory/ref_counted.h" +#include "base/task_runner.h" #include "media/cast/logging/logging_defines.h" #include "media/cast/logging/logging_raw.h" #include "media/cast/logging/logging_stats.h" @@ -17,12 +19,13 @@ namespace media { namespace cast { -class LoggingImpl { +static const int kFrameIdUnknown = -1; +// Should only be called from the main thread. +class LoggingImpl : public base::NonThreadSafe { public: LoggingImpl(base::TickClock* clock, - bool enable_data_collection, - bool enable_uma_stats, - bool enable_tracing); + scoped_refptr<base::TaskRunner> main_thread_proxy, + const CastLoggingConfig& config); ~LoggingImpl(); @@ -42,7 +45,7 @@ class LoggingImpl { uint32 frame_id, uint16 packet_id, uint16 max_packet_id, - int size); + size_t size); void InsertGenericEvent(CastLoggingEvent event, int value); // Get raw data. @@ -57,11 +60,10 @@ class LoggingImpl { void Reset(); private: + scoped_refptr<base::TaskRunner> main_thread_proxy_; + const CastLoggingConfig config_; LoggingRaw raw_; LoggingStats stats_; - bool enable_data_collection_; - bool enable_uma_stats_; - bool enable_tracing_; DISALLOW_COPY_AND_ASSIGN(LoggingImpl); }; diff --git a/media/cast/logging/logging_internal.h b/media/cast/logging/logging_internal.h index ea66b1c..6f028b9 100644 --- a/media/cast/logging/logging_internal.h +++ b/media/cast/logging/logging_internal.h @@ -27,7 +27,7 @@ struct FrameEvent { struct PacketEvent { uint32 frame_id; int max_packet_id; - int size; + size_t size; base::TimeTicks timestamp; }; diff --git a/media/cast/logging/logging_raw.cc b/media/cast/logging/logging_raw.cc index 820fd0f..0fd0ae17 100644 --- a/media/cast/logging/logging_raw.cc +++ b/media/cast/logging/logging_raw.cc @@ -4,7 +4,6 @@ #include "media/cast/logging/logging_raw.h" -#include "base/debug/trace_event.h" #include "base/logging.h" #include "base/metrics/histogram.h" #include "base/time/time.h" @@ -64,6 +63,12 @@ void LoggingRaw::InsertBaseFrameEvent(CastLoggingEvent event, // Insert to an existing entry. it->second.timestamp.push_back(clock_->NowTicks()); it->second.type.push_back(event); + // Do we have a valid frame_id? + // We don't always have it to begin with. + // TODO(mikhal): Switch frame_id to int when the fix gets in. + // This is currently illegal, as frame_id is uint8, so commenting it out. + // if (it->second.frame_id == -1 && frame_id != -1) + // it->second.frame_id = frame_id; } } @@ -72,7 +77,7 @@ void LoggingRaw::InsertPacketEvent(CastLoggingEvent event, uint32 frame_id, uint16 packet_id, uint16 max_packet_id, - int size) { + size_t size) { // Is this packet belonging to a new frame? PacketRawMap::iterator it = packet_map_.find(rtp_timestamp); if (it == packet_map_.end()) { diff --git a/media/cast/logging/logging_raw.h b/media/cast/logging/logging_raw.h index 191e5e1..4ac8d0f 100644 --- a/media/cast/logging/logging_raw.h +++ b/media/cast/logging/logging_raw.h @@ -51,7 +51,7 @@ class LoggingRaw : public base::NonThreadSafe, uint32 frame_id, uint16 packet_id, uint16 max_packet_id, - int size); + size_t size); void InsertGenericEvent(CastLoggingEvent event, int value); @@ -69,11 +69,11 @@ class LoggingRaw : public base::NonThreadSafe, uint32 frame_id, uint32 rtp_timestamp); - base::WeakPtrFactory<LoggingRaw> weak_factory_; base::TickClock* const clock_; // Not owned by this class. FrameRawMap frame_map_; PacketRawMap packet_map_; GenericRawMap generic_map_; + base::WeakPtrFactory<LoggingRaw> weak_factory_; DISALLOW_COPY_AND_ASSIGN(LoggingRaw); }; diff --git a/media/cast/logging/logging_stats.cc b/media/cast/logging/logging_stats.cc index 95e916a..84fdbf7 100644 --- a/media/cast/logging/logging_stats.cc +++ b/media/cast/logging/logging_stats.cc @@ -16,6 +16,7 @@ LoggingStats::LoggingStats(base::TickClock* clock) start_time_(), clock_(clock) { memset(counts_, 0, sizeof(counts_)); + memset(start_time_, 0, sizeof(start_time_)); } LoggingStats::~LoggingStats() {} @@ -82,7 +83,7 @@ void LoggingStats::InsertPacketEvent(CastLoggingEvent event, uint32 frame_id, uint16 packet_id, uint16 max_packet_id, - int size) { + size_t size) { // Does this packet belong to an existing event? PacketStatsMap::iterator it = packet_stats_.find(event); if (it == packet_stats_.end()) { diff --git a/media/cast/logging/logging_stats.h b/media/cast/logging/logging_stats.h index e5595476..f08649c 100644 --- a/media/cast/logging/logging_stats.h +++ b/media/cast/logging/logging_stats.h @@ -13,8 +13,6 @@ namespace media { namespace cast { -const int kNumberOfEvents = 19; - class LoggingStats { public: explicit LoggingStats(base::TickClock* clock); @@ -42,7 +40,7 @@ class LoggingStats { uint32 frame_id, uint16 packet_id, uint16 max_packet_id, - int size); + size_t size); void InsertGenericEvent(CastLoggingEvent event, int value); @@ -62,9 +60,9 @@ class LoggingStats { PacketStatsMap packet_stats_; GenericStatsMap generic_stats_; // Every event has an individual start time - base::TimeTicks start_time_[kNumberOfEvents]; + base::TimeTicks start_time_[kNumOfLoggingEvents]; // Keep track of event counts. - int counts_[kNumberOfEvents]; + int counts_[kNumOfLoggingEvents]; base::TickClock* const clock_; // Not owned by this class. DISALLOW_COPY_AND_ASSIGN(LoggingStats); diff --git a/media/cast/pacing/paced_sender_unittest.cc b/media/cast/pacing/paced_sender_unittest.cc index 8ae4ea8..e1fbc2e 100644 --- a/media/cast/pacing/paced_sender_unittest.cc +++ b/media/cast/pacing/paced_sender_unittest.cc @@ -59,7 +59,8 @@ class PacedSenderTest : public ::testing::Test { virtual void SetUp() { task_runner_ = new test::FakeTaskRunner(&testing_clock_); cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_, - task_runner_, task_runner_, task_runner_, task_runner_); + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig()); paced_sender_.reset(new PacedSender(cast_environment_, &mock_transport_)); } diff --git a/media/cast/rtcp/rtcp.cc b/media/cast/rtcp/rtcp.cc index e848f2b..a21bcb0 100644 --- a/media/cast/rtcp/rtcp.cc +++ b/media/cast/rtcp/rtcp.cc @@ -4,10 +4,10 @@ #include "media/cast/rtcp/rtcp.h" -#include "base/debug/trace_event.h" #include "base/rand_util.h" #include "media/cast/cast_config.h" #include "media/cast/cast_defines.h" +#include "media/cast/cast_environment.h" #include "media/cast/rtcp/rtcp_defines.h" #include "media/cast/rtcp/rtcp_receiver.h" #include "media/cast/rtcp/rtcp_sender.h" @@ -100,7 +100,7 @@ class LocalRtcpReceiverFeedback : public RtcpReceiverFeedback { Rtcp* rtcp_; }; -Rtcp::Rtcp(base::TickClock* clock, +Rtcp::Rtcp(scoped_refptr<CastEnvironment> cast_environment, RtcpSenderFeedback* sender_feedback, PacedPacketSender* paced_packet_sender, RtpSenderStatistics* rtp_sender_statistics, @@ -118,15 +118,17 @@ Rtcp::Rtcp(base::TickClock* clock, rtp_receiver_statistics_(rtp_receiver_statistics), receiver_feedback_(new LocalRtcpReceiverFeedback(this)), rtt_feedback_(new LocalRtcpRttFeedback(this)), - rtcp_sender_(new RtcpSender(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), - clock_(clock) { - rtcp_receiver_.reset(new RtcpReceiver(sender_feedback, + cast_environment_(cast_environment) { + rtcp_receiver_.reset(new RtcpReceiver(cast_environment, + sender_feedback, receiver_feedback_.get(), rtt_feedback_.get(), local_ssrc)); @@ -178,7 +180,7 @@ void Rtcp::SendRtcpFromRtpReceiver(const RtcpCastMessage* cast_message, const RtcpReceiverLogMessage* receiver_log) { uint32 packet_type_flags = 0; - base::TimeTicks now = clock_->NowTicks(); + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); RtcpReportBlock report_block; RtcpReceiverReferenceTimeReport rrtr; @@ -199,6 +201,11 @@ void Rtcp::SendRtcpFromRtpReceiver(const RtcpCastMessage* cast_message, &report_block.cumulative_lost, &report_block.extended_high_sequence_number, &report_block.jitter); + cast_environment_->Logging()->InsertGenericEvent(kJitterMs, + report_block.jitter); + cast_environment_->Logging()->InsertGenericEvent(kPacketLoss, + report_block.fraction_lost); + } report_block.last_sr = last_report_received_; @@ -230,7 +237,7 @@ void Rtcp::SendRtcpFromRtpReceiver(const RtcpCastMessage* cast_message, void Rtcp::SendRtcpFromRtpSender( const RtcpSenderLogMessage* sender_log_message) { uint32 packet_type_flags = RtcpSender::kRtcpSr; - base::TimeTicks now = clock_->NowTicks(); + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); RtcpSenderInfo sender_info; RtcpDlrrReportBlock dlrr; @@ -267,7 +274,7 @@ void Rtcp::SendRtcpFromRtpSender( void Rtcp::OnReceivedNtp(uint32 ntp_seconds, uint32 ntp_fraction) { last_report_received_ = (ntp_seconds << 16) + (ntp_fraction >> 16); - base::TimeTicks now = clock_->NowTicks(); + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); time_last_report_received_ = now; } @@ -280,7 +287,7 @@ void Rtcp::OnReceivedLipSyncInfo(uint32 rtp_timestamp, } void Rtcp::OnReceivedSendReportRequest() { - base::TimeTicks now = clock_->NowTicks(); + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); // Trigger a new RTCP report at next timer. next_time_to_send_rtcp_ = now; @@ -324,7 +331,9 @@ void Rtcp::OnReceivedDelaySinceLastReport(uint32 receivers_ssrc, if (it == last_reports_sent_map_.end()) { return; // Feedback on another report. } - base::TimeDelta sender_delay = clock_->NowTicks() - it->second; + + base::TimeDelta sender_delay = cast_environment_->Clock()->NowTicks() + - it->second; UpdateRtt(sender_delay, ConvertFromNtpDiff(delay_since_last_report)); } @@ -371,7 +380,6 @@ void Rtcp::UpdateRtt(const base::TimeDelta& sender_delay, avg_rtt_ms_ = rtt.InMilliseconds(); } number_of_rtt_in_avg_++; - TRACE_COUNTER_ID1("cast_rtcp", "RTT", local_ssrc_, rtt.InMilliseconds()); } bool Rtcp::Rtt(base::TimeDelta* rtt, @@ -383,7 +391,9 @@ bool Rtcp::Rtt(base::TimeDelta* rtt, 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; + cast_environment_->Logging()->InsertGenericEvent(kRttMs, + rtt->InMilliseconds()); *rtt = rtt_; *avg_rtt = base::TimeDelta::FromMilliseconds(avg_rtt_ms_); @@ -414,7 +424,7 @@ void Rtcp::UpdateNextTimeToSendRtcp() { base::TimeDelta time_to_next = (rtcp_interval_ / 2) + (rtcp_interval_ * random / 1000); - base::TimeTicks now = clock_->NowTicks(); + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); next_time_to_send_rtcp_ = now + time_to_next; } diff --git a/media/cast/rtcp/rtcp.h b/media/cast/rtcp/rtcp.h index 92e72a8..44bf270 100644 --- a/media/cast/rtcp/rtcp.h +++ b/media/cast/rtcp/rtcp.h @@ -17,6 +17,7 @@ #include "base/time/time.h" #include "media/cast/cast_config.h" #include "media/cast/cast_defines.h" +#include "media/cast/cast_environment.h" #include "media/cast/rtcp/rtcp_defines.h" namespace media { @@ -70,7 +71,7 @@ class RtpReceiverStatistics { class Rtcp { public: - Rtcp(base::TickClock* clock, + Rtcp(scoped_refptr<CastEnvironment> cast_environment, RtcpSenderFeedback* sender_feedback, PacedPacketSender* paced_packet_sender, RtpSenderStatistics* rtp_sender_statistics, @@ -141,7 +142,7 @@ class Rtcp { void SaveLastSentNtpTime(const base::TimeTicks& now, uint32 last_ntp_seconds, uint32 last_ntp_fraction); - base::TickClock* const clock_; // Not owned by this class. + scoped_refptr<CastEnvironment> cast_environment_; const base::TimeDelta rtcp_interval_; const RtcpMode rtcp_mode_; const uint32 local_ssrc_; diff --git a/media/cast/rtcp/rtcp_receiver.cc b/media/cast/rtcp/rtcp_receiver.cc index 82b657d..6bf4ac2 100644 --- a/media/cast/rtcp/rtcp_receiver.cc +++ b/media/cast/rtcp/rtcp_receiver.cc @@ -4,14 +4,14 @@ #include "media/cast/rtcp/rtcp_receiver.h" -#include "base/debug/trace_event.h" #include "base/logging.h" #include "media/cast/rtcp/rtcp_utility.h" namespace media { namespace cast { -RtcpReceiver::RtcpReceiver(RtcpSenderFeedback* sender_feedback, +RtcpReceiver::RtcpReceiver(scoped_refptr<CastEnvironment> cast_environment, + RtcpSenderFeedback* sender_feedback, RtcpReceiverFeedback* receiver_feedback, RtcpRttFeedback* rtt_feedback, uint32 local_ssrc) @@ -19,8 +19,8 @@ RtcpReceiver::RtcpReceiver(RtcpSenderFeedback* sender_feedback, remote_ssrc_(0), sender_feedback_(sender_feedback), receiver_feedback_(receiver_feedback), - rtt_feedback_(rtt_feedback) { -} + rtt_feedback_(rtt_feedback), + cast_environment_(cast_environment) {} RtcpReceiver::~RtcpReceiver() {} @@ -162,13 +162,10 @@ void RtcpReceiver::HandleReportBlock(const RtcpField* rtcp_field, return; } VLOG(1) << "Cast RTCP received RB from SSRC " << remote_ssrc; - - TRACE_COUNTER_ID1("cast_rtcp", "RtcpReceiver::FractionLost", - rb.ssrc, rb.fraction_lost); - TRACE_COUNTER_ID1("cast_rtcp", "RtcpReceiver::CumulativeNumberOfPacketsLost", - rb.ssrc, rb.cumulative_number_of_packets_lost); - TRACE_COUNTER_ID1("cast_rtcp", "RtcpReceiver::Jitter", - rb.ssrc, rb.jitter); + cast_environment_->Logging()->InsertGenericEvent(kPacketLoss, + rb.fraction_lost); + cast_environment_->Logging()->InsertGenericEvent(kJitterMs, + rb.jitter); RtcpReportBlock report_block; report_block.remote_ssrc = remote_ssrc; diff --git a/media/cast/rtcp/rtcp_receiver.h b/media/cast/rtcp/rtcp_receiver.h index bdb21a1..632c425 100644 --- a/media/cast/rtcp/rtcp_receiver.h +++ b/media/cast/rtcp/rtcp_receiver.h @@ -43,7 +43,8 @@ class RtcpRttFeedback { class RtcpReceiver { public: - explicit RtcpReceiver(RtcpSenderFeedback* sender_feedback, + explicit RtcpReceiver(scoped_refptr<CastEnvironment> cast_environment, + RtcpSenderFeedback* sender_feedback, RtcpReceiverFeedback* receiver_feedback, RtcpRttFeedback* rtt_feedback, uint32 local_ssrc); @@ -102,6 +103,7 @@ class RtcpReceiver { RtcpSenderFeedback* const sender_feedback_; RtcpReceiverFeedback* const receiver_feedback_; RtcpRttFeedback* const rtt_feedback_; + scoped_refptr<CastEnvironment> cast_environment_; FrameIdWrapHelper ack_frame_id_wrap_helper_; diff --git a/media/cast/rtcp/rtcp_receiver_unittest.cc b/media/cast/rtcp/rtcp_receiver_unittest.cc index 538b35d..f3d45f0 100644 --- a/media/cast/rtcp/rtcp_receiver_unittest.cc +++ b/media/cast/rtcp/rtcp_receiver_unittest.cc @@ -3,11 +3,14 @@ // found in the LICENSE file. #include "base/memory/scoped_ptr.h" +#include "base/test/simple_test_tick_clock.h" +#include "media/cast/cast_environment.h" #include "media/cast/rtcp/mock_rtcp_receiver_feedback.h" #include "media/cast/rtcp/mock_rtcp_sender_feedback.h" #include "media/cast/rtcp/rtcp_receiver.h" #include "media/cast/rtcp/rtcp_utility.h" #include "media/cast/rtcp/test_rtcp_packet_builder.h" +#include "media/cast/test/fake_task_runner.h" #include "testing/gmock/include/gmock/gmock.h" namespace media { @@ -61,7 +64,12 @@ class SenderFeedbackCastVerification : public RtcpSenderFeedback { class RtcpReceiverTest : public ::testing::Test { protected: RtcpReceiverTest() - : rtcp_receiver_(new RtcpReceiver(&mock_sender_feedback_, + : task_runner_(new test::FakeTaskRunner(&testing_clock_)), + cast_environment_(new CastEnvironment(&testing_clock_, task_runner_, + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig())), + rtcp_receiver_(new RtcpReceiver(cast_environment_, + &mock_sender_feedback_, &mock_receiver_feedback_, &mock_rtt_feedback_, kSourceSsrc)) { @@ -104,6 +112,9 @@ class RtcpReceiverTest : public ::testing::Test { rtcp_receiver_->IncomingRtcpPacket(&rtcp_parser); } + base::SimpleTestTickClock testing_clock_; + scoped_refptr<test::FakeTaskRunner> task_runner_; + scoped_refptr<CastEnvironment> cast_environment_; MockRtcpReceiverFeedback mock_receiver_feedback_; MockRtcpRttFeedback mock_rtt_feedback_; MockRtcpSenderFeedback mock_sender_feedback_; @@ -323,7 +334,8 @@ TEST_F(RtcpReceiverTest, InjectReceiverReportPacketWithCastFeedback) { TEST_F(RtcpReceiverTest, InjectReceiverReportPacketWithCastVerification) { SenderFeedbackCastVerification sender_feedback_cast_verification; - RtcpReceiver rtcp_receiver(&sender_feedback_cast_verification, + RtcpReceiver rtcp_receiver(cast_environment_, + &sender_feedback_cast_verification, &mock_receiver_feedback_, &mock_rtt_feedback_, kSourceSsrc); diff --git a/media/cast/rtcp/rtcp_sender.cc b/media/cast/rtcp/rtcp_sender.cc index 465e9c8..4b24b98 100644 --- a/media/cast/rtcp/rtcp_sender.cc +++ b/media/cast/rtcp/rtcp_sender.cc @@ -7,8 +7,8 @@ #include <algorithm> #include <vector> -#include "base/debug/trace_event.h" #include "base/logging.h" +#include "media/cast/cast_environment.h" #include "media/cast/pacing/paced_sender.h" #include "media/cast/rtcp/rtcp_utility.h" #include "net/base/big_endian.h" @@ -19,12 +19,14 @@ namespace cast { static const size_t kRtcpMaxNackFields = 253; static const size_t kRtcpMaxCastLossFields = 100; -RtcpSender::RtcpSender(PacedPacketSender* outgoing_transport, +RtcpSender::RtcpSender(scoped_refptr<CastEnvironment> cast_environment, + PacedPacketSender* outgoing_transport, uint32 sending_ssrc, const std::string& c_name) : ssrc_(sending_ssrc), c_name_(c_name), - transport_(outgoing_transport) { + transport_(outgoing_transport), + cast_environment_(cast_environment) { DCHECK_LT(c_name_.length(), kRtcpCnameSize) << "Invalid config"; } @@ -249,9 +251,6 @@ void RtcpSender::BuildPli(uint32 remote_ssrc, big_endian_writer.WriteU16(2); // Used fixed length of 2. big_endian_writer.WriteU32(ssrc_); // Add our own SSRC. big_endian_writer.WriteU32(remote_ssrc); // Add the remote SSRC. - TRACE_EVENT_INSTANT2("cast_rtcp", "RtcpSender::PLI", TRACE_EVENT_SCOPE_THREAD, - "remote_ssrc", remote_ssrc, - "ssrc", ssrc_); } /* @@ -355,8 +354,8 @@ void RtcpSender::BuildRemb(const RtcpRembMessage* remb, for (; it != remb->remb_ssrcs.end(); ++it) { big_endian_writer.WriteU32(*it); } - TRACE_COUNTER_ID1("cast_rtcp", "RtcpSender::RembBitrate", ssrc_, - remb->remb_bitrate); + cast_environment_->Logging()->InsertGenericEvent(kRembBitrate, + remb->remb_bitrate); } void RtcpSender::BuildNack(const RtcpNackMessage* nack, @@ -412,8 +411,6 @@ void RtcpSender::BuildNack(const RtcpNackMessage* nack, } DCHECK_GE(kRtcpMaxNackFields, number_of_nack_fields); (*packet)[nack_size_pos] = static_cast<uint8>(2 + number_of_nack_fields); - TRACE_COUNTER_ID1("cast_rtcp", "RtcpSender::NACK", ssrc_, - nack->nack_list.size()); } void RtcpSender::BuildBye(std::vector<uint8>* packet) const { @@ -567,10 +564,6 @@ void RtcpSender::BuildCast(const RtcpCastMessage* cast, DCHECK_LE(number_of_loss_fields, kRtcpMaxCastLossFields); (*packet)[cast_size_pos] = static_cast<uint8>(4 + number_of_loss_fields); (*packet)[cast_loss_field_pos] = static_cast<uint8>(number_of_loss_fields); - - // Frames with missing packets. - TRACE_COUNTER_ID1("cast_rtcp", "RtcpSender::CastNACK", ssrc_, - cast->missing_frames_and_packets_.size()); } void RtcpSender::BuildSenderLog(const RtcpSenderLogMessage* sender_log_message, diff --git a/media/cast/rtcp/rtcp_sender.h b/media/cast/rtcp/rtcp_sender.h index de97d38..24915dd 100644 --- a/media/cast/rtcp/rtcp_sender.h +++ b/media/cast/rtcp/rtcp_sender.h @@ -18,7 +18,8 @@ namespace cast { class RtcpSender { public: - RtcpSender(PacedPacketSender* const paced_packet_sender, + RtcpSender(scoped_refptr<CastEnvironment> cast_environment, + PacedPacketSender* const paced_packet_sender, uint32 sending_ssrc, const std::string& c_name); @@ -113,6 +114,7 @@ class RtcpSender { // Not owned by this class. PacedPacketSender* transport_; + scoped_refptr<CastEnvironment> cast_environment_; DISALLOW_COPY_AND_ASSIGN(RtcpSender); }; diff --git a/media/cast/rtcp/rtcp_sender_unittest.cc b/media/cast/rtcp/rtcp_sender_unittest.cc index 012d5b9..7521c12 100644 --- a/media/cast/rtcp/rtcp_sender_unittest.cc +++ b/media/cast/rtcp/rtcp_sender_unittest.cc @@ -3,18 +3,23 @@ // found in the LICENSE file. #include "base/memory/scoped_ptr.h" +#include "base/test/simple_test_tick_clock.h" #include "media/cast/cast_defines.h" +#include "media/cast/cast_environment.h" #include "media/cast/pacing/paced_sender.h" #include "media/cast/rtcp/rtcp_sender.h" #include "media/cast/rtcp/test_rtcp_packet_builder.h" +#include "media/cast/test/fake_task_runner.h" #include "testing/gmock/include/gmock/gmock.h" namespace media { namespace cast { +namespace { static const uint32 kSendingSsrc = 0x12345678; static const uint32 kMediaSsrc = 0x87654321; static const std::string kCName("test@10.1.1.1"); +} // namespace class TestRtcpTransport : public PacedPacketSender { public: @@ -54,12 +59,20 @@ class TestRtcpTransport : public PacedPacketSender { class RtcpSenderTest : public ::testing::Test { protected: RtcpSenderTest() - : rtcp_sender_(new RtcpSender(&test_transport_, + : task_runner_(new test::FakeTaskRunner(&testing_clock_)), + cast_environment_(new CastEnvironment(&testing_clock_, task_runner_, + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig())), + rtcp_sender_(new RtcpSender(cast_environment_, + &test_transport_, kSendingSsrc, kCName)) { } + base::SimpleTestTickClock testing_clock_; TestRtcpTransport test_transport_; + scoped_refptr<test::FakeTaskRunner> task_runner_; + scoped_refptr<CastEnvironment> cast_environment_; scoped_ptr<RtcpSender> rtcp_sender_; }; diff --git a/media/cast/rtcp/rtcp_unittest.cc b/media/cast/rtcp/rtcp_unittest.cc index 221ecf1..8287d99 100644 --- a/media/cast/rtcp/rtcp_unittest.cc +++ b/media/cast/rtcp/rtcp_unittest.cc @@ -4,11 +4,13 @@ #include "base/test/simple_test_tick_clock.h" #include "media/cast/cast_defines.h" +#include "media/cast/cast_environment.h" #include "media/cast/pacing/paced_sender.h" #include "media/cast/rtcp/mock_rtcp_receiver_feedback.h" #include "media/cast/rtcp/mock_rtcp_sender_feedback.h" #include "media/cast/rtcp/rtcp.h" #include "media/cast/rtcp/test_rtcp_packet_builder.h" +#include "media/cast/test/fake_task_runner.h" #include "testing/gmock/include/gmock/gmock.h" namespace media { @@ -26,7 +28,8 @@ static const int64 kAddedShortDelay= 100; class LocalRtcpTransport : public PacedPacketSender { public: - explicit LocalRtcpTransport(base::SimpleTestTickClock* testing_clock) + explicit LocalRtcpTransport(scoped_refptr<CastEnvironment> cast_environment, + base::SimpleTestTickClock* testing_clock) : drop_packets_(false), short_delay_(false), testing_clock_(testing_clock) {} @@ -64,11 +67,12 @@ class LocalRtcpTransport : public PacedPacketSender { bool short_delay_; Rtcp* rtcp_; base::SimpleTestTickClock* testing_clock_; + scoped_refptr<CastEnvironment> cast_environment_; }; class RtcpPeer : public Rtcp { public: - RtcpPeer(base::TickClock* clock, + RtcpPeer(scoped_refptr<CastEnvironment> cast_environment, RtcpSenderFeedback* sender_feedback, PacedPacketSender* const paced_packet_sender, RtpSenderStatistics* rtp_sender_statistics, @@ -78,7 +82,7 @@ class RtcpPeer : public Rtcp { uint32 local_ssrc, uint32 remote_ssrc, const std::string& c_name) - : Rtcp(clock, + : Rtcp(cast_environment, sender_feedback, paced_packet_sender, rtp_sender_statistics, @@ -97,7 +101,11 @@ class RtcpPeer : public Rtcp { class RtcpTest : public ::testing::Test { protected: RtcpTest() - : transport_(&testing_clock_) { + : task_runner_(new test::FakeTaskRunner(&testing_clock_)), + cast_environment_(new CastEnvironment(&testing_clock_, task_runner_, + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig())), + transport_(cast_environment_, &testing_clock_) { testing_clock_.Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); } @@ -109,6 +117,8 @@ class RtcpTest : public ::testing::Test { } base::SimpleTestTickClock testing_clock_; + scoped_refptr<test::FakeTaskRunner> task_runner_; + scoped_refptr<CastEnvironment> cast_environment_; LocalRtcpTransport transport_; MockRtcpSenderFeedback mock_sender_feedback_; }; @@ -116,7 +126,7 @@ class RtcpTest : public ::testing::Test { TEST_F(RtcpTest, TimeToSend) { base::TimeTicks start_time; start_time += base::TimeDelta::FromMilliseconds(kStartMillisecond); - Rtcp rtcp(&testing_clock_, + Rtcp rtcp(cast_environment_, &mock_sender_feedback_, &transport_, NULL, @@ -137,7 +147,7 @@ TEST_F(RtcpTest, TimeToSend) { } TEST_F(RtcpTest, BasicSenderReport) { - Rtcp rtcp(&testing_clock_, + Rtcp rtcp(cast_environment_, &mock_sender_feedback_, &transport_, NULL, @@ -152,7 +162,7 @@ TEST_F(RtcpTest, BasicSenderReport) { } TEST_F(RtcpTest, BasicReceiverReport) { - Rtcp rtcp(&testing_clock_, + Rtcp rtcp(cast_environment_, &mock_sender_feedback_, &transport_, NULL, @@ -170,7 +180,7 @@ TEST_F(RtcpTest, BasicCast) { EXPECT_CALL(mock_sender_feedback_, OnReceivedCastFeedback(_)).Times(1); // Media receiver. - Rtcp rtcp(&testing_clock_, + Rtcp rtcp(cast_environment_, &mock_sender_feedback_, &transport_, NULL, @@ -197,8 +207,8 @@ TEST_F(RtcpTest, BasicCast) { TEST_F(RtcpTest, RttReducedSizeRtcp) { // Media receiver. - LocalRtcpTransport receiver_transport(&testing_clock_); - Rtcp rtcp_receiver(&testing_clock_, + LocalRtcpTransport receiver_transport(cast_environment_, &testing_clock_); + Rtcp rtcp_receiver(cast_environment_, &mock_sender_feedback_, &receiver_transport, NULL, @@ -210,8 +220,8 @@ TEST_F(RtcpTest, RttReducedSizeRtcp) { kCName); // Media sender. - LocalRtcpTransport sender_transport(&testing_clock_); - Rtcp rtcp_sender(&testing_clock_, + LocalRtcpTransport sender_transport(cast_environment_, &testing_clock_); + Rtcp rtcp_sender(cast_environment_, &mock_sender_feedback_, &sender_transport, NULL, @@ -251,8 +261,8 @@ TEST_F(RtcpTest, RttReducedSizeRtcp) { TEST_F(RtcpTest, Rtt) { // Media receiver. - LocalRtcpTransport receiver_transport(&testing_clock_); - Rtcp rtcp_receiver(&testing_clock_, + LocalRtcpTransport receiver_transport(cast_environment_, &testing_clock_); + Rtcp rtcp_receiver(cast_environment_, &mock_sender_feedback_, &receiver_transport, NULL, @@ -264,8 +274,8 @@ TEST_F(RtcpTest, Rtt) { kCName); // Media sender. - LocalRtcpTransport sender_transport(&testing_clock_); - Rtcp rtcp_sender(&testing_clock_, + LocalRtcpTransport sender_transport(cast_environment_, &testing_clock_); + Rtcp rtcp_sender(cast_environment_, &mock_sender_feedback_, &sender_transport, NULL, @@ -337,8 +347,8 @@ TEST_F(RtcpTest, Rtt) { TEST_F(RtcpTest, RttWithPacketLoss) { // Media receiver. - LocalRtcpTransport receiver_transport(&testing_clock_); - Rtcp rtcp_receiver(&testing_clock_, + LocalRtcpTransport receiver_transport(cast_environment_, &testing_clock_); + Rtcp rtcp_receiver(cast_environment_, &mock_sender_feedback_, &receiver_transport, NULL, @@ -350,8 +360,8 @@ TEST_F(RtcpTest, RttWithPacketLoss) { kCName); // Media sender. - LocalRtcpTransport sender_transport(&testing_clock_); - Rtcp rtcp_sender(&testing_clock_, + LocalRtcpTransport sender_transport(cast_environment_, &testing_clock_); + Rtcp rtcp_sender(cast_environment_, &mock_sender_feedback_, &sender_transport, NULL, @@ -437,7 +447,7 @@ TEST_F(RtcpTest, NtpAndTime) { } TEST_F(RtcpTest, WrapAround) { - RtcpPeer rtcp_peer(&testing_clock_, + RtcpPeer rtcp_peer(cast_environment_, &mock_sender_feedback_, NULL, NULL, @@ -465,7 +475,7 @@ TEST_F(RtcpTest, WrapAround) { } TEST_F(RtcpTest, RtpTimestampInSenderTime) { - RtcpPeer rtcp_peer(&testing_clock_, + RtcpPeer rtcp_peer(cast_environment_, &mock_sender_feedback_, NULL, NULL, diff --git a/media/cast/rtcp/test_rtcp_packet_builder.cc b/media/cast/rtcp/test_rtcp_packet_builder.cc index aaf7007..fec0b90 100644 --- a/media/cast/rtcp/test_rtcp_packet_builder.cc +++ b/media/cast/rtcp/test_rtcp_packet_builder.cc @@ -185,7 +185,7 @@ void TestRtcpPacketBuilder::AddRemb(uint32 sender_ssrc, uint32 media_ssrc) { big_endian_writer_.WriteU8(1); // Number of SSRCs. big_endian_writer_.WriteU8(1); // BR Exp. // BR Mantissa. - big_endian_writer_.WriteU16(static_cast<uint16>(kRembBitrate / 2)); + big_endian_writer_.WriteU16(static_cast<uint16>(kTestRembBitrate / 2)); big_endian_writer_.WriteU32(media_ssrc); } diff --git a/media/cast/rtcp/test_rtcp_packet_builder.h b/media/cast/rtcp/test_rtcp_packet_builder.h index b1f1aca..4bdcf58 100644 --- a/media/cast/rtcp/test_rtcp_packet_builder.h +++ b/media/cast/rtcp/test_rtcp_packet_builder.h @@ -15,6 +15,7 @@ namespace cast { // These values are arbitrary only for the purpose of testing. +namespace { // Sender report. static const int kNtpHigh = 0x01020304; static const int kNtpLow = 0x05060708; @@ -34,7 +35,7 @@ static const int kLastRr = 0x34561234; static const int kDelayLastRr = 1000; // REMB. -static const int kRembBitrate = 52428; +static const int kTestRembBitrate = 52428; // RPSI. static const int kPayloadtype = 126; @@ -50,6 +51,7 @@ static const uint32 kFrameIdWithLostPackets = 19; static const int kLostPacketId1 = 3; static const int kLostPacketId2 = 5; static const int kLostPacketId3 = 12; +} // namespace class TestRtcpPacketBuilder { public: diff --git a/media/cast/rtp_sender/rtp_packetizer/rtp_packetizer.cc b/media/cast/rtp_sender/rtp_packetizer/rtp_packetizer.cc index 2509970..6c5141d 100644 --- a/media/cast/rtp_sender/rtp_packetizer/rtp_packetizer.cc +++ b/media/cast/rtp_sender/rtp_packetizer/rtp_packetizer.cc @@ -39,11 +39,8 @@ void RtpPacketizer::IncomingEncodedVideoFrame( DCHECK(!config_.audio) << "Invalid state"; if (config_.audio) return; - base::TimeTicks zero_time; - base::TimeDelta capture_delta = capture_time - zero_time; - // Timestamp is in 90 KHz for video. - rtp_timestamp_ = static_cast<uint32>(capture_delta.InMilliseconds() * 90); + rtp_timestamp_ = GetVideoRtpTimestamp(capture_time); time_last_sent_rtp_timestamp_ = capture_time; Cast(video_frame->key_frame, @@ -78,6 +75,7 @@ bool RtpPacketizer::LastSentTimestamp(base::TimeTicks* time_sent, return true; } +// TODO(mikhal): Switch to pass data with a const_ref. void RtpPacketizer::Cast(bool is_key, uint32 frame_id, uint32 reference_frame_id, diff --git a/media/cast/rtp_sender/rtp_sender.cc b/media/cast/rtp_sender/rtp_sender.cc index 37487a0..d222a56 100644 --- a/media/cast/rtp_sender/rtp_sender.cc +++ b/media/cast/rtp_sender/rtp_sender.cc @@ -9,28 +9,31 @@ #include "media/cast/cast_defines.h" #include "media/cast/pacing/paced_sender.h" #include "media/cast/rtcp/rtcp_defines.h" +#include "net/base/big_endian.h" namespace media { namespace cast { -RtpSender::RtpSender(base::TickClock* clock, +RtpSender::RtpSender(scoped_refptr<CastEnvironment> cast_environment, const AudioSenderConfig* audio_config, const VideoSenderConfig* video_config, PacedPacketSender* transport) - : config_(), - transport_(transport), - clock_(clock) { + : cast_environment_(cast_environment), + config_(), + transport_(transport) { // Store generic cast config and create packetizer config. DCHECK(audio_config || video_config) << "Invalid argument"; if (audio_config) { - storage_.reset(new PacketStorage(clock, audio_config->rtp_history_ms)); + storage_.reset(new PacketStorage(cast_environment->Clock(), + audio_config->rtp_history_ms)); config_.audio = true; config_.ssrc = audio_config->sender_ssrc; config_.payload_type = audio_config->rtp_payload_type; config_.frequency = audio_config->frequency; config_.audio_codec = audio_config->codec; } else { - storage_.reset(new PacketStorage(clock, video_config->rtp_history_ms)); + storage_.reset(new PacketStorage(cast_environment->Clock(), + video_config->rtp_history_ms)); config_.audio = false; config_.ssrc = video_config->sender_ssrc; config_.payload_type = video_config->rtp_payload_type; @@ -58,15 +61,52 @@ void RtpSender::IncomingEncodedAudioFrame(const EncodedAudioFrame* audio_frame, void RtpSender::ResendPackets( const MissingFramesAndPacketsMap& missing_frames_and_packets) { - PacketList packets_to_resend = - storage_->GetPackets(missing_frames_and_packets); + // Iterate over all frames in the list. + for (MissingFramesAndPacketsMap::const_iterator it = + missing_frames_and_packets.begin(); + it != missing_frames_and_packets.end(); ++it) { + PacketList packets_to_resend; + uint8 frame_id = it->first; + const PacketIdSet& packets_set = it->second; + bool success = false; - PacketList::iterator it = packets_to_resend.begin(); - for (; it != packets_to_resend.end(); ++it) { - Packet& packet = *it; - UpdateSequenceNumber(&packet); + if (packets_set.empty()) { + VLOG(1) << "Missing all packets in frame " << static_cast<int>(frame_id); + + uint16 packet_id = 0; + do { + // Get packet from storage. + success = storage_->GetPacket(frame_id, packet_id, &packets_to_resend); + + // Resend packet to the network. + if (success) { + VLOG(1) << "Resend " << static_cast<int>(frame_id) + << ":" << packet_id; + // Set a unique incremental sequence number for every packet. + Packet& packet = packets_to_resend.back(); + UpdateSequenceNumber(&packet); + // Set the size as correspond to each frame. + ++packet_id; + } + } while (success); + } else { + // Iterate over all of the packets in the frame. + for (PacketIdSet::const_iterator set_it = packets_set.begin(); + set_it != packets_set.end(); ++set_it) { + uint16 packet_id = *set_it; + success = storage_->GetPacket(frame_id, packet_id, &packets_to_resend); + + // Resend packet to the network. + if (success) { + VLOG(1) << "Resend " << static_cast<int>(frame_id) + << ":" << packet_id; + Packet& packet = packets_to_resend.back(); + UpdateSequenceNumber(&packet); + } + } + } + transport_->ResendPackets(packets_to_resend); } - transport_->ResendPackets(packets_to_resend); } void RtpSender::UpdateSequenceNumber(Packet* packet) { diff --git a/media/cast/rtp_sender/rtp_sender.h b/media/cast/rtp_sender/rtp_sender.h index 45fd987..f56d7ef 100644 --- a/media/cast/rtp_sender/rtp_sender.h +++ b/media/cast/rtp_sender/rtp_sender.h @@ -14,6 +14,7 @@ #include "base/time/tick_clock.h" #include "base/time/time.h" #include "media/cast/cast_config.h" +#include "media/cast/cast_environment.h" #include "media/cast/rtp_sender/packet_storage/packet_storage.h" #include "media/cast/rtp_sender/rtp_packetizer/rtp_packetizer.h" #include "media/cast/rtp_sender/rtp_packetizer/rtp_packetizer_config.h" @@ -30,7 +31,7 @@ struct RtcpSenderInfo; // acknowledged by the remote peer or timed out. class RtpSender { public: - RtpSender(base::TickClock* clock, + RtpSender(scoped_refptr<CastEnvironment> cast_environment, const AudioSenderConfig* audio_config, const VideoSenderConfig* video_config, PacedPacketSender* transport); @@ -52,7 +53,7 @@ class RtpSender { private: void UpdateSequenceNumber(std::vector<uint8>* packet); - base::TickClock* const clock_; // Not owned by this class. + scoped_refptr<CastEnvironment> cast_environment_; RtpPacketizerConfig config_; scoped_ptr<RtpPacketizer> packetizer_; scoped_ptr<PacketStorage> storage_; diff --git a/media/cast/test/encode_decode_test.cc b/media/cast/test/encode_decode_test.cc index 2775dcb..0cf8929 100644 --- a/media/cast/test/encode_decode_test.cc +++ b/media/cast/test/encode_decode_test.cc @@ -74,7 +74,7 @@ class EncodeDecodeTest : public ::testing::Test { // CastEnvironment will only be used by the vp8 decoder; Enable only the // video decoder and main threads. cast_environment_(new CastEnvironment(&testing_clock_, task_runner_, - NULL, NULL, NULL, task_runner_)), + NULL, NULL, NULL, task_runner_, GetDefaultCastLoggingConfig())), test_callback_(new EncodeDecodeTestFrameCallback()) { testing_clock_.Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); diff --git a/media/cast/test/end2end_unittest.cc b/media/cast/test/end2end_unittest.cc index 5375d21..584f249 100644 --- a/media/cast/test/end2end_unittest.cc +++ b/media/cast/test/end2end_unittest.cc @@ -329,7 +329,8 @@ class End2EndTest : public ::testing::Test { End2EndTest() : task_runner_(new test::FakeTaskRunner(&testing_clock_)), cast_environment_(new CastEnvironment(&testing_clock_, task_runner_, - task_runner_, task_runner_, task_runner_, task_runner_)), + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig())), sender_to_receiver_(cast_environment_), receiver_to_sender_(cast_environment_), test_receiver_audio_callback_(new TestReceiverAudioCallback()), diff --git a/media/cast/test/receiver.cc b/media/cast/test/receiver.cc index 81aa148..74b9116 100644 --- a/media/cast/test/receiver.cc +++ b/media/cast/test/receiver.cc @@ -18,6 +18,7 @@ #include "media/cast/cast_config.h" #include "media/cast/cast_environment.h" #include "media/cast/cast_receiver.h" +#include "media/cast/logging/logging_defines.h" #include "media/cast/test/transport/transport.h" #include "media/cast/test/utility/input_helper.h" @@ -201,9 +202,11 @@ int main(int argc, char** argv) { base::DefaultTickClock clock; scoped_refptr<base::SequencedTaskRunner> task_runner(main_message_loop.message_loop_proxy()); + // Enable receiver side threads, and disable logging. scoped_refptr<media::cast::CastEnvironment> cast_environment(new media::cast::CastEnvironment(&clock, - task_runner, NULL, task_runner, NULL, task_runner)); + task_runner, NULL, task_runner, NULL, task_runner, + media::cast::GetDefaultCastLoggingConfig())); media::cast::AudioReceiverConfig audio_config = media::cast::GetAudioReceiverConfig(); diff --git a/media/cast/test/sender.cc b/media/cast/test/sender.cc index 6634959..90395d4 100644 --- a/media/cast/test/sender.cc +++ b/media/cast/test/sender.cc @@ -16,6 +16,7 @@ #include "media/cast/cast_config.h" #include "media/cast/cast_environment.h" #include "media/cast/cast_sender.h" +#include "media/cast/logging/logging_defines.h" #include "media/cast/test/audio_utility.h" #include "media/cast/test/transport/transport.h" #include "media/cast/test/utility/input_helper.h" @@ -284,10 +285,11 @@ int main(int argc, char** argv) { scoped_refptr<base::SequencedTaskRunner> task_runner(main_message_loop.message_loop_proxy()); - // Enable main and send side threads only. + // Enable main and send side threads only. Disable logging. + media::cast::CastLoggingConfig logging_config; scoped_refptr<media::cast::CastEnvironment> cast_environment(new media::cast::CastEnvironment(&clock, task_runner, task_runner, NULL, - task_runner, NULL)); + task_runner, NULL, media::cast::GetDefaultCastLoggingConfig())); media::cast::AudioSenderConfig audio_config = media::cast::GetAudioSenderConfig(); diff --git a/media/cast/video_receiver/codecs/vp8/vp8_decoder.cc b/media/cast/video_receiver/codecs/vp8/vp8_decoder.cc index d9ad3f1..84d4fa9 100644 --- a/media/cast/video_receiver/codecs/vp8/vp8_decoder.cc +++ b/media/cast/video_receiver/codecs/vp8/vp8_decoder.cc @@ -84,8 +84,10 @@ bool Vp8Decoder::Decode(const EncodedVideoFrame* encoded_frame, memcpy(decoded_frame->v_plane.data, img->planes[VPX_PLANE_V], decoded_frame->v_plane.length); - // Return frame. + cast_environment_->Logging()->InsertFrameEvent(kVideoFrameDecoded, + kFrameIdUnknown, encoded_frame->frame_id); VLOG(1) << "Decoded frame " << frame_id_int; + // Frame decoded - return frame to the user via callback. cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, base::Bind(frame_decoded_cb, base::Passed(&decoded_frame), render_time)); diff --git a/media/cast/video_receiver/video_decoder_unittest.cc b/media/cast/video_receiver/video_decoder_unittest.cc index dbf95dd..f03b467 100644 --- a/media/cast/video_receiver/video_decoder_unittest.cc +++ b/media/cast/video_receiver/video_decoder_unittest.cc @@ -43,7 +43,8 @@ class VideoDecoderTest : public ::testing::Test { VideoDecoderTest() : task_runner_(new test::FakeTaskRunner(&testing_clock_)), cast_environment_(new CastEnvironment(&testing_clock_, task_runner_, - task_runner_, task_runner_, task_runner_, task_runner_)), + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig())), test_callback_(new DecodeTestFrameCallback()) { // Configure to vp8. config_.codec = kVp8; diff --git a/media/cast/video_receiver/video_receiver.cc b/media/cast/video_receiver/video_receiver.cc index 2bcd5ce..c637d7a 100644 --- a/media/cast/video_receiver/video_receiver.cc +++ b/media/cast/video_receiver/video_receiver.cc @@ -127,7 +127,7 @@ VideoReceiver::VideoReceiver(scoped_refptr<CastEnvironment> cast_environment, } rtcp_.reset( - new Rtcp(cast_environment_->Clock(), + new Rtcp(cast_environment_, NULL, packet_sender, NULL, @@ -249,6 +249,10 @@ bool VideoReceiver::PullEncodedVideoFrame(uint32 rtp_timestamp, DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); base::TimeTicks now = cast_environment_->Clock()->NowTicks(); *render_time = GetRenderTime(now, rtp_timestamp); + base::TimeDelta diff = now - *render_time; + + cast_environment_->Logging()->InsertFrameEvent(kVideoRenderDelay, + rtp_timestamp, diff.InMilliseconds()); // Minimum time before a frame is due to be rendered before we pull it for // decode. @@ -391,6 +395,10 @@ void VideoReceiver::IncomingParsedRtpPacket(const uint8* payload_data, time_incoming_packet_updated_ = true; } + cast_environment_->Logging()->InsertPacketEvent(kPacketReceived, + rtp_header.webrtc.header.timestamp, rtp_header.frame_id, + rtp_header.packet_id, rtp_header.max_packet_id, payload_size); + bool complete = framer_->InsertPacket(payload_data, payload_size, rtp_header); if (!complete) return; // Video frame not complete; wait for more packets. diff --git a/media/cast/video_receiver/video_receiver_unittest.cc b/media/cast/video_receiver/video_receiver_unittest.cc index 29efa5d..b5dda546 100644 --- a/media/cast/video_receiver/video_receiver_unittest.cc +++ b/media/cast/video_receiver/video_receiver_unittest.cc @@ -73,7 +73,8 @@ class VideoReceiverTest : public ::testing::Test { config_.use_external_decoder = false; task_runner_ = new test::FakeTaskRunner(&testing_clock_); cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_, - task_runner_, task_runner_, task_runner_, task_runner_); + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig()); receiver_.reset(new PeerVideoReceiver(cast_environment_, config_, &mock_transport_)); testing_clock_.Advance( diff --git a/media/cast/video_sender/video_encoder.cc b/media/cast/video_sender/video_encoder.cc index a4f350a..adc08c1 100644 --- a/media/cast/video_sender/video_encoder.cc +++ b/media/cast/video_sender/video_encoder.cc @@ -66,6 +66,9 @@ void VideoEncoder::EncodeVideoFrameEncoderThread( dynamic_config.latest_frame_id_to_reference); vp8_encoder_->UpdateRates(dynamic_config.bit_rate); + uint32 rtp_timestamp = GetVideoRtpTimestamp(capture_time); + cast_environment_->Logging()->InsertFrameEvent(kVideoFrameSentToEncoder, + rtp_timestamp, kFrameIdUnknown); scoped_ptr<EncodedVideoFrame> encoded_frame(new EncodedVideoFrame()); bool retval = vp8_encoder_->Encode(*video_frame, encoded_frame.get()); @@ -81,6 +84,8 @@ void VideoEncoder::EncodeVideoFrameEncoderThread( VLOG(1) << "Encoding resulted in an empty frame"; return; } + cast_environment_->Logging()->InsertFrameEvent(kVideoFrameEncoded, + rtp_timestamp, kFrameIdUnknown); cast_environment_->PostTask(CastEnvironment::MAIN, FROM_HERE, base::Bind(frame_encoded_callback, base::Passed(&encoded_frame), capture_time)); diff --git a/media/cast/video_sender/video_encoder_unittest.cc b/media/cast/video_sender/video_encoder_unittest.cc index a68db22..b492e70 100644 --- a/media/cast/video_sender/video_encoder_unittest.cc +++ b/media/cast/video_sender/video_encoder_unittest.cc @@ -97,7 +97,8 @@ class VideoEncoderTest : public ::testing::Test { virtual void SetUp() { task_runner_ = new test::FakeTaskRunner(&testing_clock_); cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_, - task_runner_, task_runner_, task_runner_, task_runner_); + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig()); } void Configure(uint8 max_unacked_frames) { diff --git a/media/cast/video_sender/video_sender.cc b/media/cast/video_sender/video_sender.cc index a0acb83..2591b12 100644 --- a/media/cast/video_sender/video_sender.cc +++ b/media/cast/video_sender/video_sender.cc @@ -60,7 +60,7 @@ VideoSender::VideoSender( max_frame_rate_(video_config.max_frame_rate), cast_environment_(cast_environment), rtcp_feedback_(new LocalRtcpVideoSenderFeedback(this)), - rtp_sender_(new RtpSender(cast_environment->Clock(), NULL, &video_config, + rtp_sender_(new RtpSender(cast_environment, NULL, &video_config, paced_packet_sender)), last_acked_frame_id_(-1), last_sent_frame_id_(-1), @@ -103,7 +103,7 @@ VideoSender::VideoSender( } rtcp_.reset(new Rtcp( - cast_environment_->Clock(), + cast_environment_, rtcp_feedback_.get(), paced_packet_sender, rtp_video_sender_statistics_.get(), @@ -311,6 +311,8 @@ void VideoSender::OnReceivedCastFeedback(const RtcpCastMessage& cast_feedback) { base::TimeDelta max_rtt; if (rtcp_->Rtt(&rtt, &avg_rtt, &min_rtt, &max_rtt)) { + cast_environment_->Logging()->InsertGenericEvent(kRttMs, + rtt.InMilliseconds()); // Don't use a RTT lower than our average. rtt = std::max(rtt, avg_rtt); } else { @@ -365,6 +367,10 @@ void VideoSender::ReceivedAck(uint32 acked_frame_id) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); VLOG(1) << "ReceivedAck:" << acked_frame_id; last_acked_frame_id_ = static_cast<int>(acked_frame_id); + cast_environment_->Logging()->InsertGenericEvent(kAckReceived, + acked_frame_id); + VLOG(1) << "ReceivedAck:" << static_cast<int>(acked_frame_id); + last_acked_frame_id_ = acked_frame_id; UpdateFramesInFlight(); } diff --git a/media/cast/video_sender/video_sender_unittest.cc b/media/cast/video_sender/video_sender_unittest.cc index 3269c85..9c9bffc 100644 --- a/media/cast/video_sender/video_sender_unittest.cc +++ b/media/cast/video_sender/video_sender_unittest.cc @@ -88,7 +88,8 @@ class VideoSenderTest : public ::testing::Test { virtual void SetUp() { task_runner_ = new test::FakeTaskRunner(&testing_clock_); cast_environment_ = new CastEnvironment(&testing_clock_, task_runner_, - task_runner_, task_runner_, task_runner_, task_runner_); + task_runner_, task_runner_, task_runner_, task_runner_, + GetDefaultCastLoggingConfig()); } I420VideoFrame* AllocateNewVideoFrame() { |