1279125 - Firefox 47: HTML5 video with VP9 codec stops after a few seconds

Status: RESOLVED FIXED

(Core :: Audio/Video: Playback, defect, P1)

Description

[u209627]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:47.0) Gecko/20100101 Firefox/47.0
Build ID: 20160608014842

Steps to reproduce:

Firefox 47 defaults to use VP9 codec on Youtube and this causes the Youtube videos to stop after a few seconds.

This doesn't happen with H264 videos, so a workaround is to use media.webm.enabled = false and everything plays fine.

What is stranger is that Vimeo also stops after a few seconds and Youtube live stream too (Does Vimeo or Youtube live stream use VP9 or something similar?).

Any hints?

Comment 1

[Jean-Yves Avenard [:jya]]

(In reply to Dâniel Fraga from comment #0)
> User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:47.0) Gecko/20100101
> Firefox/47.0
> Build ID: 20160608014842
> 
> Steps to reproduce:
> 
> Firefox 47 defaults to use VP9 codec on Youtube and this causes the Youtube
> videos to stop after a few seconds.

YouTube has used VP9 on Linux by default since 43 when MSE/WebM was enabled.

Please provide a link of such video not playing as describe.

Comment 2

[u209627]

(In reply to Jean-Yves Avenard [:jya] from comment #1)
> YouTube has used VP9 on Linux by default since 43 when MSE/WebM was enabled.
> 
> Please provide a link of such video not playing as describe.

Yes, but this happens with any video from Youtube using VP9 codec. What I don't understand is why with H264 it doesn't happen. Since Firefox is using ffmpeg, maybe it's a libvpx issue?

Comment 3

[Jean-Yves Avenard [:jya]]

Ffmpeg is used for vp9 too. We ship ffvp9 version 3.0 to decode vp9 (or vp8)

If you want to test with libvpx you can set media.ffvpx.enabled to false (media.ffmpeg.enabled to false but that disable ffmpeg completely). 

In any case, needless to say that I can't reproduce the problem, nor has it ever been reported by anyone else). And YouTube being the most visited site, there's something weird happening here.

Comment 4

[u209627]

(In reply to Jean-Yves Avenard [:jya] from comment #3)

> If you want to test with libvpx you can set media.ffvpx.enabled to false
> (media.ffmpeg.enabled to false but that disable ffmpeg completely). 
> 
> In any case, needless to say that I can't reproduce the problem, nor has it
> ever been reported by anyone else). And YouTube being the most visited site,
> there's something weird happening here.

Ok, I tried disabling media.ffvpx.enabled and media.ffmpeg.enabled, but it didn't work.

If you have more suggestions, I'll try anything to solve this.

Comment 5

[Jean-Yves Avenard [:jya]]

Can you please start Firefox with the following env variable set:

First disable e10s (Enable multi-process Nightly in the preferences)
then run firefox with:
NSPR_LOG_MODULES=PlatformDecoderModule:5,MediaFormatReader:5,MediaSource:5,MediaSourceSamples:5 ./path/to/firefox

Load a youtube video causing the stall for you.
This is going to be very verbose. So, you'll need to zip it first before attaching it here.

Also post here the output of about:support.

Thanks

Comment 6

[u209627]

Attachment: aboutsupport.txt

about:support

Comment 7

[u209627]

Attachment: firefox-log.txt.bz2

output for NSPR_LOG_MODULES=PlatformDecoderModule:5,MediaFormatReader:5,MediaSource:5,MediaSourceSamples:5

Comment 8

[u209627]

(In reply to Jean-Yves Avenard [:jya] from comment #5)

> First disable e10s (Enable multi-process Nightly in the preferences)
> then run firefox with:
> NSPR_LOG_MODULES=PlatformDecoderModule:5,MediaFormatReader:5,MediaSource:5,
> MediaSourceSamples:5 ./path/to/firefox

> Also post here the output of about:support.

Ok, thanks. I sent both files. I used the following video to test:

https://www.youtube.com/watch?v=KBFedmrDTQw

Although it happens on any video.

Ps: after the video stops, I tried to move the slider ahead, but it keeeps stopping no matter what. It seems it can play just 1 second of the video and stops after that.

Comment 9

[Jean-Yves Avenard [:jya]]

Please try in safe mode and see if you're still having problems.

What this YouTube extension high definition extension? Try without.

Comment 10

[u209627]

(In reply to Jean-Yves Avenard [:jya] from comment #9)
> Please try in safe mode and see if you're still having problems.
> 
> What this YouTube extension high definition extension? Try without.

I tried in safe mode, but it keeps stopping. And disabling Youtube High Definition extension didn't help either.

Isn't there anything suspect on the log? Is there anything else I can do?

Comment 11

[Jean-Yves Avenard [:jya]]

Haven't had the chance to look at the logs yet. Please try with a clean profile. 

YouTube with VP9 is used by millions of people every day. If it was so common we would have heard about it.

Comment 12

[u209627]

(In reply to Jean-Yves Avenard [:jya] from comment #11)
> Haven't had the chance to look at the logs yet. Please try with a clean
> profile. 
> 
> YouTube with VP9 is used by millions of people every day. If it was so
> common we would have heard about it.

I tried with a brand new profile, but it didn't work.

Yes, I agree it's strange it happens with me and nobody else, but maybe I have a specific setup and I'm reaching a very specific case nobody else experienced.

Comment 13

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

It may be worth trying nightly.

Comment 14

[Jean-Yves Avenard [:jya]]

Please install the about:media plugin (https://addons.mozilla.org/en-US/firefox/addon/about-media/?src=api) play the youtube page; open a new tab and type about:media.

Please copy/paste here the result

Comment 15

[Jean-Yves Avenard [:jya]]

In this log it shows that playback was ongoing, then you (you, or an extension or whatelse) seeked to 117.920024s, the video is then paused.

At the time, the video has been entirely buffered (with the buffered range being [0.000000, 279.321000)

Can you re-run that video with :
NSPR_LOG_MODULES=MediaDecoder:5,MediaFormatReader:5

if all you did is let the video play and it stalled, then it looks like something seeked and they pause in that video.
An extension maybe?

(right at that time when playback is paused, in the console there's an error about a script http://www4.tjrj.jus.br failing and media element is then closed, not sure if that's related)

Comment 16

[u209627]

(In reply to Jean-Yves Avenard (On PTO until July 10) [:jya] from comment #14)
> Please install the about:media plugin
> (https://addons.mozilla.org/en-US/firefox/addon/about-media/?src=api) play
> the youtube page; open a new tab and type about:media.
> 
> Please copy/paste here the result

Ok, here's the output:

HTMLMediaElement debug data

https://www.youtube.com/watch?v=KBFedmrDTQw
	mediasource:https://www.youtube.com/75906cf7-ed54-438c-8a1a-c4a0469cb758
	currentTime: 0.736
	Quality: 100% (total:33 dropped:0 corrupted:0)
	Buffered ranges: [(0, 279.321)]
		SourceBuffer 0
			start=0 end=279.321
		SourceBuffer 1
			start=0 end=279.28
	Internal Data:
	audio decoder: opus audio decoder
	audio frames decoded: 141
	video decoder: ffvpx video decoder
	hardware video decoding: disabled
	video frames decoded: 32 (skipped:0)
	Dumping data for demuxer 7fe52cbd2400:
		Dumping Audio Track Buffer(audio/webm; codecs=opus): - mLastAudioTime: 2.821000
			NumSamples:13966 Size:7097972 NextGetSampleIndex:141 NextInsertionIndex:13966
			Buffered: ranges=[(0.000000, 279.321000)]
		Dumping Video Track Buffer(video/webm; codecs=vp9) - mLastVideoTime: 1.320000
			NumSamples:6982 Size:14399118 NextGetSampleIndex:33 NextInsertionIndex:6982
			Buffered: ranges=[(0.000000, 279.280000)]

Comment 17

[u209627]

(In reply to Jean-Yves Avenard (On PTO until July 10) [:jya] from comment #15)
> In this log it shows that playback was ongoing, then you (you, or an
> extension or whatelse) seeked to 117.920024s, the video is then paused.
> 
> At the time, the video has been entirely buffered (with the buffered range
> being [0.000000, 279.321000)
> 
> Can you re-run that video with :
> NSPR_LOG_MODULES=MediaDecoder:5,MediaFormatReader:5
> 
> if all you did is let the video play and it stalled, then it looks like
> something seeked and they pause in that video.
> An extension maybe?
> 
> (right at that time when playback is paused, in the console there's an error
> about a script http://www4.tjrj.jus.br failing and media element is then
> closed, not sure if that's related)

Don't worry about the seeking. It's just me seeking through the video to show it stops no matter what time of the video I'm watching. Regarding the error about a script failing, it's Distill extension, but even with all extension disabled (safe-mode) it happens).

I'm uploading the log you requested. I opened the video, wait for it to stop. Then I reload the video, it buffered 100% and stopped. Then I seeked to another time on the video and it stopped.

Comment 18

[u209627]

Attachment: firefox-log2.txt.bz2

NSPR_LOG_MODULES=MediaDecoder:5,MediaFormatReader:5

Comment 19

[Jean-Yves Avenard [:jya]]

Please don't.. Just start the video wait until it stops. Don't do anything else, otherwise it makes it much harder to guess what's going on.

Then copy the output of about:media and the logs.

Thanks

Comment 20

[u209627]

(In reply to Jean-Yves Avenard (On PTO until July 10) [:jya] from comment #19)
> Please don't.. Just start the video wait until it stops. Don't do anything
> else, otherwise it makes it much harder to guess what's going on.
> 
> Then copy the output of about:media and the logs.
> 
> Thanks

Ok, sorry. Now I did it the correct way:

1) about:media output

HTMLMediaElement debug data

https://www.youtube.com/watch?v=KBFedmrDTQw
	mediasource:https://www.youtube.com/3b09a8e5-5aca-4631-b18d-168f601946c3
	currentTime: 1.841166
	Quality: 100% (total:61 dropped:0 corrupted:0)
	Buffered ranges: [(0, 279.321)]
		SourceBuffer 0
			start=0 end=279.321
		SourceBuffer 1
			start=0 end=279.28
	Internal Data:
	audio decoder: opus audio decoder
	audio frames decoded: 202
	video decoder: ffvpx video decoder
	hardware video decoding: disabled
	video frames decoded: 60 (skipped:0)
	Dumping data for demuxer 7f708010a800:
		Dumping Audio Track Buffer(audio/webm; codecs=opus): - mLastAudioTime: 3.921000
			NumSamples:13966 Size:7097972 NextGetSampleIndex:196 NextInsertionIndex:13966
			Buffered: ranges=[(0.000000, 279.321000)]
		Dumping Video Track Buffer(video/webm; codecs=vp9) - mLastVideoTime: 2.440000
			NumSamples:6982 Size:14399118 NextGetSampleIndex:61 NextInsertionIndex:6982
			Buffered: ranges=[(0.000000, 279.280000)]

2) and the logfile (firefox-log3-final.txt.bz2) will be attached

I just started Firefox. The first tab opened is the Youtube video tab. I didn't touch anything. The video started playing and stopped. Then I opened another tab to get the about:media output and that's it.

I notice the video gets stuck with the following loop (this never ends):

[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1880000 (id=30) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1920000 (id=31) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1960000 (id=32) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2000000 (id=33) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2040000 (id=34) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2080000 (id=35) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2120000 (id=36) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2160000 (id=37) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2200000 (id=38) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2240000 (id=39) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1840000 (id=2f) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1880000 (id=30) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1920000 (id=31) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1960000 (id=32) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2000000 (id=33) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2040000 (id=34) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2080000 (id=35) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2120000 (id=36) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2160000 (id=37) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2200000 (id=38) (vq-queued=11)
[MediaPlayback #4]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2240000 (id=39) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1840000 (id=2f) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1880000 (id=30) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1920000 (id=31) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1960000 (id=32) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2000000 (id=33) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2040000 (id=34) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2080000 (id=35) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2120000 (id=36) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2160000 (id=37) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2200000 (id=38) (vq-queued=11)
[MediaPlayback #5]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 2240000 (id=39) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1840000 (id=2f) (vq-queued=11)
[MediaPlayback #1]: V/MediaDecoder VideoSink=7f70850afa80 playing video frame 1880000 (id=30) (vq-queued=11)

Comment 21

[u209627]

Attachment: firefox-log3-final.txt.bz2

NSPR_LOG_MODULES=MediaDecoder:5,MediaFormatReader:5

Comment 22

[Jean-Yves Avenard [:jya]]

JW, could you look at the log, do you see anything special about it?

The MediaFormatReader indicates that after RequestVideoData was called, the video frames are played in some kind of loop.

Comment 23

[JW Wang [:jwwang] [:jw_wang]]

It looks like audio clock is not progressing.

Can you catch the log with:
NSPR_LOG_MODULES=timestamp:1,MediaDecoder:5,AudioStream:4

Thanks.

Comment 24

[u209627]

Attachment: firefox-log-timestamp-final.log.bz2

Ok JW, here's the log with the timestamp.

Comment 25

[JW Wang [:jwwang] [:jw_wang]]

Thanks for the log.

2016-06-27 07:49:48.199066 UTC - [Unnamed thread 0x7ff41da55160]: D/AudioStream 7ff41c7f8ca0 StateCallback, mState=2 cubeb_state=3
2016-06-27 07:49:48.199106 UTC - [Unnamed thread 0x7ff41da55160]: D/AudioStream 7ff41c7f8ca0 StateCallback() state 2 cubeb error


Looks like something wrong to the cubeb stream. Need to add more logs for tracing.

Comment 26

[JW Wang [:jwwang] [:jw_wang]]

http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-29de4ba07511b37749bf24cfc7cbf5d0bcec8073/try-linux64/firefox-50.0a1.en-US.linux-x86_64.tar.bz2

Here is the build with more logs.

Can you download the build and run with
MOZ_LOG=timestamp:1,AudioStream:4 ./firefox-bin https://www.youtube.com/watch?v=KBFedmrDTQw ?

Thanks!

Comment 27

[u209627]

Attachment: firefox-log-audiostream.txt

MOZ_LOG=timestamp:1,AudioStream:4 ./firefox-bin https://www.youtube.com/watch?v=KBFedmrDTQw

Comment 28

[u209627]

(In reply to JW Wang [:jwwang] from comment #26)

> Can you download the build and run with
> MOZ_LOG=timestamp:1,AudioStream:4 ./firefox-bin
> https://www.youtube.com/watch?v=KBFedmrDTQw ?

Ok, I attached the full log. I think the relevant part is:

2016-06-27 14:50:43.309852 UTC - [MediaPlayback #3]: D/AudioStream 7faa8b2f4cc0 Init channels: 2, rate: 48000
2016-06-27 14:50:43.541499 UTC - [MediaPlayback #3]: D/AudioStream 7faa8b2f4cc0 creation time first: 231 ms
2016-06-27 14:50:43.541585 UTC - [MediaPlayback #3]: D/AudioStream 7faa8b2f4cc0 started, state STARTED
2016-06-27 14:50:54.768094 UTC - [Unnamed thread 0x7faa94755940]: D/AudioStream 7faa8b2f4cc0 StateCallback, mState=1 cubeb_state=3
2016-06-27 14:50:54.768159 UTC - [Unnamed thread 0x7faa94755940]: D/AudioStream 7faa8b2f4cc0 StateCallback() state 1 cubeb error

Comment 29

[JW Wang [:jwwang] [:jw_wang]]

Thanks for the extracted logs.

The cubeb stream is started at 43.541585 and some unknown error occurs about 11s later at 54.768094. Therefore the cubeb stops requesting data and the audio clock stops as well as the playback.

Hi kinetik,
Do you have any idea about what could cause a CUBEB_STATE_ERROR?

Btw, it is worth noting that this problem only happens on Daniel's computer and this problem goes away if Youtube servers H264 instead of VP9.

Comment 30

[Matthew Gregan [:kinetik]]

Daniel, can you confirm if you're using PulseAudio or ALSA?  Unfortunately, we don't (yet) log the backend in use in about:support.  If you don't have PA installed, we'll be falling back to ALSA.  If you have PA installed, there's a possibility we're still falling back to ALSA -- to check that, look in the PA volume control while Firefox is playing audio and note the name of the stream; if it's "Nightly: Audiostream" or "CubebUtils: Audiostream" then it's using PulseAudio directly and if it's something like "ALSA plug-in [firefox]" then we're using ALSA.

(In reply to JW Wang [:jwwang] from comment #29)
> Do you have any idea about what could cause a CUBEB_STATE_ERROR?

It depends which audio backend is in use.

The PulseAudio backend only calls the state_callback with CUBEB_STATE_ERROR in one place, which is if the stream has transitioned away from PA_STREAM_READY to some error or disconnected state, which would suggest something happening with the PulseAudio server process.  Looking at logs from the PA server would probably be the best next step, in that case.

The ALSA backend calls state_callback with CUBEB_STATE_ERROR from four error paths; we'd probably need to add more logging to work out what's going wrong, but it's worth noting that one of those paths has a watchdog timer that kills the stream and fires an error if the stream has not requested data for 10s -- that's suspiciously close to the 
~11.2s noted above.

(In reply to JW Wang [:jwwang] from comment #29)
> Btw, it is worth noting that this problem only happens on Daniel's computer
> and this problem goes away if Youtube servers H264 instead of VP9.

Doesn't make sense that the video codec would have an effect directly.  The first thing that comes to mind here is that VP9 is likely paired with Opus and playing back at 48kHz and I'd guess H.264 is paired with AAC and probably playing back at 44.1kHz, and the different sample rate could be triggering some audio playback bug somewhere in the stack.

Comment 31

[Matthew Gregan [:kinetik]]

And if you're using ALSA, you'll almost certainly find that switching to PulseAudio will fix this issue.

Comment 32

[Jean-Yves Avenard [:jya]]

Webm/Opus is enabled even with MP4/h264 video, so they now typically always get opus.

Comment 33

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #30)
> Daniel, can you confirm if you're using PulseAudio or ALSA?  Unfortunately,
> we don't (yet) log the backend in use in about:support.  If you don't have
> PA installed, we'll be falling back to ALSA.  If you have PA installed,
> there's a possibility we're still falling back to ALSA -- to check that,
> look in the PA volume control while Firefox is playing audio and note the
> name of the stream; if it's "Nightly: Audiostream" or "CubebUtils:
> Audiostream" then it's using PulseAudio directly and if it's something like
> "ALSA plug-in [firefox]" then we're using ALSA.

Matthew, I just use ALSA (no Pulseaudio installation here).

Comment 34

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #30)

> Doesn't make sense that the video codec would have an effect directly.  The
> first thing that comes to mind here is that VP9 is likely paired with Opus
> and playing back at 48kHz and I'd guess H.264 is paired with AAC and
> probably playing back at 44.1kHz, and the different sample rate could be
> triggering some audio playback bug somewhere in the stack.

I'll send my ~/.asoundrc file, but there isn't anything special about it (I just use dmix and dsnoop).

If you want I can apply patches and test too.

Comment 35

[u209627]

Attachment: alsa-asoundrc.txt

Comment 36

[Matthew Gregan [:kinetik]]

Thanks.  If you test with WebM disabled, what sample rate is the audio stream being produced at in the logs?  If it's 44.1kHz, you could try (with WebM enabled, and with a Nightly build) setting (in about:config) media.resampling.enabled to true and media.resampling.rate to 44100 to see if the bug still triggers.

I've also pushed a build with some additional logging (to stderr, it doesn't use the Gecko logging).  It should turn up here in a couple of hours: http://ftp.mozilla.org/pub/firefox/try-builds/[e-mail]-70c6a4f2c699/

Comment 37

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #36)
> Thanks.  If you test with WebM disabled, what sample rate is the audio
> stream being produced at in the logs?  If it's 44.1kHz, you could try (with
> WebM enabled, and with a Nightly build) setting (in about:config)
> media.resampling.enabled to true and media.resampling.rate to 44100 to see
> if the bug still triggers.

Ok, you're right. With WebM disabled, the audio rate is 44.1kHz:

2016-06-28 08:35:24.450573 UTC - [Main Thread]: D/MediaDecoder Decoder=7f65192df6e0 MetadataLoaded, channels=2 rate=44100 hasAudio=1 hasVideo=1
2016-06-28 08:35:24.450650 UTC - [Main Thread]: D/MediaDecoder Decoder=7f65192df6e0 UpdateDormantState aTimeout=0 aActivity=0 mIsDormant=0 ownerActive=1 ownerHidden=0 mIsHeuristicDormant=0 mPlayState=PLAY_STATE_LOADING encrypted=0
2016-06-28 08:35:24.450831 UTC - [Main Thread]: D/MediaDecoder Decoder=7f65192df6e0 Telemetry MEDIA_CODEC_USED= 'audio/mp4a-latm'
2016-06-28 08:35:24.450852 UTC - [Main Thread]: D/MediaDecoder Decoder=7f65192df6e0 Telemetry MEDIA_CODEC_USED= 'video/avc'
2016-06-28 08:35:24.451534 UTC - [Main Thread]: D/MediaDecoder Decoder=7f65192df6e0 FirstFrameLoaded, channels=2 rate=44100 hasAudio=1 hasVideo=1 mPlayState=PLAY_STATE_LOADING mIsDormant=0

So I changed the about:config as you requested and with media.resampling.rate to 44100, WebM works fine! Vimeo also works now ;) So the issue is with the audio rate, right?

> I've also pushed a build with some additional logging (to stderr, it doesn't
> use the Gecko logging).  It should turn up here in a couple of hours:
> http://ftp.mozilla.org/pub/firefox/try-builds/[e-mail]-
> 70c6a4f2c699/

Ok, as soon as the build finishes, I'll download and return the log. Thanks.

Comment 38

[Matthew Gregan [:kinetik]]

(In reply to Dâniel Fraga from comment #37)
> So I changed the about:config as you requested and with
> media.resampling.rate to 44100, WebM works fine! Vimeo also works now ;) So
> the issue is with the audio rate, right?

That's definitely useful information, thanks for testing.  It seems related to the sample rate, possibly triggering a buffer sizing bug in our ALSA backend or in ALSA/dmix that we need to deal with.  I uploaded some simple sine wave tests if you want to try a simpler case: https://flim.org/~kinetik/tests/bug1279125/ -- they're Vorbis rather than Opus but I'm reasonably sure the bug will still trigger without resampling and disappear with resampling.

Given we've narrowed this down to ALSA and probably to audio format related issues, it may be useful to have a copy of the output of ALSA's debug script: http://www.alsa-project.org/alsa-info.sh

> Ok, as soon as the build finishes, I'll download and return the log. Thanks.

They're up now, but I guessed the wrong URL.  The builds are at: http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-70c6a4f2c6995f30c1b734250d896baf56a457c5/

Given the sample rate confirmation above the logs probably won't reveal enough to formulate a fix, but it'd still be interesting to see which error path(s) we're triggering when playback fails.

Comment 39

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #38)
> That's definitely useful information, thanks for testing.  It seems related
> to the sample rate, possibly triggering a buffer sizing bug in our ALSA
> backend or in ALSA/dmix that we need to deal with.  I uploaded some simple
> sine wave tests if you want to try a simpler case:
> https://flim.org/~kinetik/tests/bug1279125/ -- they're Vorbis rather than
> Opus but I'm reasonably sure the bug will still trigger without resampling
> and disappear with resampling.

You're right again ;) It works just with resampling.

> Given we've narrowed this down to ALSA and probably to audio format related
> issues, it may be useful to have a copy of the output of ALSA's debug
> script: http://www.alsa-project.org/alsa-info.sh

> They're up now, but I guessed the wrong URL.  The builds are at:
> http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-
> 70c6a4f2c6995f30c1b734250d896baf56a457c5/
> 
> Given the sample rate confirmation above the logs probably won't reveal
> enough to formulate a fix, but it'd still be interesting to see which error
> path(s) we're triggering when playback fails.

Ok, I'm uploading now the log from the build you suggested and the alsa-info output.

Comment 40

[u209627]

Attachment: alsa-info.txt

Comment 41

[u209627]

Attachment: firefox-log-matthew-final.txt.bz2

Comment 42

[Matthew Gregan [:kinetik]]

Thanks again.  The logs confirm that we're hitting the watchdog timer as I guessed in comment 30:

2016-06-28 22:41:16.525621 UTC - [Unnamed thread 0x7f438d64bbc0]: D/AudioStream 7f4392f279e0 StateCallback() state 1 cubeb error
[...]
alsa_run(0x7f43917512e0): stream error: watchdog timeout

I'll see if I can repro locally based on the config and alsa-info you've provided.

Comment 43

[Matthew Gregan [:kinetik]]

I can repro something similar locally once I duplicate the dmix configuration.  It looks like ALSA wakes us up via poll() but revents doesn't contain POLLOUT so we early-exit alsa_refill_stream waiting for a later wakeup, but we never get one with POLLOUT set before the 10s watchdog kicks in.

This ends up looking remarkably similar to one of the changes made in bug 1130155 (which got stuck in limbo due to inadequate explanation of why the changes were needed).

On wakeup, if we ignore POLLOUT and check the available buffer space is > 0 and attempt to refill, playback works for me locally.  The down side of that is we lose control of the rate we request audio from the API user, since the intention was to refill complete buffer (period) chunks at a time, and now we're forced to refill some random smaller amount at ALSA's will.

Build with a preliminary fix should appear here within a couple of hours:
http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-4cc26ed324816f5d945f3782490eb3a18a0632a8/

Comment 44

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #43)

> Build with a preliminary fix should appear here within a couple of hours:
> http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-
> 4cc26ed324816f5d945f3782490eb3a18a0632a8/

Thank you Matthew! Your fix works perfectly here!

Will you provide a patch (so I can apply on Firefox 47)?

Comment 45

[Matthew Gregan [:kinetik]]

Attachment: bug1279125_v0.patch

Thanks again for confirming!  This patch should apply to 47 directly as I don't think there have been any significant changes made to the ALSA backend since then.

Comment 46

[Matthew Gregan [:kinetik]]

It occurred to me that there's no point calling snd_pcm_poll_descriptors_revents if we don't look at the resulting revents, so I removed the call completely:

https://github.com/kinetiknz/cubeb/commit/de4940260e197592faaed7d3818e85c6aca56197

The comment removed there was also slightly wrong, because it's documented behaviour that poll() can return but the processed revent is zero.

Comment 47

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #46)
> It occurred to me that there's no point calling
> snd_pcm_poll_descriptors_revents if we don't look at the resulting revents,
> so I removed the call completely:
> 
> https://github.com/kinetiknz/cubeb/commit/
> de4940260e197592faaed7d3818e85c6aca56197

Any idea on what Firefox version this patch will be merged?

Comment 48

[Matthew Gregan [:kinetik]]

It just landed via bug 1283850, so it'll be included in Nightly shortly and will ride the trains in v50.

Comment 49

[Paul Adenot (:padenot)]

We can close this now, bug 1283850 has been merged in mozilla-central.

Comment 50

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #48)
> It just landed via bug 1283850, so it'll be included in Nightly shortly and
> will ride the trains in v50.

Matthew, I found another issue with your final patch (it happens with just some videos, so I just notice now): it's skipping very fast the video. With the first patch it doesn't happen. If you need I can do more tests, but if you can replicate there, you can test with the following video:

https://www.youtube.com/watch?v=CHpCc1DfDHA (H.264)

or this one:

https://www.youtube.com/watch?v=q5qWufRYucA (VP9)

I suspect there's something different regarding the audio, right?

I wait for your instructions, so we can figure it out what's happening.

Thanks.

Comment 51

[Matthew Gregan [:kinetik]]

Nothing unusual about the audio in those files, looks like they are both 44.1kHz stereo (one AAC, the other Vorbis).

If the build from comment 43 works but the final patch and Nightly build doesn't, it looks like the extra test for being woken up when the output buffer is still full really is necessary.  The original change converted that case to a non-error, but the final patch left the recovery code in place (which explains the skipping; it recreates the output stream or at least discards the buffered audio).

Here (shortly) is a build that reinstates the previous change in a cleaner way:

http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-ae4b0ab2bea1ba6f353917c03adedf996feecea7/

I don't think we need that recovery code; if the stream is really broken it'll be dealt with by the watchdog timeout code.

Comment 52

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #51)
> Here (shortly) is a build that reinstates the previous change in a cleaner
> way:
> 
> http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-
> ae4b0ab2bea1ba6f353917c03adedf996feecea7/
> 
> I don't think we need that recovery code; if the stream is really broken
> it'll be dealt with by the watchdog timeout code.

This build works fine, except that on the second video the time counter freezes than jump to the right "time" in the first 30 seconds:

https://www.youtube.com/watch?v=q5qWufRYucA

But i can see the video perfectly.

Ps: I don't know if your patch affects somehow the time counter... At least I can see the video perfectly.

Comment 53

[u209627]

than -> then (sorry)

Comment 54

[Matthew Gregan [:kinetik]]

Thanks for testing.  I'll come back to this in a bit (next week?), I'm tied up with other bugs at the moment.  I'll ni? myself so I don't forget.

(In reply to Dâniel Fraga from comment #52)
> This build works fine, except that on the second video the time counter
> freezes than jump to the right "time" in the first 30 seconds:

Is the audio playing correctly during that time?

> https://www.youtube.com/watch?v=q5qWufRYucA
> 
> But i can see the video perfectly.
> 
> Ps: I don't know if your patch affects somehow the time counter... At least
> I can see the video perfectly.

The time is derived from the position of the audio stream, with the ALSA backend the main reason for time to jump ahead like that is if we detect the stream is underrunning and call snd_pcm_recover on it, which discards the current audio buffer and causes a complete refill.

Comment 55

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #54)
> Thanks for testing.  I'll come back to this in a bit (next week?), I'm tied
> up with other bugs at the moment.  I'll ni? myself so I don't forget.

No problem Matthew. Take your time. ;)

> Is the audio playing correctly during that time?

Yes, the audio is perfect.

> The time is derived from the position of the audio stream, with the ALSA
> backend the main reason for time to jump ahead like that is if we detect the
> stream is underrunning and call snd_pcm_recover on it, which discards the
> current audio buffer and causes a complete refill.

I see. Anyway it doesn't affect the audio and video, so maybe we can ignore it at this moment. At least the main issue is solved ;)

Comment 56

[Matthew Gregan [:kinetik]]

For the record: we're also discussing this in https://github.com/kinetiknz/cubeb/pull/127

https://treeherder.mozilla.org/#/jobs?repo=try&revision=91fff44e5746
https://treeherder.mozilla.org/#/jobs?repo=try&revision=91527b924ce5

Builds should appear here soon:

http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-91fff44e57466d7e300aad15a94843796bccda63/
http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-91527b924ce5cea957beb826c195c2321adec847/

I'm fairly certain the second build will reintroduce the bug originally reported here.

Comment 57

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #56)
> Builds should appear here soon:
> 
> http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-
> 91fff44e57466d7e300aad15a94843796bccda63/
> http://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-
> 91527b924ce5cea957beb826c195c2321adec847/
> 
> I'm fairly certain the second build will reintroduce the bug originally
> reported here.

You're correct. The first build works perfectly while the second build fails.

Comment 58

[Matthew Gregan [:kinetik]]

Thanks Daniel.  I'll call this fixed as of https://github.com/kinetiknz/cubeb/commit/18efde64d2126f351985bdcfe7b1293c2337df0f but I'll need to update Gecko's copy of libcubeb to pick up the fix.

Comment 59

[u209627]

(In reply to Matthew Gregan [:kinetik] from comment #58)
> Thanks Daniel.  I'll call this fixed as of
> https://github.com/kinetiknz/cubeb/commit/
> 18efde64d2126f351985bdcfe7b1293c2337df0f but I'll need to update Gecko's
> copy of libcubeb to pick up the fix.

No problem Matthew. Thank you very much for your help on this.

Comment 61

[Matthew Gregan [:kinetik]]

The second part of this fix (per comment 58) has landed via bug 1290425.