diff --git a/BUILD.gn b/BUILD.gn index 4558737a0a..6a3042678a 100644 --- a/BUILD.gn +++ b/BUILD.gn @@ -321,6 +321,10 @@ config("common_config") { defines += [ "WEBRTC_ABSL_MUTEX" ] } + if (rtc_enable_libevent) { + defines += [ "WEBRTC_ENABLE_LIBEVENT" ] + } + if (rtc_disable_logging) { defines += [ "RTC_DISABLE_LOGGING" ] } diff --git a/video/BUILD.gn b/video/BUILD.gn index 0349f2d830..d696445db2 100644 --- a/video/BUILD.gn +++ b/video/BUILD.gn @@ -236,6 +236,7 @@ rtc_library("frame_cadence_adapter") { "../api/units:timestamp", "../api/video:video_frame", "../rtc_base:checks", + "../rtc_base:event_tracer", "../rtc_base:logging", "../rtc_base:macromagic", "../rtc_base:race_checker", diff --git a/video/frame_cadence_adapter.cc b/video/frame_cadence_adapter.cc index 250a82b544..a8d581b568 100644 --- a/video/frame_cadence_adapter.cc +++ b/video/frame_cadence_adapter.cc @@ -34,6 +34,7 @@ #include "rtc_base/task_utils/repeating_task.h" #include "rtc_base/thread_annotations.h" #include "rtc_base/time_utils.h" +#include "rtc_base/trace_event.h" #include "system_wrappers/include/clock.h" #include "system_wrappers/include/metrics.h" #include "system_wrappers/include/ntp_time.h" @@ -325,8 +326,9 @@ void ZeroHertzAdapterMode::UpdateLayerQualityConvergence( size_t spatial_index, bool quality_converged) { RTC_DCHECK_RUN_ON(&sequence_checker_); - RTC_LOG(LS_INFO) << __func__ << " this " << this << " layer " << spatial_index - << " quality has converged: " << quality_converged; + TRACE_EVENT_INSTANT2(TRACE_DISABLED_BY_DEFAULT("webrtc"), __func__, + "spatial_index", spatial_index, "converged", + quality_converged); if (spatial_index >= layer_trackers_.size()) return; if (layer_trackers_[spatial_index].quality_converged.has_value()) @@ -336,6 +338,8 @@ void ZeroHertzAdapterMode::UpdateLayerQualityConvergence( void ZeroHertzAdapterMode::UpdateLayerStatus(size_t spatial_index, bool enabled) { RTC_DCHECK_RUN_ON(&sequence_checker_); + TRACE_EVENT_INSTANT2(TRACE_DISABLED_BY_DEFAULT("webrtc"), __func__, + "spatial_index", spatial_index, "enabled", enabled); if (spatial_index >= layer_trackers_.size()) return; if (enabled) { @@ -346,21 +350,13 @@ void ZeroHertzAdapterMode::UpdateLayerStatus(size_t spatial_index, } else { layer_trackers_[spatial_index].quality_converged = absl::nullopt; } - RTC_LOG(LS_INFO) - << __func__ << " this " << this << " layer " << spatial_index - << (enabled - ? (layer_trackers_[spatial_index].quality_converged.has_value() - ? " enabled." - : " enabled and it's assumed quality has not converged.") - : " disabled."); } void ZeroHertzAdapterMode::OnFrame(Timestamp post_time, int frames_scheduled_for_processing, const VideoFrame& frame) { RTC_DCHECK_RUN_ON(&sequence_checker_); - RTC_DLOG(LS_VERBOSE) << "ZeroHertzAdapterMode::" << __func__ << " this " - << this; + TRACE_EVENT0("webrtc", "ZeroHertzAdapterMode::OnFrame"); refresh_frame_requester_.Stop(); // Assume all enabled layers are unconverged after frame entry. @@ -390,7 +386,7 @@ void ZeroHertzAdapterMode::OnFrame(Timestamp post_time, void ZeroHertzAdapterMode::OnDiscardedFrame() { RTC_DCHECK_RUN_ON(&sequence_checker_); - RTC_DLOG(LS_VERBOSE) << "ZeroHertzAdapterMode::" << __func__; + TRACE_EVENT0("webrtc", __func__); // Under zero hertz source delivery, a discarded frame ending a sequence of // frames which happened to contain important information can be seen as a @@ -406,7 +402,7 @@ absl::optional ZeroHertzAdapterMode::GetInputFrameRateFps() { void ZeroHertzAdapterMode::ProcessKeyFrameRequest() { RTC_DCHECK_RUN_ON(&sequence_checker_); - + TRACE_EVENT_INSTANT0("webrtc", __func__); // If we're new and don't have a frame, there's no need to request refresh // frames as this was being triggered for us when zero-hz mode was set up. // @@ -471,27 +467,27 @@ void ZeroHertzAdapterMode::ResetQualityConvergenceInfo() { void ZeroHertzAdapterMode::ProcessOnDelayedCadence() { RTC_DCHECK_RUN_ON(&sequence_checker_); RTC_DCHECK(!queued_frames_.empty()); - RTC_DLOG(LS_VERBOSE) << __func__ << " this " << this; + TRACE_EVENT0("webrtc", __func__); - SendFrameNow(queued_frames_.front()); + // Avoid sending the front frame for encoding (which could take a long time) + // until we schedule a repeate. + VideoFrame front_frame = queued_frames_.front(); // If there were two or more frames stored, we do not have to schedule repeats // of the front frame. if (queued_frames_.size() > 1) { queued_frames_.pop_front(); - return; + } else { + // There's only one frame to send. Schedule a repeat sequence, which is + // cancelled by `current_frame_id_` getting incremented should new frames + // arrive. + ScheduleRepeat(current_frame_id_, HasQualityConverged()); } - - // There's only one frame to send. Schedule a repeat sequence, which is - // cancelled by `current_frame_id_` getting incremented should new frames - // arrive. - ScheduleRepeat(current_frame_id_, HasQualityConverged()); + SendFrameNow(front_frame); } void ZeroHertzAdapterMode::ScheduleRepeat(int frame_id, bool idle_repeat) { RTC_DCHECK_RUN_ON(&sequence_checker_); - RTC_DLOG(LS_VERBOSE) << __func__ << " this " << this << " frame_id " - << frame_id; Timestamp now = clock_->CurrentTime(); if (!scheduled_repeat_.has_value()) { scheduled_repeat_.emplace(now, queued_frames_.front().timestamp_us(), @@ -512,8 +508,7 @@ void ZeroHertzAdapterMode::ScheduleRepeat(int frame_id, bool idle_repeat) { void ZeroHertzAdapterMode::ProcessRepeatedFrameOnDelayedCadence(int frame_id) { RTC_DCHECK_RUN_ON(&sequence_checker_); - RTC_DLOG(LS_VERBOSE) << __func__ << " this " << this << " frame_id " - << frame_id; + TRACE_EVENT0("webrtc", __func__); RTC_DCHECK(!queued_frames_.empty()); // Cancel this invocation if new frames turned up. @@ -542,18 +537,15 @@ void ZeroHertzAdapterMode::ProcessRepeatedFrameOnDelayedCadence(int frame_id) { frame.set_ntp_time_ms(scheduled_repeat_->origin_ntp_time_ms + total_delay.ms()); } - SendFrameNow(frame); - // Schedule another repeat. + // Schedule another repeat before sending the frame off which could take time. ScheduleRepeat(frame_id, HasQualityConverged()); + SendFrameNow(frame); } void ZeroHertzAdapterMode::SendFrameNow(const VideoFrame& frame) const { RTC_DCHECK_RUN_ON(&sequence_checker_); - RTC_DLOG(LS_VERBOSE) << __func__ << " this " << this << " timestamp " - << frame.timestamp() << " timestamp_us " - << frame.timestamp_us() << " ntp_time_ms " - << frame.ntp_time_ms(); + TRACE_EVENT0("webrtc", __func__); // TODO(crbug.com/1255737): figure out if frames_scheduled_for_processing // makes sense to compute in this implementation. callback_->OnFrame(/*post_time=*/clock_->CurrentTime(), @@ -569,7 +561,6 @@ TimeDelta ZeroHertzAdapterMode::RepeatDuration(bool idle_repeat) const { void ZeroHertzAdapterMode::MaybeStartRefreshFrameRequester() { RTC_DCHECK_RUN_ON(&sequence_checker_); - RTC_DLOG(LS_VERBOSE) << __func__; if (!refresh_frame_requester_.Running()) { refresh_frame_requester_ = RepeatingTaskHandle::DelayedStart( queue_, @@ -650,8 +641,7 @@ void FrameCadenceAdapterImpl::OnFrame(const VideoFrame& frame) { // This method is called on the network thread under Chromium, or other // various contexts in test. RTC_DCHECK_RUNS_SERIALIZED(&incoming_frame_race_checker_); - RTC_DLOG(LS_VERBOSE) << "FrameCadenceAdapterImpl::" << __func__ << " this " - << this; + TRACE_EVENT0("webrtc", "FrameCadenceAdapterImpl::OnFrame"); // Local time in webrtc time base. Timestamp post_time = clock_->CurrentTime(); diff --git a/video/frame_cadence_adapter_unittest.cc b/video/frame_cadence_adapter_unittest.cc index b826672a2c..1fd2091c34 100644 --- a/video/frame_cadence_adapter_unittest.cc +++ b/video/frame_cadence_adapter_unittest.cc @@ -22,6 +22,7 @@ #include "api/video/nv12_buffer.h" #include "api/video/video_frame.h" #include "rtc_base/event.h" +#include "rtc_base/logging.h" #include "rtc_base/rate_statistics.h" #include "rtc_base/time_utils.h" #include "system_wrappers/include/metrics.h" @@ -869,5 +870,69 @@ TEST(FrameCadenceAdapterRealTimeTest, TimestampsDoNotDrift) { finalized.Wait(rtc::Event::kForever); } +// TODO(bugs.webrtc.org/15462) Disable ScheduledRepeatAllowsForSlowEncode for +// TaskQueueLibevent. +#if defined(WEBRTC_ENABLE_LIBEVENT) +#define MAYBE_ScheduledRepeatAllowsForSlowEncode \ + DISABLED_ScheduledRepeatAllowsForSlowEncode +#else +#define MAYBE_ScheduledRepeatAllowsForSlowEncode \ + ScheduledRepeatAllowsForSlowEncode +#endif + +TEST(FrameCadenceAdapterRealTimeTest, + MAYBE_ScheduledRepeatAllowsForSlowEncode) { + // This regression test must be performed in realtime because of limitations + // in GlobalSimulatedTimeController. + // + // We sleep for a long while (but less than max fps) in the first repeated + // OnFrame (frame 2). This should not lead to a belated second repeated + // OnFrame (frame 3). + auto factory = CreateDefaultTaskQueueFactory(); + auto queue = + factory->CreateTaskQueue("test", TaskQueueFactory::Priority::NORMAL); + ZeroHertzFieldTrialEnabler enabler; + MockCallback callback; + Clock* clock = Clock::GetRealTimeClock(); + std::unique_ptr adapter; + int frame_counter = 0; + rtc::Event event; + absl::optional start_time; + queue->PostTask([&] { + adapter = CreateAdapter(enabler, clock); + adapter->Initialize(&callback); + adapter->SetZeroHertzModeEnabled( + FrameCadenceAdapterInterface::ZeroHertzModeParams{}); + adapter->OnConstraintsChanged(VideoTrackSourceConstraints{0, 2}); + auto frame = CreateFrame(); + constexpr int kSleepMs = 400; + constexpr TimeDelta kAllowedBelate = TimeDelta::Millis(150); + EXPECT_CALL(callback, OnFrame) + .WillRepeatedly(InvokeWithoutArgs([&, kAllowedBelate] { + ++frame_counter; + // Avoid the first OnFrame and sleep on the second. + if (frame_counter == 2) { + start_time = clock->CurrentTime(); + SleepMs(kSleepMs); + } else if (frame_counter == 3) { + TimeDelta diff = + clock->CurrentTime() - (*start_time + TimeDelta::Millis(500)); + RTC_LOG(LS_ERROR) + << "Difference in when frame should vs is appearing: " << diff; + EXPECT_LT(diff, kAllowedBelate); + event.Set(); + } + })); + adapter->OnFrame(frame); + }); + event.Wait(rtc::Event::kForever); + rtc::Event finalized; + queue->PostTask([&] { + adapter = nullptr; + finalized.Set(); + }); + finalized.Wait(rtc::Event::kForever); +} + } // namespace } // namespace webrtc