1166836 - Runaway plugin-container in NS_QuickSort while playing mp4 video

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Ben Turner (not reading bugmail, use the needinfo flag!)]

On today's nightly (win 8.1 x86_64, 64-bit firefox, e10s enabled) I was trying to watch this video: http://channel9.msdn.com/Shows/Visual-Studio-Toolbox/Visual-Studio-Debugging-Tips-and-Tricks

The plugin-container process chews CPU incessantly and so all other tabs stop responding. I had to kill the process.

Stack attached.

Comment 1

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Attachment: Stack

Comment 2

[Chris Pearce [:cpearce (Not reading bugmail)]]

jya: Is this stuff you added recently? Can you take a look?

Comment 3

[Jean-Yves Avenard [:jya]]

The MediaFormatReader will ask its demuxers to recalculate their buffered ranges when NotifyDataArrived() is called.

While I can optimise the mp4_demuxer to not use quicksort (and instead use the new IntervalSet object). Can also cache the values so that if the resource media range hasn't changed it doesn't recalculate the buffered range.

But there's still the issue on why NotifyDataArrived called so often?

Comment 4

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Can you reproduce this problem?

Comment 5

[Jean-Yves Avenard [:jya]]

(In reply to Ben Turner [:bent] (use the needinfo flag!) from comment #4)
> Can you reproduce this problem?

I have a fairly high CPU usage, but nothing out of the extraordinary. It's also no more when I disable the new MediaFormatReader and go back to using MP4Reader.

You can switch back to the older MP4 reader by setting media.format-reader.mp4 to false. Does it still happen for you?

Comment 6

[Jean-Yves Avenard [:jya]]

I've done some profiling...

When playing this video, during a 1 minute playback, 55.9% (62s CPU time) was spent in GetBuffered(). The main thread alone calculating GetBuffered().
All this time is spent in mp4_demuxer::Index::ConvertByteRangesToTimeRanges.

On the MediaFormatReader::MediaTaskQueue(), the combined time spent 30.8s to process GetBuffered().

The mp4_demuxer::Index keeps an array of samples, which is sorted by decode order.
It adds interatively all those samples (one at a time) to an array, and then sort it using QuickSort to get them in presentation order.

we end up with an array that has 69344 samples. For each sample it tests if it is contained in the mdat range (half the time is spent there).
Finally, QuickSort no matter how quick it is, when having to sort this several times per second ends up being (the other half)

When using MP4Reader, there's no real improvement as far as the main thread is concerned (and this is expected as Getbuffered() is mostly done while in the main thread). There's however something to take into account, as the demuxer is shared across all threads, the main thread may be locking while the reader task queue is calculating GetBuffered(). The overall CPU time is 60.2s. So less than MediaFormatReader but the mainthread would be waiting for GetBuffered for longer.

We only need to call GetBuffered() on the reader's taskqueue when using MediaSource, so we can optimise greatly the need for the second demuxer in calculating the time ranges.

The problem reported isn't being made worse by having the MediaFormatReader being the default reader. Yes, more CPU time is spent in total, but this is more spread across threads.

Ben, could you please confirm that when setting media.format-reader.mp4 to false, you're still experiencing the problem, and let me know if it's the same, much better or worse (theory is great, but actual usage is always better)

I have some ideas on how we could optimise GetBuffered() for MP4, I will run them by Anthony.

Comment 7

[Jean-Yves Avenard [:jya]]

Interestingly, once download as completed (and as such we don't call GetBuffered() anymore), 15% of CPU time is spent in ReentrantMonitorAutoEnter::Wait. 8s worth...

worth looking into it IMHO.

Comment 8

[Jean-Yves Avenard [:jya]]

Attachment: Part1. Cache main thread buffered time range

Cache the buffered range for the main thread. It doesn't account for much savings, but the Chrome UI does call GetBuffered() from time to time which causes an unecessary recalculation.

Comment 9

[Jean-Yves Avenard [:jya]]

Attachment: Part2. Cache and update our buffered range as much as possible

Only rescan the moof when we're about to calculate the buffered range.

Comment 10

[Jean-Yves Avenard [:jya]]

Attachment: Part3. Optimise most common addition to IntervalSet

Profiler showed that this is the most common use of IntervalSet. Remove the need for looping in the array.

Comment 11

[Jean-Yves Avenard [:jya]]

Comment on attachment 8608662 [details] [diff] [review]
Part3. Optimise most common addition to IntervalSet

got an idea, will merge that with it

Comment 12

[Jean-Yves Avenard [:jya]]

Attachment: Part4. Don't unecessarily call GetBuffered()

Doh! regression introduced in bug 1163445. We are only supposed to calculate the buffered range for stream where the duration is unknown.

Comment 13

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Attachment: stack with |"media.format-reader.mp4" = false|

Setting media.format-reader.mp4=false I still see the problem. The stack looks the same but with MP4Reader::GetBuffered instead of MediaFormatReader::GetBuffered, I think. Same hangup.

Comment 14

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8608660 [details] [diff] [review]
Part2. Cache and update our buffered range as much as possible

Review of attachment 8608660 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/media/fmp4/MP4Demuxer.cpp
@@ +342,5 @@
>      ranges +=
>        media::TimeInterval(media::TimeUnit::FromMicroseconds(timeRanges[i].start),
>                            media::TimeUnit::FromMicroseconds(timeRanges[i].end));
>    }
> +  return buffered;

return ranges.

Comment 15

[Jean-Yves Avenard [:jya]]

Attachment: Part5. Don't call GetBuffered() on the main thread

Never have the MDSM calls GetBuffered() on the main thread, as the time range is cached by the MediaFormatReader it's only calculated a few time. We had to make sure the buffered range time is updated immediately so that the next task running on the reader's queue gets the last value. With this we drop the CPU runtime (still during 1 minute playback) from 65s to 16s. Most of that time (6.6s) is spent in VsyncRefreshDriver. This could be more elegantly done with the state mirror mechanism

Comment 16

[Jean-Yves Avenard [:jya]]

Attachment: Part1. Cache main thread buffered time range

Rebase

Comment 17

[Jean-Yves Avenard [:jya]]

Attachment: Part2. Only rescans MP4's moof when necessary

Rebase

Comment 18

[Jean-Yves Avenard [:jya]]

Attachment: Part3. Optimise most common addition to IntervalSet

Rebase

Comment 19

[Jean-Yves Avenard [:jya]]

Attachment: Part4. Don't unecessarily call GetBuffered()

Rebase

Comment 20

[Jean-Yves Avenard [:jya]]

Attachment: Part5. Don't call GetBuffered() on the main thread

Rebase

Comment 21

[Jean-Yves Avenard [:jya]]

Attachment: Part5. Don't call GetBuffered() on the main thread

Minor rewrite. NotifiedDataArriverd is called every 65kB downloaded. This causes up to 6000 tasks being queued on my machine before any of other tasks have a chance to run. That causes 6000 calls to GetBuffered() consecutively. Using ScheduleUpdate() allows us to slightly buffer those as it runs only one Update() par run. To ensure we have up to date buffered range in GetBuffered(), we force the update there if necessary

Comment 23

[Jean-Yves Avenard [:jya]]

The patches depends on bug 1163227.

I will commit part4 now as it's the core reason of the high-cpu usage and will push the rest with 1163227

Comment 24

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/85dae255c645

Comment 25

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/85dae255c645

Comment 26

[Jean-Yves Avenard [:jya]]

Attachment: Part1. Cache main thread buffered time range

MDSM::NotifyDataArrived isn't always called, so we must set mCachedTimeRangesStale initially to true so the next call to GetBuffered() will force a refresh. I've merged the refresh of cached time range from part5.

Comment 27

[Jean-Yves Avenard [:jya]]

Comment on attachment 8609233 [details] [diff] [review]
Part5. Don't call GetBuffered() on the main thread

This causes intermittent failure with some format that do not set the duration in the loadedmetadata phase and relies on the first MDSM::NotifyDataArrived to set the duration.

I believe the mochitests test the wrong behaviour but that's for a later.

At least with MediaFormatReader the buffered range is cache, so it won't cause high CPU usage even on the main thread.

Comment 28

[Jean-Yves Avenard [:jya]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=62ec2a54c4a6

super consistent on all version of mac and windows, still old intermittent with bug 1138555 on linux

Comment 29

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/6d38104707a1
https://hg.mozilla.org/integration/mozilla-inbound/rev/91df4391d321
https://hg.mozilla.org/integration/mozilla-inbound/rev/9fe966afb11a

Comment 30

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/6d38104707a1
https://hg.mozilla.org/mozilla-central/rev/91df4391d321
https://hg.mozilla.org/mozilla-central/rev/9fe966afb11a