diff --git a/video/BUILD.gn b/video/BUILD.gn index 65f02d84e3..40faf3b785 100644 --- a/video/BUILD.gn +++ b/video/BUILD.gn @@ -342,6 +342,7 @@ rtc_library("video_receive_stream_timeout_tracker") { "../api/task_queue", "../api/units:time_delta", "../api/units:timestamp", + "../rtc_base:logging", "../rtc_base/task_utils:repeating_task", "../system_wrappers", ] diff --git a/video/frame_buffer_proxy.cc b/video/frame_buffer_proxy.cc index f69d9da124..bc78be0e28 100644 --- a/video/frame_buffer_proxy.cc +++ b/video/frame_buffer_proxy.cc @@ -186,8 +186,6 @@ class FrameBuffer3Proxy : public FrameBufferProxy { std::unique_ptr frame_decode_scheduler, const FieldTrialsView& field_trials) : field_trials_(field_trials), - max_wait_for_keyframe_(max_wait_for_keyframe), - max_wait_for_frame_(max_wait_for_frame), clock_(clock), worker_queue_(worker_queue), decode_queue_(decode_queue), @@ -393,10 +391,6 @@ class FrameBuffer3Proxy : public FrameBufferProxy { OnFrameReady(std::move(frames), render_time); } - TimeDelta MaxWait() const RTC_RUN_ON(&worker_sequence_checker_) { - return keyframe_required_ ? max_wait_for_keyframe_ : max_wait_for_frame_; - } - void UpdateDroppedFrames() RTC_RUN_ON(&worker_sequence_checker_) { const int dropped_frames = buffer_->GetTotalNumberOfDroppedFrames() - frames_dropped_before_last_new_frame_; @@ -463,11 +457,15 @@ class FrameBuffer3Proxy : public FrameBufferProxy { return; } + TimeDelta max_wait = timeout_tracker_.TimeUntilTimeout(); + // Ensures the frame is scheduled for decode before the stream times out. + // This is otherwise a race condition. + max_wait = std::max(max_wait - TimeDelta::Millis(1), TimeDelta::Zero()); absl::optional schedule; while (decodable_tu_info) { schedule = decode_timing_.OnFrameBufferUpdated( decodable_tu_info->next_rtp_timestamp, - decodable_tu_info->last_rtp_timestamp, MaxWait(), + decodable_tu_info->last_rtp_timestamp, max_wait, IsTooManyFramesQueued()); if (schedule) { // Don't schedule if already waiting for the same frame. @@ -488,8 +486,6 @@ class FrameBuffer3Proxy : public FrameBufferProxy { RTC_NO_UNIQUE_ADDRESS SequenceChecker worker_sequence_checker_; const FieldTrialsView& field_trials_; - const TimeDelta max_wait_for_keyframe_; - const TimeDelta max_wait_for_frame_; const absl::optional rtt_mult_settings_ = RttMultExperiment::GetRttMultValue(); Clock* const clock_; diff --git a/video/frame_decode_timing.cc b/video/frame_decode_timing.cc index 15fcefb357..58ecd41c9e 100644 --- a/video/frame_decode_timing.cc +++ b/video/frame_decode_timing.cc @@ -30,7 +30,7 @@ FrameDecodeTiming::OnFrameBufferUpdated(uint32_t next_temporal_unit_rtp, uint32_t last_temporal_unit_rtp, TimeDelta max_wait_for_frame, bool too_many_frames_queued) { - RTC_DCHECK_GT(max_wait_for_frame, TimeDelta::Zero()); + RTC_DCHECK_GE(max_wait_for_frame, TimeDelta::Zero()); const Timestamp now = clock_->CurrentTime(); Timestamp render_time = timing_->RenderTime(next_temporal_unit_rtp, now); TimeDelta max_wait = @@ -42,15 +42,16 @@ FrameDecodeTiming::OnFrameBufferUpdated(uint32_t next_temporal_unit_rtp, if (max_wait <= -kMaxAllowedFrameDelay && next_temporal_unit_rtp != last_temporal_unit_rtp) { RTC_DLOG(LS_VERBOSE) << "Fast-forwarded frame " << next_temporal_unit_rtp - << " render time " << render_time.ms() - << " with delay " << max_wait.ms() << "ms"; + << " render time " << render_time << " with delay " + << max_wait; return absl::nullopt; } - RTC_DLOG(LS_VERBOSE) << "Selected frame with rtp " << next_temporal_unit_rtp - << " render time " << render_time.ms() - << " with a max wait of " << max_wait.ms() << "ms"; max_wait.Clamp(TimeDelta::Zero(), max_wait_for_frame); + RTC_DLOG(LS_VERBOSE) << "Selected frame with rtp " << next_temporal_unit_rtp + << " render time " << render_time + << " with a max wait of " << max_wait_for_frame + << " clamped to " << max_wait; Timestamp latest_decode_time = now + max_wait; return FrameSchedule{.latest_decode_time = latest_decode_time, .render_time = render_time}; diff --git a/video/video_receive_stream2_unittest.cc b/video/video_receive_stream2_unittest.cc index 1846e51ea9..5b2543092f 100644 --- a/video/video_receive_stream2_unittest.cc +++ b/video/video_receive_stream2_unittest.cc @@ -1162,6 +1162,59 @@ TEST_P(VideoReceiveStream2Test, PoorConnectionWithFpsChangeDuringLostFrame) { video_receive_stream_->Stop(); } +TEST_P(VideoReceiveStream2Test, StreamShouldNotTimeoutWhileWaitingForFrame) { + // Disable smoothing since this makes it hard to test frame timing. + config_.enable_prerenderer_smoothing = false; + RecreateReceiveStream(); + + video_receive_stream_->Start(); + EXPECT_CALL(mock_transport_, SendRtcp).Times(AnyNumber()); + + video_receive_stream_->OnCompleteFrame( + test::FakeFrameBuilder() + .Id(0) + .PayloadType(99) + .Time(RtpTimestampForFrame(0)) + .ReceivedTime(ReceiveTimeForFrame(0)) + .AsLast() + .Build()); + EXPECT_THAT(fake_renderer_.WaitForFrame(k30FpsDelay, /*advance_time=*/true), + RenderedFrameWith(RtpTimestamp(RtpTimestampForFrame(0)))); + + for (int id = 1; id < 30; ++id) { + video_receive_stream_->OnCompleteFrame( + test::FakeFrameBuilder() + .Id(id) + .PayloadType(99) + .Time(RtpTimestampForFrame(id)) + .ReceivedTime(ReceiveTimeForFrame(id)) + .Refs({0}) + .AsLast() + .Build()); + EXPECT_THAT(fake_renderer_.WaitForFrame(k30FpsDelay, /*advance_time=*/true), + RenderedFrameWith(RtpTimestamp(RtpTimestampForFrame(id)))); + } + + // Simulate a pause in the stream, followed by a decodable frame that is ready + // long in the future. The stream should not timeout in this case, but rather + // decode the frame just before the timeout. + time_controller_.AdvanceTime(TimeDelta::Millis(2900)); + uint32_t late_decode_rtp = kFirstRtpTimestamp + 200 * k30FpsRtpTimestampDelta; + video_receive_stream_->OnCompleteFrame( + test::FakeFrameBuilder() + .Id(121) + .PayloadType(99) + .Time(late_decode_rtp) + .ReceivedTime(clock_->CurrentTime()) + .AsLast() + .Build()); + EXPECT_THAT(fake_renderer_.WaitForFrame(TimeDelta::Millis(100), + /*advance_time=*/true), + RenderedFrameWith(RtpTimestamp(late_decode_rtp))); + + video_receive_stream_->Stop(); +} + INSTANTIATE_TEST_SUITE_P(VideoReceiveStream2Test, VideoReceiveStream2Test, testing::Bool(), diff --git a/video/video_receive_stream_timeout_tracker.cc b/video/video_receive_stream_timeout_tracker.cc index c0c8087b24..32e8bf8dc7 100644 --- a/video/video_receive_stream_timeout_tracker.cc +++ b/video/video_receive_stream_timeout_tracker.cc @@ -10,8 +10,11 @@ #include "video/video_receive_stream_timeout_tracker.h" +#include #include +#include "rtc_base/logging.h" + namespace webrtc { VideoReceiveStreamTimeoutTracker::VideoReceiveStreamTimeoutTracker( @@ -32,6 +35,10 @@ bool VideoReceiveStreamTimeoutTracker::Running() const { return timeout_task_.Running(); } +TimeDelta VideoReceiveStreamTimeoutTracker::TimeUntilTimeout() const { + return std::max(timeout_ - clock_->CurrentTime(), TimeDelta::Zero()); +} + void VideoReceiveStreamTimeoutTracker::Start(bool waiting_for_keyframe) { RTC_DCHECK(!timeout_task_.Running()); waiting_for_keyframe_ = waiting_for_keyframe; @@ -68,6 +75,7 @@ TimeDelta VideoReceiveStreamTimeoutTracker::HandleTimeoutTask() { // `timeout_` is hit and we have timed out. Schedule the next timeout at // the timeout delay. if (now >= timeout_) { + RTC_DLOG(LS_VERBOSE) << "Stream timeout at " << now; TimeDelta timeout_delay = TimeoutForNextFrame(); timeout_ = now + timeout_delay; timeout_cb_(now - last_frame_); diff --git a/video/video_receive_stream_timeout_tracker.h b/video/video_receive_stream_timeout_tracker.h index d555ac8cd6..c5a1c73be5 100644 --- a/video/video_receive_stream_timeout_tracker.h +++ b/video/video_receive_stream_timeout_tracker.h @@ -44,6 +44,7 @@ class VideoReceiveStreamTimeoutTracker { void Stop(); void SetWaitingForKeyframe(); void OnEncodedFrameReleased(); + TimeDelta TimeUntilTimeout() const; private: TimeDelta TimeoutForNextFrame() const {