From 0c42d8eeb1fcb81fb23312b52a7c5a8b7d012d0a Mon Sep 17 00:00:00 2001 From: "pwestin@google.com" Date: Tue, 17 Dec 2013 23:12:07 +0000 Subject: Cast: Changing log classes to support incoming time of event. Prior to this cl the log class retrived the time from the system with this change the time of a log event can be specified by the caller. This change is needed for the receiver of a RTCP message that contain log messages to insert them with a correct time. Review URL: https://codereview.chromium.org/111663003 git-svn-id: svn://svn.chromium.org/chrome/trunk/src@241404 0039d316-1c4b-4281-b951-d872f2087c98 --- media/cast/audio_receiver/audio_receiver.cc | 14 +++-- media/cast/audio_sender/audio_encoder.cc | 4 +- media/cast/audio_sender/audio_sender.cc | 8 ++- media/cast/cast_environment.cc | 2 +- media/cast/logging/logging_impl.cc | 74 ++++++++++++++---------- media/cast/logging/logging_impl.h | 33 +++++++---- media/cast/logging/logging_raw.cc | 43 ++++++++------ media/cast/logging/logging_raw.h | 22 ++++--- media/cast/logging/logging_stats.cc | 61 +++++++++++--------- media/cast/logging/logging_stats.h | 30 +++++----- media/cast/logging/logging_unittest.cc | 89 +++++++++++++++++------------ media/cast/net/pacing/paced_sender.cc | 9 ++- media/cast/rtcp/rtcp.cc | 33 ++++++----- media/cast/rtcp/rtcp_receiver.cc | 5 +- media/cast/rtcp/rtcp_sender.cc | 3 +- media/cast/video_receiver/video_receiver.cc | 7 ++- media/cast/video_sender/video_encoder.cc | 6 +- media/cast/video_sender/video_sender.cc | 12 ++-- 18 files changed, 268 insertions(+), 187 deletions(-) (limited to 'media') diff --git a/media/cast/audio_receiver/audio_receiver.cc b/media/cast/audio_receiver/audio_receiver.cc index 5aad22f..d1eb11c 100644 --- a/media/cast/audio_receiver/audio_receiver.cc +++ b/media/cast/audio_receiver/audio_receiver.cc @@ -152,7 +152,9 @@ void AudioReceiver::IncomingParsedRtpPacket(const uint8* payload_data, size_t payload_size, const RtpCastHeader& rtp_header) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); - cast_environment_->Logging()->InsertPacketEvent(kPacketReceived, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + + cast_environment_->Logging()->InsertPacketEvent(now, kPacketReceived, rtp_header.webrtc.header.timestamp, rtp_header.frame_id, rtp_header.packet_id, rtp_header.max_packet_id, payload_size); @@ -161,7 +163,7 @@ void AudioReceiver::IncomingParsedRtpPacket(const uint8* payload_data, if (time_first_incoming_packet_.is_null()) { InitializeTimers(); first_incoming_rtp_timestamp_ = rtp_header.webrtc.header.timestamp; - time_first_incoming_packet_ = cast_environment_->Clock()->NowTicks(); + time_first_incoming_packet_ = now; } if (audio_decoder_) { @@ -255,14 +257,14 @@ void AudioReceiver::ReturnDecodedFrameWithPlayoutDelay( scoped_ptr audio_frame, uint32 rtp_timestamp, const AudioFrameDecodedCallback callback) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); - cast_environment_->Logging()->InsertFrameEvent(kAudioFrameDecoded, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertFrameEvent(now, kAudioFrameDecoded, rtp_timestamp, kFrameIdUnknown); - base::TimeTicks now = cast_environment_->Clock()->NowTicks(); base::TimeTicks playout_time = GetPlayoutTime(now, rtp_timestamp); - cast_environment_->Logging()->InsertFrameEventWithDelay(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, diff --git a/media/cast/audio_sender/audio_encoder.cc b/media/cast/audio_sender/audio_encoder.cc index a82d1de..c71329a 100644 --- a/media/cast/audio_sender/audio_encoder.cc +++ b/media/cast/audio_sender/audio_encoder.cc @@ -23,7 +23,9 @@ namespace cast { void LogAudioEncodedEvent(CastEnvironment* const cast_environment, const base::TimeTicks& recorded_time) { // TODO(mikhal): Resolve timestamp calculation for audio. - cast_environment->Logging()->InsertFrameEvent(kAudioFrameEncoded, + base::TimeTicks now = cast_environment->Clock()->NowTicks(); + + cast_environment->Logging()->InsertFrameEvent(now, kAudioFrameEncoded, GetVideoRtpTimestamp(recorded_time), kFrameIdUnknown); } diff --git a/media/cast/audio_sender/audio_sender.cc b/media/cast/audio_sender/audio_sender.cc index b1b177d..7c20ad1 100644 --- a/media/cast/audio_sender/audio_sender.cc +++ b/media/cast/audio_sender/audio_sender.cc @@ -110,8 +110,9 @@ void AudioSender::InsertAudio(const AudioBus* audio_bus, DCHECK(audio_encoder_.get()) << "Invalid internal state"; // TODO(mikhal): Resolve calculation of the audio rtp_timestamp for logging. // This is a tmp solution to allow the code to build. - cast_environment_->Logging()->InsertFrameEvent(kAudioFrameReceived, - GetVideoRtpTimestamp(recorded_time), kFrameIdUnknown); + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertFrameEvent(now, kAudioFrameReceived, + GetVideoRtpTimestamp(recorded_time), kFrameIdUnknown); audio_encoder_->InsertAudio(audio_bus, recorded_time, done_callback); } @@ -121,7 +122,8 @@ void AudioSender::InsertCodedAudioFrame(const EncodedAudioFrame* audio_frame, DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); DCHECK(audio_encoder_.get() == NULL) << "Invalid internal state"; - cast_environment_->Logging()->InsertFrameEvent(kAudioFrameReceived, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertFrameEvent(now, kAudioFrameReceived, GetVideoRtpTimestamp(recorded_time), kFrameIdUnknown); if (encryptor_) { diff --git a/media/cast/cast_environment.cc b/media/cast/cast_environment.cc index be636bb..482534f 100644 --- a/media/cast/cast_environment.cc +++ b/media/cast/cast_environment.cc @@ -25,7 +25,7 @@ CastEnvironment::CastEnvironment( audio_decode_thread_proxy_(audio_decode_thread_proxy), video_encode_thread_proxy_(video_encode_thread_proxy), video_decode_thread_proxy_(video_decode_thread_proxy), - logging_(new LoggingImpl(clock, main_thread_proxy, config)) { + logging_(new LoggingImpl(main_thread_proxy, config)) { DCHECK(main_thread_proxy) << "Main thread required"; } diff --git a/media/cast/logging/logging_impl.cc b/media/cast/logging/logging_impl.cc index ea96b94..1c67c50 100644 --- a/media/cast/logging/logging_impl.cc +++ b/media/cast/logging/logging_impl.cc @@ -10,23 +10,23 @@ namespace media { namespace cast { -LoggingImpl::LoggingImpl(base::TickClock* clock, - scoped_refptr main_thread_proxy, +LoggingImpl::LoggingImpl(scoped_refptr main_thread_proxy, const CastLoggingConfig& config) : main_thread_proxy_(main_thread_proxy), config_(config), - raw_(clock), - stats_(clock) {} + raw_(), + stats_() {} LoggingImpl::~LoggingImpl() {} -void LoggingImpl::InsertFrameEvent(CastLoggingEvent event, +void LoggingImpl::InsertFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id) { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); if (config_.enable_data_collection) { - raw_.InsertFrameEvent(event, rtp_timestamp, frame_id); - stats_.InsertFrameEvent(event, rtp_timestamp, frame_id); + raw_.InsertFrameEvent(time_of_event, event, rtp_timestamp, frame_id); + stats_.InsertFrameEvent(time_of_event, event, rtp_timestamp, frame_id); } if (config_.enable_tracing) { std::string event_string = CastLoggingToString(event); @@ -36,14 +36,17 @@ void LoggingImpl::InsertFrameEvent(CastLoggingEvent event, } } -void LoggingImpl::InsertFrameEventWithSize(CastLoggingEvent event, +void LoggingImpl::InsertFrameEventWithSize(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, int frame_size) { 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); + raw_.InsertFrameEventWithSize(time_of_event, event, rtp_timestamp, frame_id, + frame_size); + stats_.InsertFrameEventWithSize(time_of_event, event, rtp_timestamp, + frame_id, frame_size); } if (config_.enable_uma_stats) { UMA_HISTOGRAM_COUNTS(CastLoggingToString(event), frame_size); @@ -56,14 +59,18 @@ void LoggingImpl::InsertFrameEventWithSize(CastLoggingEvent event, } } -void LoggingImpl::InsertFrameEventWithDelay(CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - base::TimeDelta delay) { +void LoggingImpl::InsertFrameEventWithDelay( + 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_data_collection) { - raw_.InsertFrameEventWithDelay(event, rtp_timestamp, frame_id, delay); - stats_.InsertFrameEventWithDelay(event, rtp_timestamp, frame_id, delay); + raw_.InsertFrameEventWithDelay(time_of_event, event, rtp_timestamp, + frame_id, delay); + stats_.InsertFrameEventWithDelay(time_of_event, event, rtp_timestamp, + frame_id, delay); } if (config_.enable_uma_stats) { UMA_HISTOGRAM_TIMES(CastLoggingToString(event), delay); @@ -76,7 +83,8 @@ void LoggingImpl::InsertFrameEventWithDelay(CastLoggingEvent event, } } -void LoggingImpl::InsertPacketListEvent(CastLoggingEvent event, +void LoggingImpl::InsertPacketListEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, const PacketList& packets) { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); for (unsigned int i = 0; i < packets.size(); ++i) { @@ -91,12 +99,13 @@ void LoggingImpl::InsertPacketListEvent(CastLoggingEvent event, cast_big_endian_reader.ReadU16(&packet_id); cast_big_endian_reader.ReadU16(&max_packet_id); // rtp_timestamp is enough - no need for frame_id as well. - InsertPacketEvent(event, rtp_timestamp, kFrameIdUnknown, packet_id, - max_packet_id, packet.size()); + InsertPacketEvent(time_of_event, event, rtp_timestamp, kFrameIdUnknown, + packet_id, max_packet_id, packet.size()); } } -void LoggingImpl::InsertPacketEvent(CastLoggingEvent event, +void LoggingImpl::InsertPacketEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, uint16 packet_id, @@ -104,10 +113,10 @@ void LoggingImpl::InsertPacketEvent(CastLoggingEvent event, 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); + raw_.InsertPacketEvent(time_of_event, event, rtp_timestamp, frame_id, + packet_id, max_packet_id, size); + stats_.InsertPacketEvent(time_of_event, event, rtp_timestamp, frame_id, + packet_id, max_packet_id, size); } if (config_.enable_tracing) { std::string event_string = CastLoggingToString(event); @@ -117,11 +126,12 @@ void LoggingImpl::InsertPacketEvent(CastLoggingEvent event, } } -void LoggingImpl::InsertGenericEvent(CastLoggingEvent event, int value) { +void LoggingImpl::InsertGenericEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, int value) { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); if (config_.enable_data_collection) { - raw_.InsertGenericEvent(event, value); - stats_.InsertGenericEvent(event, value); + raw_.InsertGenericEvent(time_of_event, event, value); + stats_.InsertGenericEvent(time_of_event, event, value); } if (config_.enable_uma_stats) { UMA_HISTOGRAM_COUNTS(CastLoggingToString(event), value); @@ -149,10 +159,11 @@ GenericRawMap LoggingImpl::GetGenericRawData() { return raw_.GetGenericData(); } -const FrameStatsMap* LoggingImpl::GetFrameStatsData() { +const FrameStatsMap* LoggingImpl::GetFrameStatsData( + const base::TimeTicks& now) { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); // Get stats data. - const FrameStatsMap* stats = stats_.GetFrameStatsData(); + const FrameStatsMap* stats = stats_.GetFrameStatsData(now); if (config_.enable_uma_stats) { FrameStatsMap::const_iterator it; for (it = stats->begin(); it != stats->end(); ++it) { @@ -184,10 +195,11 @@ const FrameStatsMap* LoggingImpl::GetFrameStatsData() { return stats; } -const PacketStatsMap* LoggingImpl::GetPacketStatsData() { +const PacketStatsMap* LoggingImpl::GetPacketStatsData( + const base::TimeTicks& now) { DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread()); // Get stats data. - const PacketStatsMap* stats = stats_.GetPacketStatsData(); + const PacketStatsMap* stats = stats_.GetPacketStatsData(now); if (config_.enable_uma_stats) { PacketStatsMap::const_iterator it; for (it = stats->begin(); it != stats->end(); ++it) { diff --git a/media/cast/logging/logging_impl.h b/media/cast/logging/logging_impl.h index 34021b7..d065655 100644 --- a/media/cast/logging/logging_impl.h +++ b/media/cast/logging/logging_impl.h @@ -23,42 +23,51 @@ namespace cast { // Should only be called from the main thread. class LoggingImpl : public base::NonThreadSafe { public: - LoggingImpl(base::TickClock* clock, - scoped_refptr main_thread_proxy, + LoggingImpl(scoped_refptr main_thread_proxy, const CastLoggingConfig& config); ~LoggingImpl(); - // TODO(pwestin): Add argument to API to send in time of event instead of - // grabbing now. - void InsertFrameEvent(CastLoggingEvent event, + void InsertFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id); - void InsertFrameEventWithSize(CastLoggingEvent event, + + void InsertFrameEventWithSize(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, int frame_size); - void InsertFrameEventWithDelay(CastLoggingEvent event, + + void InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, base::TimeDelta delay); - void InsertPacketListEvent(CastLoggingEvent event, const PacketList& packets); - void InsertPacketEvent(CastLoggingEvent event, + void InsertPacketListEvent(const base::TimeTicks& time_of_event, + 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); - void InsertGenericEvent(CastLoggingEvent event, int value); + + void InsertGenericEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, + int value); // Get raw data. FrameRawMap GetFrameRawData(); PacketRawMap GetPacketRawData(); GenericRawMap GetGenericRawData(); // Get stats only (computed when called). Triggers UMA stats when enabled. - const FrameStatsMap* GetFrameStatsData(); - const PacketStatsMap* GetPacketStatsData(); + const FrameStatsMap* GetFrameStatsData(const base::TimeTicks& now); + const PacketStatsMap* GetPacketStatsData(const base::TimeTicks& now); const GenericStatsMap* GetGenericStatsData(); void Reset(); diff --git a/media/cast/logging/logging_raw.cc b/media/cast/logging/logging_raw.cc index 6a38961..9525729 100644 --- a/media/cast/logging/logging_raw.cc +++ b/media/cast/logging/logging_raw.cc @@ -11,44 +11,47 @@ namespace media { namespace cast { -LoggingRaw::LoggingRaw(base::TickClock* clock) - : clock_(clock), - frame_map_(), +LoggingRaw::LoggingRaw() + : frame_map_(), packet_map_(), generic_map_(), weak_factory_(this) {} LoggingRaw::~LoggingRaw() {} -void LoggingRaw::InsertFrameEvent(CastLoggingEvent event, +void LoggingRaw::InsertFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id) { - InsertBaseFrameEvent(event, frame_id, rtp_timestamp); + InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp); } -void LoggingRaw::InsertFrameEventWithSize(CastLoggingEvent event, +void LoggingRaw::InsertFrameEventWithSize(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, int size) { - InsertBaseFrameEvent(event, frame_id, rtp_timestamp); + 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; } -void LoggingRaw::InsertFrameEventWithDelay(CastLoggingEvent event, +void LoggingRaw::InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, base::TimeDelta delay) { - InsertBaseFrameEvent(event, frame_id, rtp_timestamp); + 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; } -void LoggingRaw::InsertBaseFrameEvent(CastLoggingEvent event, +void LoggingRaw::InsertBaseFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 frame_id, uint32 rtp_timestamp) { // Is this a new event? @@ -57,12 +60,12 @@ void LoggingRaw::InsertBaseFrameEvent(CastLoggingEvent event, // Create a new map entry. FrameEvent info; info.frame_id = frame_id; - info.timestamp.push_back(clock_->NowTicks()); + 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(clock_->NowTicks()); + 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. @@ -71,7 +74,8 @@ void LoggingRaw::InsertBaseFrameEvent(CastLoggingEvent event, } } -void LoggingRaw::InsertPacketEvent(CastLoggingEvent event, +void LoggingRaw::InsertPacketEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, uint16 packet_id, @@ -86,7 +90,7 @@ void LoggingRaw::InsertPacketEvent(CastLoggingEvent event, info.max_packet_id = max_packet_id; BasePacketInfo base_info; base_info.size = size; - base_info.timestamp.push_back(clock_->NowTicks()); + base_info.timestamp.push_back(time_of_event); base_info.type.push_back(event); packet_map_.insert(std::make_pair(rtp_timestamp, info)); } else { @@ -95,20 +99,21 @@ void LoggingRaw::InsertPacketEvent(CastLoggingEvent event, if (packet_it == it->second.packet_map.end()) { BasePacketInfo base_info; base_info.size = size; - base_info.timestamp.push_back(clock_->NowTicks()); + 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(clock_->NowTicks()); + packet_it->second.timestamp.push_back(time_of_event); packet_it->second.type.push_back(event); } } } -void LoggingRaw::InsertGenericEvent(CastLoggingEvent event, int value) { +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(clock_->NowTicks()); + 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()) { @@ -117,7 +122,7 @@ void LoggingRaw::InsertGenericEvent(CastLoggingEvent event, int value) { } else { // Insert to existing entry. it->second.value.push_back(value); - it->second.timestamp.push_back(clock_->NowTicks()); + it->second.timestamp.push_back(time_of_event); } } diff --git a/media/cast/logging/logging_raw.h b/media/cast/logging/logging_raw.h index 4ac8d0f..7911178 100644 --- a/media/cast/logging/logging_raw.h +++ b/media/cast/logging/logging_raw.h @@ -24,36 +24,42 @@ namespace cast { class LoggingRaw : public base::NonThreadSafe, public base::SupportsWeakPtr { public: - explicit LoggingRaw(base::TickClock* clock); + LoggingRaw(); ~LoggingRaw(); // Inform of new event: three types of events: frame, packets and generic. // Frame events can be inserted with different parameters. - void InsertFrameEvent(CastLoggingEvent event, + void InsertFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id); // Size - Inserting the size implies that this is an encoded frame. - void InsertFrameEventWithSize(CastLoggingEvent event, + void InsertFrameEventWithSize(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, int frame_size); // Render/playout delay - void InsertFrameEventWithDelay(CastLoggingEvent event, + void InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, base::TimeDelta delay); // Insert a packet event. - void InsertPacketEvent(CastLoggingEvent 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); - void InsertGenericEvent(CastLoggingEvent event, int value); + void InsertGenericEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, + int value); // Get raw log data. FrameRawMap GetFrameData() const; @@ -65,11 +71,11 @@ class LoggingRaw : public base::NonThreadSafe, void Reset(); private: - void InsertBaseFrameEvent(CastLoggingEvent event, + void InsertBaseFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 frame_id, uint32 rtp_timestamp); - base::TickClock* const clock_; // Not owned by this class. FrameRawMap frame_map_; PacketRawMap packet_map_; GenericRawMap generic_map_; diff --git a/media/cast/logging/logging_stats.cc b/media/cast/logging/logging_stats.cc index 84fdbf7..4b9d000 100644 --- a/media/cast/logging/logging_stats.cc +++ b/media/cast/logging/logging_stats.cc @@ -9,12 +9,11 @@ namespace media { namespace cast { -LoggingStats::LoggingStats(base::TickClock* clock) +LoggingStats::LoggingStats() : frame_stats_(), packet_stats_(), generic_stats_(), - start_time_(), - clock_(clock) { + start_time_() { memset(counts_, 0, sizeof(counts_)); memset(start_time_, 0, sizeof(start_time_)); } @@ -28,28 +27,33 @@ void LoggingStats::Reset() { memset(counts_, 0, sizeof(counts_)); } -void LoggingStats::InsertFrameEvent(CastLoggingEvent event, +void LoggingStats::InsertFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id) { - InsertBaseFrameEvent(event, frame_id, rtp_timestamp); + InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp); } -void LoggingStats::InsertFrameEventWithSize(CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - int frame_size) { - InsertBaseFrameEvent(event, frame_id, rtp_timestamp); +void LoggingStats::InsertFrameEventWithSize( + const base::TimeTicks& time_of_event, + CastLoggingEvent event, + uint32 rtp_timestamp, + uint32 frame_id, + int frame_size) { + InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp); // Update size. FrameStatsMap::iterator it = frame_stats_.find(event); DCHECK(it != frame_stats_.end()); it->second->bitrate_kbps += frame_size; } -void LoggingStats::InsertFrameEventWithDelay(CastLoggingEvent event, - uint32 rtp_timestamp, - uint32 frame_id, - base::TimeDelta delay) { - InsertBaseFrameEvent(event, frame_id, rtp_timestamp); +void LoggingStats::InsertFrameEventWithDelay( + const base::TimeTicks& time_of_event, + CastLoggingEvent event, + uint32 rtp_timestamp, + uint32 frame_id, + base::TimeDelta delay) { + InsertBaseFrameEvent(time_of_event, event, frame_id, rtp_timestamp); // Update size. FrameStatsMap::iterator it = frame_stats_.find(event); DCHECK(it != frame_stats_.end()); @@ -63,14 +67,15 @@ void LoggingStats::InsertFrameEventWithDelay(CastLoggingEvent event, it->second->min_delay_ms = delay.InMilliseconds(); } -void LoggingStats::InsertBaseFrameEvent(CastLoggingEvent event, +void LoggingStats::InsertBaseFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 frame_id, uint32 rtp_timestamp) { // Does this belong to an existing event? FrameStatsMap::iterator it = frame_stats_.find(event); if (it == frame_stats_.end()) { // New event. - start_time_[event] = clock_->NowTicks(); + start_time_[event] = time_of_event; linked_ptr stats(new FrameLogStats()); frame_stats_.insert(std::make_pair(event, stats)); } @@ -78,7 +83,8 @@ void LoggingStats::InsertBaseFrameEvent(CastLoggingEvent event, ++counts_[event]; } -void LoggingStats::InsertPacketEvent(CastLoggingEvent event, +void LoggingStats::InsertPacketEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, uint16 packet_id, @@ -88,7 +94,7 @@ void LoggingStats::InsertPacketEvent(CastLoggingEvent event, PacketStatsMap::iterator it = packet_stats_.find(event); if (it == packet_stats_.end()) { // New event. - start_time_[event] = clock_->NowTicks(); + start_time_[event] = time_of_event; packet_stats_.insert(std::make_pair(event, size)); } else { // Add to existing. @@ -97,25 +103,27 @@ void LoggingStats::InsertPacketEvent(CastLoggingEvent event, ++counts_[event]; } -void LoggingStats::InsertGenericEvent(CastLoggingEvent event, int value) { +void LoggingStats::InsertGenericEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, int value) { // Does this event belong to an existing event? GenericStatsMap::iterator it = generic_stats_.find(event); if (it == generic_stats_.end()) { // New event. - start_time_[event] = clock_->NowTicks(); + start_time_[event] = time_of_event; generic_stats_.insert(std::make_pair(event, value)); } else { // Add to existing (will be used to compute average). it->second += value; } - ++counts_[event]; + ++counts_[event]; } -const FrameStatsMap* LoggingStats::GetFrameStatsData() { +const FrameStatsMap* LoggingStats::GetFrameStatsData( + const base::TimeTicks& now) { // Compute framerate and bitrate (when available). FrameStatsMap::iterator it; for (it = frame_stats_.begin(); it != frame_stats_.end(); ++it) { - base::TimeDelta time_diff = clock_->NowTicks() - start_time_[it->first]; + base::TimeDelta time_diff = now - start_time_[it->first]; it->second->framerate_fps = counts_[it->first] / time_diff.InSecondsF(); if (it->second->bitrate_kbps > 0) { it->second->bitrate_kbps = (8 / 1000) * @@ -127,11 +135,12 @@ const FrameStatsMap* LoggingStats::GetFrameStatsData() { return &frame_stats_; } -const PacketStatsMap* LoggingStats::GetPacketStatsData() { +const PacketStatsMap* LoggingStats::GetPacketStatsData( + const base::TimeTicks& now) { PacketStatsMap::iterator it; for (it = packet_stats_.begin(); it != packet_stats_.end(); ++it) { if (counts_[it->first] == 0) continue; - base::TimeDelta time_diff = clock_->NowTicks() - start_time_[it->first]; + base::TimeDelta time_diff = now - start_time_[it->first]; it->second = (8 / 1000) * it->second / time_diff.InSecondsF(); } return &packet_stats_; diff --git a/media/cast/logging/logging_stats.h b/media/cast/logging/logging_stats.h index f08649c..4421ecd 100644 --- a/media/cast/logging/logging_stats.h +++ b/media/cast/logging/logging_stats.h @@ -6,7 +6,6 @@ #define MEDIA_CAST_LOGGING_LOGGING_STATS_H_ #include "base/basictypes.h" -#include "base/time/tick_clock.h" #include "base/time/time.h" #include "media/cast/logging/logging_defines.h" @@ -15,47 +14,53 @@ namespace cast { class LoggingStats { public: - explicit LoggingStats(base::TickClock* clock); - + LoggingStats(); ~LoggingStats(); void Reset(); - void InsertFrameEvent(CastLoggingEvent event, + void InsertFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id); - void InsertFrameEventWithSize(CastLoggingEvent event, + void InsertFrameEventWithSize(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, int frame_size); - void InsertFrameEventWithDelay(CastLoggingEvent event, + void InsertFrameEventWithDelay(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 rtp_timestamp, uint32 frame_id, base::TimeDelta delay); - void InsertPacketEvent(CastLoggingEvent 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); - void InsertGenericEvent(CastLoggingEvent event, int value); + void InsertGenericEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, int value); // Get log stats: some of the values, such as frame rate and bit rates are // computed at the time of the call. - const FrameStatsMap* GetFrameStatsData(); + const FrameStatsMap* GetFrameStatsData(const base::TimeTicks& now); - const PacketStatsMap* GetPacketStatsData(); + const PacketStatsMap* GetPacketStatsData(const base::TimeTicks& now); const GenericStatsMap* GetGenericStatsData(); private: - void InsertBaseFrameEvent(CastLoggingEvent event, + void InsertBaseFrameEvent(const base::TimeTicks& time_of_event, + CastLoggingEvent event, uint32 frame_id, uint32 rtp_timestamp); + FrameStatsMap frame_stats_; PacketStatsMap packet_stats_; GenericStatsMap generic_stats_; @@ -63,10 +68,9 @@ class LoggingStats { base::TimeTicks start_time_[kNumOfLoggingEvents]; // Keep track of event counts. int counts_[kNumOfLoggingEvents]; - base::TickClock* const clock_; // Not owned by this class. DISALLOW_COPY_AND_ASSIGN(LoggingStats); - }; +}; } // namespace cast } // namespace media diff --git a/media/cast/logging/logging_unittest.cc b/media/cast/logging/logging_unittest.cc index 5ce760e..7dd2ac7 100644 --- a/media/cast/logging/logging_unittest.cc +++ b/media/cast/logging/logging_unittest.cc @@ -9,12 +9,12 @@ #include "base/time/tick_clock.h" #include "base/time/time.h" #include "media/cast/logging/logging_impl.h" - +#include "media/cast/test/fake_task_runner.h" namespace media { namespace cast { - // Insert frame duration- one second. +// Insert frame duration- one second. const int64 kIntervalTime1S = 1; // Test frame rate goal - 30fps. const int kFrameIntervalMs = 33; @@ -23,16 +23,21 @@ static const int64 kStartMillisecond = GG_INT64_C(12345678900000); class TestLogging : public ::testing::Test { protected: - TestLogging() + TestLogging() { // Enable logging, disable tracing and uma. - : logging_(&testing_clock_, true, false, false) { + config_.enable_data_collection = true; + testing_clock_.Advance( base::TimeDelta::FromMilliseconds(kStartMillisecond)); + task_runner_ = new test::FakeTaskRunner(&testing_clock_); + logging_.reset(new LoggingImpl(task_runner_, config_)); } virtual ~TestLogging() {} - LoggingImpl logging_; + CastLoggingConfig config_; + scoped_refptr task_runner_; + scoped_ptr logging_; base::SimpleTestTickClock testing_clock_; }; @@ -42,19 +47,21 @@ TEST_F(TestLogging, BasicFrameLogging) { uint32 rtp_timestamp = 0; uint32 frame_id = 0; do { - logging_.InsertFrameEvent(kAudioFrameCaptured, rtp_timestamp, frame_id); + logging_->InsertFrameEvent(testing_clock_.NowTicks(), + kAudioFrameCaptured, rtp_timestamp, frame_id); testing_clock_.Advance( - base::TimeDelta::FromMilliseconds(kFrameIntervalMs)); + 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(); + 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. - const FrameStatsMap* frame_stats = logging_.GetFrameStatsData(); + const FrameStatsMap* frame_stats = + logging_->GetFrameStatsData(testing_clock_.NowTicks()); // Size of stats equals the number of events. EXPECT_EQ(1u, frame_stats->size()); FrameStatsMap::const_iterator it = frame_stats->find(kAudioFrameCaptured); @@ -77,20 +84,21 @@ TEST_F(TestLogging, FrameLoggingWithSize) { do { int size = kBaseFrameSizeBytes + base::RandInt(-kRandomSizeInterval, kRandomSizeInterval); - logging_.InsertFrameEventWithSize( + logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(), kAudioFrameCaptured, rtp_timestamp, frame_id, size); testing_clock_.Advance( - base::TimeDelta::FromMilliseconds(kFrameIntervalMs)); + 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(); + 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. - const FrameStatsMap* frame_stats = logging_.GetFrameStatsData(); + const FrameStatsMap* frame_stats = + logging_->GetFrameStatsData(testing_clock_.NowTicks()); // Size of stats equals the number of events. EXPECT_EQ(1u, frame_stats->size()); FrameStatsMap::const_iterator it = frame_stats->find(kAudioFrameCaptured); @@ -114,21 +122,22 @@ TEST_F(TestLogging, FrameLoggingWithDelay) { do { int delay = kPlayoutDelayMs + base::RandInt(-kRandomSizeInterval, kRandomSizeInterval); - logging_.InsertFrameEventWithDelay( + logging_->InsertFrameEventWithDelay(testing_clock_.NowTicks(), kAudioFrameCaptured, rtp_timestamp, frame_id, base::TimeDelta::FromMilliseconds(delay)); testing_clock_.Advance( - base::TimeDelta::FromMilliseconds(kFrameIntervalMs)); + 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(); + 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. - const FrameStatsMap* frame_stats = logging_.GetFrameStatsData(); + const FrameStatsMap* frame_stats = + logging_->GetFrameStatsData(testing_clock_.NowTicks()); // Size of stats equals the number of events. EXPECT_EQ(1u, frame_stats->size()); FrameStatsMap::const_iterator it = frame_stats->find(kAudioFrameCaptured); @@ -147,14 +156,16 @@ TEST_F(TestLogging, MultipleEventFrameLogging) { uint32 rtp_timestamp = 0; uint32 frame_id = 0; do { - logging_.InsertFrameEvent(kAudioFrameCaptured, rtp_timestamp, frame_id); + logging_->InsertFrameEvent(testing_clock_.NowTicks(), kAudioFrameCaptured, + rtp_timestamp, frame_id); if (frame_id % 2) { - logging_.InsertFrameEventWithSize( + logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(), kAudioFrameEncoded, rtp_timestamp, frame_id, 1500); } else if (frame_id % 3) { - logging_.InsertFrameEvent(kVideoFrameDecoded, rtp_timestamp, frame_id); + logging_->InsertFrameEvent(testing_clock_.NowTicks(), kVideoFrameDecoded, + rtp_timestamp, frame_id); } else { - logging_.InsertFrameEventWithDelay( + logging_->InsertFrameEventWithDelay(testing_clock_.NowTicks(), kVideoRenderDelay, rtp_timestamp, frame_id, base::TimeDelta::FromMilliseconds(20)); } @@ -165,7 +176,7 @@ TEST_F(TestLogging, MultipleEventFrameLogging) { time_interval = testing_clock_.NowTicks() - start_time; } while (time_interval.InSeconds() < kIntervalTime1S); // Get logging data. - FrameRawMap frame_map = logging_.GetFrameRawData(); + 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. @@ -182,21 +193,22 @@ TEST_F(TestLogging, PacketLogging) { do { for (int i = 0; i < kNumPacketsPerFrame; ++i) { int size = kBaseSize + base::RandInt(-kSizeInterval, kSizeInterval); - logging_.InsertPacketEvent(kPacketSentToPacer, rtp_timestamp, frame_id, - i, kNumPacketsPerFrame, size); + logging_->InsertPacketEvent(testing_clock_.NowTicks(), kPacketSentToPacer, + rtp_timestamp, frame_id, i, kNumPacketsPerFrame, size); } testing_clock_.Advance( - base::TimeDelta::FromMilliseconds(kFrameIntervalMs)); + 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(); + 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. - const PacketStatsMap* stats_map = logging_.GetPacketStatsData(); + const PacketStatsMap* stats_map = + logging_->GetPacketStatsData(testing_clock_.NowTicks()); // Size of stats equals the number of events. EXPECT_EQ(1u, stats_map->size()); PacketStatsMap::const_iterator it = stats_map->find(kPacketSentToPacer); @@ -208,39 +220,40 @@ TEST_F(TestLogging, PacketLogging) { TEST_F(TestLogging, GenericLogging) { // Insert multiple generic types. - const int kNumRuns = 1000; + const size_t kNumRuns = 1000; const int kBaseValue = 20; - for (int i = 0; i < kNumRuns; ++i) { + for (size_t i = 0; i < kNumRuns; ++i) { int value = kBaseValue + base::RandInt(-5, 5); - logging_.InsertGenericEvent(kRtt, value); + logging_->InsertGenericEvent(testing_clock_.NowTicks(), kRttMs, value); if (i % 2) { - logging_.InsertGenericEvent(kPacketLoss, value); + logging_->InsertGenericEvent(testing_clock_.NowTicks(), kPacketLoss, + value); } if (!(i % 4)) { - logging_.InsertGenericEvent(kJitter, value); + logging_->InsertGenericEvent(testing_clock_.NowTicks(), kJitterMs, value); } } - GenericRawMap raw_map = logging_.GetGenericRawData(); - const GenericStatsMap* stats_map = logging_.GetGenericStatsData(); + GenericRawMap raw_map = logging_->GetGenericRawData(); + const 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(kRtt); + 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(kJitter); + 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 event. - GenericStatsMap::const_iterator sit = stats_map->find(kRtt); + GenericStatsMap::const_iterator sit = stats_map->find(kRttMs); EXPECT_NEAR(kBaseValue, sit->second, 2.5); sit = stats_map->find(kPacketLoss); EXPECT_NEAR(kBaseValue, sit->second, 2.5); - sit = stats_map->find(kJitter); + sit = stats_map->find(kJitterMs); EXPECT_NEAR(kBaseValue, sit->second, 2.5); } diff --git a/media/cast/net/pacing/paced_sender.cc b/media/cast/net/pacing/paced_sender.cc index 8a07380..6e93e83 100644 --- a/media/cast/net/pacing/paced_sender.cc +++ b/media/cast/net/pacing/paced_sender.cc @@ -29,14 +29,16 @@ PacedSender::~PacedSender() {} bool PacedSender::SendPackets(const PacketList& packets) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); - cast_environment_->Logging()->InsertPacketListEvent(kPacketSentToPacer, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertPacketListEvent(now, kPacketSentToPacer, packets); return SendPacketsToTransport(packets, &packet_list_); } bool PacedSender::ResendPackets(const PacketList& packets) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); - cast_environment_->Logging()->InsertPacketListEvent(kPacketRetransmited, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertPacketListEvent(now, kPacketRetransmited, packets); return SendPacketsToTransport(packets, &resend_packet_list_); } @@ -68,7 +70,8 @@ bool PacedSender::SendPacketsToTransport(const PacketList& packets, packets_sent_in_burst_ += packets_to_send.size(); if (packets_to_send.empty()) return true; - cast_environment_->Logging()->InsertPacketListEvent(kPacketSentToNetwork, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertPacketListEvent(now, kPacketSentToNetwork, packets); return transport_->SendPackets(packets_to_send); } diff --git a/media/cast/rtcp/rtcp.cc b/media/cast/rtcp/rtcp.cc index 4ea4bc9..3e9cdcc 100644 --- a/media/cast/rtcp/rtcp.cc +++ b/media/cast/rtcp/rtcp.cc @@ -96,24 +96,24 @@ class LocalRtcpReceiverFeedback : public RtcpReceiverFeedback { RtcpReceiverEventLogMessages::const_iterator event_it = it->event_log_messages_.begin(); for (; event_it != it->event_log_messages_.end(); ++event_it) { - // TODO(pwestin): we need to send in the event_it->event_timestamp to - // the log system too. switch (event_it->type) { case kPacketReceived: - cast_environment_->Logging()->InsertPacketEvent(kPacketReceived, - rtp_timestamp, kFrameIdUnknown, event_it->packet_id, 0, 0); + cast_environment_->Logging()->InsertPacketEvent( + event_it->event_timestamp, kPacketReceived, rtp_timestamp, + kFrameIdUnknown, event_it->packet_id, 0, 0); break; case kAckSent: case kAudioFrameDecoded: case kVideoFrameDecoded: - cast_environment_->Logging()->InsertFrameEvent(event_it->type, - rtp_timestamp, kFrameIdUnknown); + cast_environment_->Logging()->InsertFrameEvent( + event_it->event_timestamp, event_it->type, rtp_timestamp, + kFrameIdUnknown); break; case kAudioPlayoutDelay: case kVideoRenderDelay: cast_environment_->Logging()->InsertFrameEventWithDelay( - 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: " @@ -156,8 +156,11 @@ class LocalRtcpReceiverFeedback : public RtcpReceiverFeedback { } // TODO(pwestin): how do we handle the truncated rtp_timestamp? // Add received log messages into our log system. - cast_environment_->Logging()->InsertFrameEvent(log_event, rtp_timestamp, - kFrameIdUnknown); + // TODO(pwestin): how do we handle the time? we don't care about it but + // we need to send in one. + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertFrameEvent(now, log_event, + rtp_timestamp, kFrameIdUnknown); } } @@ -252,7 +255,7 @@ void Rtcp::SendRtcpFromRtpReceiver(const RtcpCastMessage* cast_message, if (cast_message) { packet_type_flags |= RtcpSender::kRtcpCast; - cast_environment_->Logging()->InsertGenericEvent(kAckSent, + cast_environment_->Logging()->InsertGenericEvent(now, kAckSent, cast_message->ack_frame_id_); } if (receiver_log) { @@ -269,9 +272,9 @@ 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, + cast_environment_->Logging()->InsertGenericEvent(now, kJitterMs, report_block.jitter); - cast_environment_->Logging()->InsertGenericEvent(kPacketLoss, + cast_environment_->Logging()->InsertGenericEvent(now, kPacketLoss, report_block.fraction_lost); } @@ -461,7 +464,9 @@ bool Rtcp::Rtt(base::TimeDelta* rtt, DCHECK(max_rtt) << "Invalid argument"; if (number_of_rtt_in_avg_ == 0) return false; - cast_environment_->Logging()->InsertGenericEvent(kRttMs, + + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertGenericEvent(now, kRttMs, rtt->InMilliseconds()); *rtt = rtt_; diff --git a/media/cast/rtcp/rtcp_receiver.cc b/media/cast/rtcp/rtcp_receiver.cc index 152ebc0..eaafefd 100644 --- a/media/cast/rtcp/rtcp_receiver.cc +++ b/media/cast/rtcp/rtcp_receiver.cc @@ -212,9 +212,10 @@ void RtcpReceiver::HandleReportBlock(const RtcpField* rtcp_field, return; } VLOG(1) << "Cast RTCP received RB from SSRC " << remote_ssrc; - cast_environment_->Logging()->InsertGenericEvent(kPacketLoss, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertGenericEvent(now, kPacketLoss, rb.fraction_lost); - cast_environment_->Logging()->InsertGenericEvent(kJitterMs, + cast_environment_->Logging()->InsertGenericEvent(now, kJitterMs, rb.jitter); RtcpReportBlock report_block; diff --git a/media/cast/rtcp/rtcp_sender.cc b/media/cast/rtcp/rtcp_sender.cc index b5cf4ce..dcc69f5 100644 --- a/media/cast/rtcp/rtcp_sender.cc +++ b/media/cast/rtcp/rtcp_sender.cc @@ -458,7 +458,8 @@ void RtcpSender::BuildRemb(const RtcpRembMessage* remb, for (; it != remb->remb_ssrcs.end(); ++it) { big_endian_writer.WriteU32(*it); } - cast_environment_->Logging()->InsertGenericEvent(kRembBitrate, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertGenericEvent(now, kRembBitrate, remb->remb_bitrate); } diff --git a/media/cast/video_receiver/video_receiver.cc b/media/cast/video_receiver/video_receiver.cc index 98bed1f..c735103 100644 --- a/media/cast/video_receiver/video_receiver.cc +++ b/media/cast/video_receiver/video_receiver.cc @@ -250,8 +250,9 @@ bool VideoReceiver::PullEncodedVideoFrame(uint32 rtp_timestamp, *render_time = GetRenderTime(now, rtp_timestamp); // TODO(mikhal): Store actual render time and not diff. - cast_environment_->Logging()->InsertFrameEventWithDelay(kVideoRenderDelay, - rtp_timestamp, (*encoded_frame)->frame_id, now - *render_time); + cast_environment_->Logging()->InsertFrameEventWithDelay(now, + kVideoRenderDelay, rtp_timestamp, (*encoded_frame)->frame_id, + now - *render_time); // Minimum time before a frame is due to be rendered before we pull it for // decode. @@ -394,7 +395,7 @@ void VideoReceiver::IncomingParsedRtpPacket(const uint8* payload_data, time_incoming_packet_updated_ = true; } - cast_environment_->Logging()->InsertPacketEvent(kPacketReceived, + cast_environment_->Logging()->InsertPacketEvent(now, kPacketReceived, rtp_header.webrtc.header.timestamp, rtp_header.frame_id, rtp_header.packet_id, rtp_header.max_packet_id, payload_size); diff --git a/media/cast/video_sender/video_encoder.cc b/media/cast/video_sender/video_encoder.cc index faa78d3..eb0cf49 100644 --- a/media/cast/video_sender/video_encoder.cc +++ b/media/cast/video_sender/video_encoder.cc @@ -15,7 +15,8 @@ namespace cast { void LogFrameEncodedEvent(CastEnvironment* const cast_environment, const base::TimeTicks& capture_time) { - cast_environment->Logging()->InsertFrameEvent(kVideoFrameEncoded, + base::TimeTicks now = cast_environment->Clock()->NowTicks(); + cast_environment->Logging()->InsertFrameEvent(now, kVideoFrameEncoded, GetVideoRtpTimestamp(capture_time), kFrameIdUnknown); } @@ -52,7 +53,8 @@ bool VideoEncoder::EncodeVideoFrame( return false; } - cast_environment_->Logging()->InsertFrameEvent(kVideoFrameSentToEncoder, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertFrameEvent(now, kVideoFrameSentToEncoder, GetVideoRtpTimestamp(capture_time), kFrameIdUnknown); cast_environment_->PostTask(CastEnvironment::VIDEO_ENCODER, FROM_HERE, base::Bind(&VideoEncoder::EncodeVideoFrameEncoderThread, diff --git a/media/cast/video_sender/video_sender.cc b/media/cast/video_sender/video_sender.cc index 7391fe8..d0d7048 100644 --- a/media/cast/video_sender/video_sender.cc +++ b/media/cast/video_sender/video_sender.cc @@ -132,7 +132,9 @@ void VideoSender::InsertRawVideoFrame( const base::TimeTicks& capture_time) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); DCHECK(video_encoder_.get()) << "Invalid state"; - cast_environment_->Logging()->InsertFrameEvent(kVideoFrameReceived, + + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertFrameEvent(now, kVideoFrameReceived, GetVideoRtpTimestamp(capture_time), kFrameIdUnknown); if (!video_encoder_->EncodeVideoFrame(video_frame, capture_time, @@ -356,9 +358,10 @@ void VideoSender::OnReceivedCastFeedback(const RtcpCastMessage& cast_feedback) { base::TimeDelta avg_rtt; base::TimeDelta min_rtt; base::TimeDelta max_rtt; + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); if (rtcp_->Rtt(&rtt, &avg_rtt, &min_rtt, &max_rtt)) { - cast_environment_->Logging()->InsertGenericEvent(kRttMs, + cast_environment_->Logging()->InsertGenericEvent(now, kRttMs, rtt.InMilliseconds()); // Don't use a RTT lower than our average. rtt = std::max(rtt, avg_rtt); @@ -400,7 +403,7 @@ void VideoSender::OnReceivedCastFeedback(const RtcpCastMessage& cast_feedback) { } } else { rtp_sender_->ResendPackets(cast_feedback.missing_frames_and_packets_); - last_send_time_ = cast_environment_->Clock()->NowTicks(); + last_send_time_ = now; uint32 new_bitrate = 0; if (congestion_control_.OnNack(rtt, &new_bitrate)) { @@ -413,7 +416,8 @@ void VideoSender::OnReceivedCastFeedback(const RtcpCastMessage& cast_feedback) { void VideoSender::ReceivedAck(uint32 acked_frame_id) { DCHECK(cast_environment_->CurrentlyOn(CastEnvironment::MAIN)); last_acked_frame_id_ = static_cast(acked_frame_id); - cast_environment_->Logging()->InsertGenericEvent(kAckReceived, + base::TimeTicks now = cast_environment_->Clock()->NowTicks(); + cast_environment_->Logging()->InsertGenericEvent(now, kAckReceived, acked_frame_id); VLOG(1) << "ReceivedAck:" << static_cast(acked_frame_id); last_acked_frame_id_ = acked_frame_id; -- cgit v1.1