Log Message
AVSampleBufferRenderSynchronizer timeline sometimes goes backwards when playback begins https://bugs.webkit.org/show_bug.cgi?id=239471 rdar://91117803
Reviewed by Jer Noble. Source/WebCore: Test: media/media-source/media-source-current-time.html * html/HTMLMediaElement.cpp: (WebCore::HTMLMediaElement::mediaPlayerTimeChanged): Log current time and requested playback rate. (WebCore::HTMLMediaElement::setPausedInternal): Log. * platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.h: * platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.mm: (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::MediaPlayerPrivateMediaSourceAVFObjC): If time has gone backward, clamp to the most recent seek time. (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::playInternal): INFO_LOG -> ALWAYS_LOG (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::pauseInternal): Ditto. (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::currentMediaTime const): Use clampTimeToLastSeekTime. (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::clampTimeToLastSeekTime const): New, clamp time value to the most recent seek time. (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::setCurrentTimeDidChangeCallback): Use clampTimeToLastSeekTime. (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::seekWithTolerance): INFO_LOG -> ALWAYS_LOG (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::seekInternal): INFO_LOG -> ALWAYS_LOG (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::updateLastPixelBuffer): INFO_LOG -> ALWAYS_LOG (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::setHasAvailableVideoFrame): INFO_LOG -> ALWAYS_LOG (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::durationChanged): INFO_LOG -> ALWAYS_LOG Source/WebKit: * WebProcess/GPU/media/MediaPlayerPrivateRemote.cpp: (WebKit::MediaPlayerPrivateRemote::currentTimeChanged): Log when time jumps backwards. LayoutTests: * media/media-source/media-source-current-time-expected.txt: Added. * media/media-source/media-source-current-time.html: Added.
Modified Paths
- trunk/LayoutTests/ChangeLog
- trunk/Source/WebCore/ChangeLog
- trunk/Source/WebCore/html/HTMLMediaElement.cpp
- trunk/Source/WebCore/platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.h
- trunk/Source/WebCore/platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.mm
- trunk/Source/WebKit/ChangeLog
- trunk/Source/WebKit/WebProcess/GPU/media/MediaPlayerPrivateRemote.cpp
Added Paths
Diff
Modified: trunk/LayoutTests/ChangeLog (293169 => 293170)
--- trunk/LayoutTests/ChangeLog 2022-04-21 15:21:53 UTC (rev 293169)
+++ trunk/LayoutTests/ChangeLog 2022-04-21 16:21:01 UTC (rev 293170)
@@ -1,3 +1,14 @@
+2022-04-21 Eric Carlson <eric.carl...@apple.com>
+
+ AVSampleBufferRenderSynchronizer timeline sometimes goes backwards when playback begins
+ https://bugs.webkit.org/show_bug.cgi?id=239471
+ rdar://91117803
+
+ Reviewed by Jer Noble.
+
+ * media/media-source/media-source-current-time-expected.txt: Added.
+ * media/media-source/media-source-current-time.html: Added.
+
2022-04-21 Tim Nguyen <n...@apple.com>
[iOS] Rebaseline fast/attachment/attachment-disabled-rendering.html expectations
Added: trunk/LayoutTests/media/media-source/media-source-current-time-expected.txt (0 => 293170)
--- trunk/LayoutTests/media/media-source/media-source-current-time-expected.txt (rev 0)
+++ trunk/LayoutTests/media/media-source/media-source-current-time-expected.txt 2022-04-21 16:21:01 UTC (rev 293170)
@@ -0,0 +1,48 @@
+
+RUN(video.src = ""
+EVENT(sourceopen)
+RUN(sourceBuffer = source.addSourceBuffer(loader.type()))
+RUN(sourceBuffer.appendBuffer(loader.initSegment()))
+EVENT(update)
+
+Append all media segments
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(0)))
+EVENT(update)
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(1)))
+EVENT(update)
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(2)))
+EVENT(update)
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(3)))
+EVENT(update)
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(4)))
+EVENT(update)
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(5)))
+EVENT(update)
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(6)))
+EVENT(update)
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(7)))
+EVENT(update)
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(8)))
+EVENT(update)
+RUN(sourceBuffer.appendBuffer(loader.mediaSegment(9)))
+EVENT(update)
+
+Seek and play
+RUN(video.currentTime = 1.6)
+EVENT(seeked)
+EXPECTED (video.currentTime == '1.6') OK
+RUN(video.play())
+
+EVENT(timeupdate)
+EXPECTED (video.currentTime >= '1.6') OK
+EVENT(timeupdate)
+EXPECTED (video.currentTime >= '1.6') OK
+EVENT(timeupdate)
+EXPECTED (video.currentTime >= '1.6') OK
+EVENT(timeupdate)
+EXPECTED (video.currentTime >= '1.6') OK
+EVENT(timeupdate)
+EXPECTED (video.currentTime >= '1.6') OK
+
+END OF TEST
+
Added: trunk/LayoutTests/media/media-source/media-source-current-time.html (0 => 293170)
--- trunk/LayoutTests/media/media-source/media-source-current-time.html (rev 0)
+++ trunk/LayoutTests/media/media-source/media-source-current-time.html 2022-04-21 16:21:01 UTC (rev 293170)
@@ -0,0 +1,64 @@
+<!DOCTYPE html>
+<html>
+<head>
+ <title>media-source-resize</title>
+ <script src=""
+ <script src=""
+ <script>
+ var loader;
+ var source;
+ var sourceBuffer;
+
+ function loaderPromise(loader) {
+ return new Promise((resolve, reject) => {
+ loader._onload_ = resolve;
+ loader._onerror_ = reject;
+ });
+ }
+
+ window.addEventListener('load', async event => {
+ findMediaElement();
+
+ loader = new MediaSourceLoader('content/test-fragmented-manifest.json');
+ await loaderPromise(loader);
+
+ source = new MediaSource();
+ run('video.src = ""
+ await waitFor(source, 'sourceopen');
+ waitFor(video, 'error').then(failTest);
+
+ run('sourceBuffer = source.addSourceBuffer(loader.type())');
+ run('sourceBuffer.appendBuffer(loader.initSegment())');
+ await waitFor(sourceBuffer, 'update');
+
+ consoleWrite('<br>Append all media segments')
+ for (i = 0; i < loader.mediaSegmentsLength(); i++) {
+ run(`sourceBuffer.appendBuffer(loader.mediaSegment(${i}))`);
+ await waitFor(sourceBuffer, 'update');
+ }
+
+ consoleWrite('<br>Seek and play')
+ let seekTime = 1.6;
+ run(`video.currentTime = ${seekTime}`);
+ await waitFor(video, 'seeked');
+ testExpected('video.currentTime', seekTime);
+ run('video.play()');
+
+ consoleWrite('');
+ let count = 0;
+ waitForEvent('timeupdate', (evt) => {
+ testExpected('video.currentTime', seekTime, '>=');
+
+ if (++count == 5) {
+ consoleWrite('')
+ endTest();
+ }
+ });
+ });
+
+ </script>
+</head>
+<body>
+ <video controls></video>
+</body>
+</html>
\ No newline at end of file
Modified: trunk/Source/WebCore/ChangeLog (293169 => 293170)
--- trunk/Source/WebCore/ChangeLog 2022-04-21 15:21:53 UTC (rev 293169)
+++ trunk/Source/WebCore/ChangeLog 2022-04-21 16:21:01 UTC (rev 293170)
@@ -1,3 +1,35 @@
+2022-04-21 Eric Carlson <eric.carl...@apple.com>
+
+ AVSampleBufferRenderSynchronizer timeline sometimes goes backwards when playback begins
+ https://bugs.webkit.org/show_bug.cgi?id=239471
+ rdar://91117803
+
+ Reviewed by Jer Noble.
+
+ Test: media/media-source/media-source-current-time.html
+
+ * html/HTMLMediaElement.cpp:
+ (WebCore::HTMLMediaElement::mediaPlayerTimeChanged): Log current time and requested
+ playback rate.
+ (WebCore::HTMLMediaElement::setPausedInternal): Log.
+
+ * platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.h:
+ * platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.mm:
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::MediaPlayerPrivateMediaSourceAVFObjC):
+ If time has gone backward, clamp to the most recent seek time.
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::playInternal): INFO_LOG -> ALWAYS_LOG
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::pauseInternal): Ditto.
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::currentMediaTime const): Use clampTimeToLastSeekTime.
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::clampTimeToLastSeekTime const): New,
+ clamp time value to the most recent seek time.
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::setCurrentTimeDidChangeCallback):
+ Use clampTimeToLastSeekTime.
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::seekWithTolerance): INFO_LOG -> ALWAYS_LOG
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::seekInternal): INFO_LOG -> ALWAYS_LOG
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::updateLastPixelBuffer): INFO_LOG -> ALWAYS_LOG
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::setHasAvailableVideoFrame): INFO_LOG -> ALWAYS_LOG
+ (WebCore::MediaPlayerPrivateMediaSourceAVFObjC::durationChanged): INFO_LOG -> ALWAYS_LOG
+
2022-04-21 Antti Koivisto <an...@apple.com>
[LFC][Integration] Add direct style accessor to inline iterator
Modified: trunk/Source/WebCore/html/HTMLMediaElement.cpp (293169 => 293170)
--- trunk/Source/WebCore/html/HTMLMediaElement.cpp 2022-04-21 15:21:53 UTC (rev 293169)
+++ trunk/Source/WebCore/html/HTMLMediaElement.cpp 2022-04-21 16:21:01 UTC (rev 293170)
@@ -5775,9 +5775,10 @@
#endif
}
-void HTMLMediaElement::setPausedInternal(bool b)
+void HTMLMediaElement::setPausedInternal(bool paused)
{
- m_pausedInternal = b;
+ ALWAYS_LOG(LOGIDENTIFIER, paused);
+ m_pausedInternal = paused;
scheduleUpdatePlayState();
}
Modified: trunk/Source/WebCore/platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.h (293169 => 293170)
--- trunk/Source/WebCore/platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.h 2022-04-21 15:21:53 UTC (rev 293169)
+++ trunk/Source/WebCore/platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.h 2022-04-21 16:21:01 UTC (rev 293170)
@@ -282,6 +282,7 @@
void setResourceOwner(const ProcessIdentity& resourceOwner) final { m_resourceOwner = resourceOwner; }
void checkNewVideoFrameMetadata(CMTime);
+ MediaTime clampTimeToLastSeekTime(const MediaTime&) const;
friend class MediaSourcePrivateAVFObjC;
Modified: trunk/Source/WebCore/platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.mm (293169 => 293170)
--- trunk/Source/WebCore/platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.mm 2022-04-21 15:21:53 UTC (rev 293169)
+++ trunk/Source/WebCore/platform/graphics/avfoundation/objc/MediaPlayerPrivateMediaSourceAVFObjC.mm 2022-04-21 16:21:01 UTC (rev 293170)
@@ -158,7 +158,8 @@
if (!weakThis)
return;
- DEBUG_LOG(logSiteIdentifier, "synchronizer fired for ", PAL::toMediaTime(time), ", seeking = ", m_seeking, ", pending = ", !!m_pendingSeek);
+ auto clampedTime = CMTIME_IS_NUMERIC(time) ? clampTimeToLastSeekTime(PAL::toMediaTime(time)) : MediaTime::zeroTime();
+ ALWAYS_LOG(logSiteIdentifier, "synchronizer fired: time clamped = ", clampedTime, ", seeking = ", m_seeking, ", pending = ", !!m_pendingSeek);
if (m_seeking && !m_pendingSeek) {
m_seeking = false;
@@ -173,7 +174,7 @@
seekInternal();
if (m_currentTimeDidChangeCallback)
- m_currentTimeDidChangeCallback(CMTIME_IS_NUMERIC(time) ? PAL::toMediaTime(time) : MediaTime::zeroTime());
+ m_currentTimeDidChangeCallback(clampedTime);
}];
}
@@ -339,7 +340,7 @@
ALLOW_NEW_API_WITHOUT_GUARDS_BEGIN
if (hostTime && [m_synchronizer respondsToSelector:@selector(setRate:time:atHostTime:)]) {
auto cmHostTime = PAL::CMClockMakeHostTimeFromSystemUnits(hostTime->toMachAbsoluteTime());
- INFO_LOG(LOGIDENTIFIER, "setting rate to ", m_rate, " at host time ", PAL::CMTimeGetSeconds(cmHostTime));
+ ALWAYS_LOG(LOGIDENTIFIER, "setting rate to ", m_rate, " at host time ", PAL::CMTimeGetSeconds(cmHostTime));
[m_synchronizer setRate:m_rate time:PAL::kCMTimeInvalid atHostTime:cmHostTime];
} else
[m_synchronizer setRate:m_rate];
@@ -365,7 +366,7 @@
ALLOW_NEW_API_WITHOUT_GUARDS_BEGIN
if (hostTime && [m_synchronizer respondsToSelector:@selector(setRate:time:atHostTime:)]) {
auto cmHostTime = PAL::CMClockMakeHostTimeFromSystemUnits(hostTime->toMachAbsoluteTime());
- INFO_LOG(LOGIDENTIFIER, "setting rate to 0 at host time ", PAL::CMTimeGetSeconds(cmHostTime));
+ ALWAYS_LOG(LOGIDENTIFIER, "setting rate to 0 at host time ", PAL::CMTimeGetSeconds(cmHostTime));
[m_synchronizer setRate:0 time:PAL::kCMTimeInvalid atHostTime:cmHostTime];
} else
[m_synchronizer setRate:0];
@@ -439,7 +440,7 @@
MediaTime MediaPlayerPrivateMediaSourceAVFObjC::currentMediaTime() const
{
- MediaTime synchronizerTime = PAL::toMediaTime(PAL::CMTimebaseGetTime([m_synchronizer timebase]));
+ MediaTime synchronizerTime = clampTimeToLastSeekTime(PAL::toMediaTime(PAL::CMTimebaseGetTime([m_synchronizer timebase])));
if (synchronizerTime < MediaTime::zeroTime())
return MediaTime::zeroTime();
if (synchronizerTime < m_lastSeekTime)
@@ -447,6 +448,14 @@
return synchronizerTime;
}
+MediaTime MediaPlayerPrivateMediaSourceAVFObjC::clampTimeToLastSeekTime(const MediaTime& time) const
+{
+ if (m_lastSeekTime.isFinite() && time < m_lastSeekTime)
+ return m_lastSeekTime;
+
+ return time;
+}
+
bool MediaPlayerPrivateMediaSourceAVFObjC::setCurrentTimeDidChangeCallback(MediaPlayer::CurrentTimeDidChangeCallback&& callback)
{
m_currentTimeDidChangeCallback = WTFMove(callback);
@@ -453,8 +462,11 @@
if (m_currentTimeDidChangeCallback) {
m_timeChangedObserver = [m_synchronizer addPeriodicTimeObserverForInterval:PAL::CMTimeMake(1, 10) queue:dispatch_get_main_queue() usingBlock:^(CMTime time) {
- if (m_currentTimeDidChangeCallback)
- m_currentTimeDidChangeCallback(CMTIME_IS_NUMERIC(time) ? PAL::toMediaTime(time) : MediaTime::zeroTime());
+ if (!m_currentTimeDidChangeCallback)
+ return;
+
+ auto clampedTime = CMTIME_IS_NUMERIC(time) ? clampTimeToLastSeekTime(PAL::toMediaTime(time)) : MediaTime::zeroTime();
+ m_currentTimeDidChangeCallback(clampedTime);
}];
} else
@@ -491,7 +503,7 @@
void MediaPlayerPrivateMediaSourceAVFObjC::seekWithTolerance(const MediaTime& time, const MediaTime& negativeThreshold, const MediaTime& positiveThreshold)
{
- INFO_LOG(LOGIDENTIFIER, "time = ", time, ", negativeThreshold = ", negativeThreshold, ", positiveThreshold = ", positiveThreshold);
+ ALWAYS_LOG(LOGIDENTIFIER, "time = ", time, ", negativeThreshold = ", negativeThreshold, ", positiveThreshold = ", positiveThreshold);
m_seeking = true;
m_pendingSeek = makeUnique<PendingSeek>(time, negativeThreshold, positiveThreshold);
@@ -521,7 +533,7 @@
m_lastSeekTime = MediaTime::createWithDouble(m_lastSeekTime.toDouble(), MediaTime::DefaultTimeScale);
MediaTime synchronizerTime = PAL::toMediaTime(PAL::CMTimebaseGetTime([m_synchronizer timebase]));
- INFO_LOG(LOGIDENTIFIER, "seekTime = ", m_lastSeekTime, ", synchronizerTime = ", synchronizerTime);
+ ALWAYS_LOG(LOGIDENTIFIER, "seekTime = ", m_lastSeekTime, ", synchronizerTime = ", synchronizerTime);
bool doesNotRequireSeek = synchronizerTime == m_lastSeekTime;
@@ -647,7 +659,7 @@
if (m_videoOutput) {
CMTime outputTime;
if (auto pixelBuffer = adoptCF([m_videoOutput copyPixelBufferForSourceTime:PAL::toCMTime(currentMediaTime()) sourceTimeForDisplay:&outputTime])) {
- INFO_LOG(LOGIDENTIFIER, "new pixelbuffer found for time ", PAL::toMediaTime(outputTime));
+ ALWAYS_LOG(LOGIDENTIFIER, "new pixelbuffer found for time ", PAL::toMediaTime(outputTime));
m_lastPixelBuffer = WTFMove(pixelBuffer);
return true;
}
@@ -933,7 +945,7 @@
if (m_hasAvailableVideoFrame == flag)
return;
- DEBUG_LOG(LOGIDENTIFIER, flag);
+ ALWAYS_LOG(LOGIDENTIFIER, flag);
m_hasAvailableVideoFrame = flag;
updateAllRenderersHaveAvailableSamples();
@@ -961,7 +973,7 @@
auto& properties = iter->value;
if (properties.hasAudibleSample == flag)
return;
- DEBUG_LOG(LOGIDENTIFIER, flag);
+ ALWAYS_LOG(LOGIDENTIFIER, flag);
properties.hasAudibleSample = flag;
updateAllRenderersHaveAvailableSamples();
}
@@ -1018,7 +1030,7 @@
return;
MediaTime now = weakThis->currentMediaTime();
- DEBUG_LOG(logSiteIdentifier, "boundary time observer called, now = ", now);
+ ALWAYS_LOG(logSiteIdentifier, "boundary time observer called, now = ", now);
weakThis->pauseInternal();
if (now < duration) {
Modified: trunk/Source/WebKit/ChangeLog (293169 => 293170)
--- trunk/Source/WebKit/ChangeLog 2022-04-21 15:21:53 UTC (rev 293169)
+++ trunk/Source/WebKit/ChangeLog 2022-04-21 16:21:01 UTC (rev 293170)
@@ -1,3 +1,14 @@
+2022-04-21 Eric Carlson <eric.carl...@apple.com>
+
+ AVSampleBufferRenderSynchronizer timeline sometimes goes backwards when playback begins
+ https://bugs.webkit.org/show_bug.cgi?id=239471
+ rdar://91117803
+
+ Reviewed by Jer Noble.
+
+ * WebProcess/GPU/media/MediaPlayerPrivateRemote.cpp:
+ (WebKit::MediaPlayerPrivateRemote::currentTimeChanged): Log when time jumps backwards.
+
2022-04-20 Wenson Hsieh <wenson_hs...@apple.com>
Unreviewed, fix the iOS 15.4 build after r293117
Modified: trunk/Source/WebKit/WebProcess/GPU/media/MediaPlayerPrivateRemote.cpp (293169 => 293170)
--- trunk/Source/WebKit/WebProcess/GPU/media/MediaPlayerPrivateRemote.cpp 2022-04-21 15:21:53 UTC (rev 293169)
+++ trunk/Source/WebKit/WebProcess/GPU/media/MediaPlayerPrivateRemote.cpp 2022-04-21 16:21:01 UTC (rev 293170)
@@ -431,6 +431,9 @@
void MediaPlayerPrivateRemote::currentTimeChanged(const MediaTime& mediaTime, const MonotonicTime& queryTime, bool timeIsProgressing)
{
auto reverseJump = mediaTime < m_cachedMediaTime;
+ if (reverseJump)
+ ALWAYS_LOG(LOGIDENTIFIER, "time jumped backwards, was ", m_cachedMediaTime, ", is now ", mediaTime);
+
m_timeIsProgressing = timeIsProgressing;
m_cachedMediaTime = mediaTime;
m_cachedMediaTimeQueryTime = queryTime;
_______________________________________________ webkit-changes mailing list webkit-changes@lists.webkit.org https://lists.webkit.org/mailman/listinfo/webkit-changes
