Bug 49009 – Lots of time spent in MediaPlayerPrivate::currentTime() when playing multiple videos.

• Status: RESOLVED
• Resolution: FIXED
• Component: Media

[Eric Carlson]

Created attachment 72961 [details]
Test case

When the attached test case is loaded and the CPU is sampled, we see that a lot of time is being spent in MediaPlayerPrivate::currentTime(). The following three second sample is of Safari 5 on 10.6.4:

858 SafariMain
 858 NSApplicationMain
  858 -[NSApplication run]
   858 -[BrowserApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
    858 -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
     858 _DPSNextEvent
      858 BlockUntilNextEventMatchingListInMode
       858 ReceiveNextEventCommon
        858 RunCurrentEventLoopInMode
         858 CFRunLoopRunSpecific
          858 __CFRunLoopRun
           650 WebCore::timerFired(__CFRunLoopTimer*, void*)
            607 WebCore::ThreadTimers::sharedTimerFiredInternal()
             421 WebCore::HTMLMediaElement::scheduleTimeupdateEvent(bool)
              421 WebCore::MediaPlayerPrivate::currentTime() const
               421 -[QTMovie currentTime]

[Eric Carlson]

Created attachment 72977 [details]
Proposed patch

Changes for HTMLMediaElement and OS X media engine. I will file bugs for the other media engines.

[Eric Carlson]

(In reply to comment #1)
> Created an attachment (id=72977) [details]
> Proposed patch
> 
> Changes for HTMLMediaElement and OS X media engine. I will file bugs for the other media engines.

With these changes, a three second sample of Safari with TOT WebKit show either one or no calls to MediaPlayerPrivate::currentTime because it is only called once every five seconds.

[Antti Koivisto]

Comment on attachment 72977 [details]
Proposed patch

View in context: https://bugs.webkit.org/attachment.cgi?id=72977&action=review

> WebCore/html/HTMLMediaElement.cpp:108
> +#ifndef LOG_CACHED_TIME_WARNINGS
> +// Default to not logging warnings about excessive drift in the cached media time because it adds a
> +// fair amount of overhead and logging.
> +#define LOG_CACHED_TIME_WARNINGS 0
> +#endif

Do you think this logging will be actually useful in the future? Code that is not enabled by default tends to stop compiling eventually...

> WebCore/html/HTMLMediaElement.cpp:144
> +    , m_cachedTime(-1)

You could have a constant for the invalid cached time. Testing for cache validity might read better then.

> WebCore/html/HTMLMediaElement.cpp:146
> +    , m_minimumWallClockTimeToCacheMovieTime(0)

"Movie" here is a QT term. I think the generic WebKit code has tried to avoid it.

This comment applies to a bunch of other names in this patch too.

> WebCore/html/HTMLMediaElement.cpp:1219
> +void HTMLMediaElement::refreshCachedTime()
> +{
> +    LOG(Media, "HTMLMediaElement::refreshCachedTime");
> +
> +    m_cachedTimeWallClockUpdateTime = WTF::currentTime();
> +    m_cachedTime = m_player->currentTime();
> +}

Why is refreshCachedTime() needed at all? Couldn't you just invalidate where you now do refresh and then let currentTime() refresh as needed?

> WebCore/html/HTMLMediaElement.cpp:1229
> +    // Don't try to cache movie time when playback first starts as the time reported by the engine
> +    // sometimes fluctuates for a short amount of time, so the cached time will be off if we take it
> +    // too early.
> +    static float minimumTimePlayingBeforeCacheSnapshot = 0.5;
> +

static const float

> WebCore/html/HTMLMediaElement.cpp:1235
> -float HTMLMediaElement::currentTime() const
> +float HTMLMediaElement::currentTime()

You could make the cache variables mutable and keep the const.

> WebCore/html/HTMLMediaElement.cpp:1245
> +#if !LOG_CACHED_TIME_WARNINGS
> +    static const double minCachedDeltaForWarning = 0.01;
> +#endif
> +
>      if (!m_player)
>          return 0;
> -    if (m_seeking)
> +
> +    if (m_seeking) {
> +        LOG(Media, "HTMLMediaElement::currentTime - seeking, returning %f", m_lastSeekTime);

Could this too generate tons of logging? Should this be behind #if too?

> WebCore/html/HTMLMediaElement.cpp:1363
> -bool HTMLMediaElement::ended() const
> +bool HTMLMediaElement::ended()

You could make the cache variables mutable and keep the const.

> WebCore/html/HTMLMediaElement.cpp:1644
> -bool HTMLMediaElement::canPlay() const
> +bool HTMLMediaElement::canPlay()

You could make the cache variables mutable and keep the const.

> WebCore/html/HTMLMediaElement.h:360
> +    float m_cachedTime;
> +    double m_cachedTimeWallClockUpdateTime;
> +    double m_minimumWallClockTimeToCacheMovieTime;

I think you should make the cache fields mutable and keep the const in currentTime(), ended() etc.

> WebCore/platform/graphics/mac/MediaPlayerPrivateQTKit.h:178
> +    virtual double maximumDurationToCacheMovieTime() const { return 5; }

Isn't 5 seconds pretty aggressive? Would a smaller value increase the cpu usage substantially?

[Eric Carlson]

(In reply to comment #3)
> (From update of attachment 72977 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=72977&action=review
> 
> > WebCore/html/HTMLMediaElement.cpp:108
> > +#ifndef LOG_CACHED_TIME_WARNINGS
> > +// Default to not logging warnings about excessive drift in the cached media time because it adds a
> > +// fair amount of overhead and logging.
> > +#define LOG_CACHED_TIME_WARNINGS 0
> > +#endif
> 
> Do you think this logging will be actually useful in the future? Code that is not enabled by default tends to stop compiling eventually...
> 
Yes, it is required for the other media engines to figure out a safe maximum cache time.
 

> > WebCore/html/HTMLMediaElement.cpp:144
> > +    , m_cachedTime(-1)
> 
> You could have a constant for the invalid cached time. Testing for cache validity might read better then.
> 
OK.

> > WebCore/html/HTMLMediaElement.cpp:146
> > +    , m_minimumWallClockTimeToCacheMovieTime(0)
> 
> "Movie" here is a QT term. I think the generic WebKit code has tried to avoid it.
> 
> This comment applies to a bunch of other names in this patch too.
> 
I disagree that "movie" is QuickTime specific term, but what would you suggest instead? "video" is incorrect because not all files have video media. "media file" is incorrect because an jpeg is a media file too. "linear media file" is technically correct, but who would understand what that means?


> > WebCore/html/HTMLMediaElement.cpp:1219
> > +void HTMLMediaElement::refreshCachedTime()
> > +{
> > +    LOG(Media, "HTMLMediaElement::refreshCachedTime");
> > +
> > +    m_cachedTimeWallClockUpdateTime = WTF::currentTime();
> > +    m_cachedTime = m_player->currentTime();
> > +}
> 
> Why is refreshCachedTime() needed at all? Couldn't you just invalidate where you now do refresh and then let currentTime() refresh as needed?
> 
It is useful because invalidateCachedTime() also sets m_minimumWallClockTimeToCacheMovieTime, which prevents the cached time from being used for a half second, but there are times when we know that necessary to update the cached time but it is NOT necessary to keep it cached.

> > WebCore/html/HTMLMediaElement.cpp:1229
> > +    // Don't try to cache movie time when playback first starts as the time reported by the engine
> > +    // sometimes fluctuates for a short amount of time, so the cached time will be off if we take it
> > +    // too early.
> > +    static float minimumTimePlayingBeforeCacheSnapshot = 0.5;
> > +
> 
> static const float
> 
Oops!

> 
> > WebCore/html/HTMLMediaElement.cpp:1245
> > +#if !LOG_CACHED_TIME_WARNINGS
> > +    static const double minCachedDeltaForWarning = 0.01;
> > +#endif
> > +
> >      if (!m_player)
> >          return 0;
> > -    if (m_seeking)
> > +
> > +    if (m_seeking) {
> > +        LOG(Media, "HTMLMediaElement::currentTime - seeking, returning %f", m_lastSeekTime);
> 
> Could this too generate tons of logging? Should this be behind #if too?
> 
No, this will rarely be true.


> > WebCore/html/HTMLMediaElement.h:360
> > +    float m_cachedTime;
> > +    double m_cachedTimeWallClockUpdateTime;
> > +    double m_minimumWallClockTimeToCacheMovieTime;
> 
> I think you should make the cache fields mutable and keep the const in currentTime(), ended() etc.
> 
Great idea!

> > WebCore/platform/graphics/mac/MediaPlayerPrivateQTKit.h:178
> > +    virtual double maximumDurationToCacheMovieTime() const { return 5; }
> 
> Isn't 5 seconds pretty aggressive? Would a smaller value increase the cpu usage substantially?
>
The wall clock is a very close approximation of the media clock 5 seconds, it actually works well when set to 10 seconds but I decided that was too aggressive :-)

[Antti Koivisto]

(In reply to comment #4)
> > > WebCore/html/HTMLMediaElement.cpp:146
> > > +    , m_minimumWallClockTimeToCacheMovieTime(0)
> > 
> > "Movie" here is a QT term. I think the generic WebKit code has tried to avoid it.
> > 
> > This comment applies to a bunch of other names in this patch too.
> > 
> I disagree that "movie" is QuickTime specific term, but what would you suggest instead? "video" is incorrect because not all files have video media. "media file" is incorrect because an jpeg is a media file too. "linear media file" is technically correct, but who would understand what that means?

I have never heard the term "movie" used for audio content outside QuickTime, but maybe it is just me. As a historical note the class MediaPlayer used to be called Movie before the term was exorcised from the generic code.

In this instance, you could just drop the word Movie as it doesn't add much (the cache is called m_cachedTime not m_cachedMovieTime).

> It is useful because invalidateCachedTime() also sets m_minimumWallClockTimeToCacheMovieTime, which prevents the cached time from being used for a half second, but there are times when we know that necessary to update the cached time but it is NOT necessary to keep it cached.

Ok.  

> > Could this too generate tons of logging? Should this be behind #if too?
> > 
> No, this will rarely be true.

I suppose someone could query the current time a lot during seeking but I guess there are tons of similar cases already.

> The wall clock is a very close approximation of the media clock 5 seconds, it actually works well when set to 10 seconds but I decided that was too aggressive :-)

:) 

I was thinking that the media clock might get skewed quickly in streaming cases or something. But perhaps those just produce stalls?

[Antti Koivisto]

Comment on attachment 72977 [details]
Proposed patch

Anyway, r=me with or without changes.

[Eric Carlson]

http://trac.webkit.org/changeset/71824

[Eric Carlson]

http://trac.webkit.org/changeset/71826 required to fix Leopard build.

[WebKit Review Bot]

http://trac.webkit.org/changeset/71824 might have broken Leopard Intel Release (Tests)
The following tests are not passing:
media/video-played-collapse.html
media/video-played-ranges-1.html
media/video-played-reset.html

[Eric Carlson]

(In reply to comment #9)
> http://trac.webkit.org/changeset/71824 might have broken Leopard Intel Release (Tests)
> The following tests are not passing:
> media/video-played-collapse.html
> media/video-played-ranges-1.html
> media/video-played-reset.html

https://bugs.webkit.org/show_bug.cgi?id=49390