Open Bug 1588395 Opened 5 years ago Updated 2 years ago

[Linux] Loading circle and lag on YouTube Videos (OK after reloading)

Categories

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

Product:
Core
Component:
Audio/Video: Playback
Version:
69 Branch
Platform:
x86_64
Linux
Type:
defect

Tracking

()

People

(Reporter: cryptage, Unassigned)

References

Details

Attachments

(7 files)

BugFirefoxYT.avi
5.24 MB, video/x-msvideo
Details
moz.log.child-3.gz
906.22 KB, application/gzip
Details
SoundFF.png
56.54 KB, image/png
Details
pulseverbose.log
501.18 KB, text/x-log
Details
moz.log.child-1.gz
621.59 KB, application/gzip
Details
equalizer-presets.tdb
648.00 KB, application/octet-stream
Details
qpaeq.png
26.05 KB, image/png
Details
Attached video BugFirefoxYT.avi —

Hi,

I have a bug on Linux with YouTube videos.

Easy to reproduce :
Go to Youtube.com and load a video randomly.

The problem :
The video takes some time to load and when I want to move in the video I always have the loading circle.

If I refresh with Ctrl+R or Ctrl+F5 video loads instantly, the same if I move in the video (even if it's not preloaded).

--> I've attached a video with the problem.

Description :
I'm using Linux Debian 10.1 with Mate and Marco (no compositor).

Firefox version is 69.0.3 (but same problem with older versions, I tried 56, 57, 64, 65...).

I own a Nvidia NVS 310 video card with Nvidia 390.87 driver.
Hardware acceleration is enabled.

  • I tried with a new Firefox profile, no extension and safe mode but the problem still persists.
  • I used another video card (Nvidia Quadro K600 and 430.50 driver) but it doesn't change anything.
  • With other window managers (Compton, Compiz...) I still have the problem.

For information Opera browser doesn't have the problem at all, only Firefox.

Thanks for helping me.

OS: Unspecified → Linux
Hardware: Unspecified → x86_64

Something else : after refresh (Ctrl+F5) the video is working great and next videos too.

Component: General → Audio/Video: Playback
Product: Firefox → Core

:bryce, is this something you have time to look at?

Flags: needinfo?(bvandyk)

I'm afraid I don't think I'll realistically have time in the near future to look at this. My guess (not verified) would be that the spinner is triggered by us firing the waiting event, which is typically triggered by the MSE machinery not having enough data -- but we'd need to investigate as to why we're doing that here.

Flags: needinfo?(bvandyk)

Thanks for your answers.

Please let me know if I can provide you any additional information that may help you to solve this unpleasant bug.

I am unable to reproduce on Ubuntu 18.04. I'll note that the hardware and graphics settings listed in the description shouldn't have an impact. On linux we use only software decoders, and for buffering issues the core problem is somewhere before we reach the graphics pipeline.

Could you try to reproduce this with the following environment variable set?
MOZ_LOG=timestamp,sync,nsMediaElement:5,nsMediaElementEvents:5,MediaDecoder:5,MediaSource:5,MediaSourceResource:5

This is hopefully enough to get going. Please note down the steps you did to produce the log, when you started playback, when you clicked the progress bar to seek, which clicks led to buffering, etc. So we know what to look for in the log.

To get the log into a file the easiest is to also set MOZ_LOG_FILE=/path/to/destination/file. There will be a bunch of files, most with a child-N suffix. Please upload the largest one here, with the notes of your steps.

Thanks!

Flags: needinfo?(cryptage)

Hi,

It was very easy for me to reproduce because each time I have the problem.

Preparing :

  • export MOZ_LOG=timestamp,sync,nsMediaElement:5,nsMediaElementEvents:5,MediaDecoder:5,MediaSource:5,MediaSourceResource:5
  • export MOZ_LOG_FILE=/home/cryptage/moz.log
  • /opt/firefox/firefox

Steps :

--> the problem exists.

After that I've done a CTRL+F5 to reload the page : 8:09:30 PM

  • Launching video,
  • Forward to 25s, 50s, 1m50s, 3min,
  • Then back to 55s, 1m25s,
  • Playing video for 5 seconds,
  • Pause.

--> the problem does not exist.

Then exit Firefox.

Flags: needinfo?(cryptage)
Attached file moz.log.child-3.gz —

File uploaded.
I had to gzip it because it was too big (> 20 MB).

While you have the loading circle immediately after a seek; do you hear audio before the circle goes away and video starts playing?

Your example video doesn't contain audio so I cannot judge it, and the log shows that seeking is snappy wrt finding the video key frame and playing audio. What I'm not certain of however, is what event they use to display (or stop displaying) the loading circle, because we fire "playing" much faster than the time until the circle goes away in your video.

Flags: needinfo?(cryptage)

Well, I can see that after the second seek:

18:08:23.090485: D/nsMediaElement 0x7f48ccf9d000 SetCurrentTime(30,087069) starting seek

It takes ~2 seconds before we have played enough audio to drop the first video frame (and your video shows one frame getting displayed shortly after the seek, then a second or two before the loading circle goes away and frames roll continuously):

18:08:25.227531 [MediaDecoderStateMachine #1]: V/MediaDecoder VideoSink=0x7f48c2409600 playing video frame 30100000 (id=f2) (vq-queued=10)

Hmm, I guess you hear ~250ms of audio before the pause?
The audio callbacks after the second seek look like this:

18:08:23.143552 [MediaDecoderStateMachine #1]: D/MediaDecoder VideoSink=0x7f48c2409600 [Start]
18:08:23.143576 [MediaDecoderStateMachine #1]: V/MediaDecoder AudioSink=0x7f48bfef8800 Audio format changed from 0@0Hz to 2@48000Hz
18:08:23.145362 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30087062 offset=0 length=357
18:08:23.145444 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30094500 offset=0 length=960
18:08:23.145469 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30114500 offset=0 length=960
18:08:23.145486 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30134500 offset=0 length=960
18:08:23.145505 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30154500 offset=0 length=960
18:08:23.145529 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30174500 offset=0 length=960
18:08:23.145553 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30194500 offset=0 length=960
18:08:23.145575 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30214500 offset=0 length=960
18:08:23.145599 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30234500 offset=0 length=960
18:08:23.145622 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30254500 offset=0 length=147
18:08:23.145794 [AudioIPC1]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30254500 offset=147 length=813
18:08:23.145817 [AudioIPC1]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30274500 offset=0 length=960
18:08:23.145832 [AudioIPC1]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30294500 offset=0 length=960
18:08:23.145841 [AudioIPC1]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30314500 offset=0 length=191
(...)
18:08:25.214525 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30314500 offset=191 length=769
18:08:25.214561 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30334500 offset=0 length=960
18:08:25.214585 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30354500 offset=0 length=960
18:08:25.214636 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30374500 offset=0 length=960
18:08:25.214661 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30394500 offset=0 length=960
18:08:25.214718 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30414500 offset=0 length=960
18:08:25.214750 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30434500 offset=0 length=960
18:08:25.214763 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30454500 offset=0 length=960
18:08:25.214775 [AudioIPC0]: V/MediaDecoder AudioSink=0x7f48bfef8800 playing audio at time=30474500 offset=0 length=567

kinetik, do you have a clue to what's up?

Flags: needinfo?(kinetik)

I'm confirming this because we have evidence.

Status: UNCONFIRMED → NEW
Ever confirmed: true

Paul, FYI, perhaps this could be related to us blowing the audio budget under rtkit.

Flags: needinfo?(padenot)

I don't think so, the real-time thread is not enabled on the versions that are reported:

Firefox version is 69.0.3 (but same problem with older versions, I tried 56, 57, 64, 65...).

Flags: needinfo?(padenot)

I don't mean that this blows the budget for the reporter, but that the root causes could be the same.

(In reply to Andreas Pehrson [:pehrsons] from comment #9)

While you have the loading circle immediately after a seek; do you hear audio before the circle goes away and video starts playing?

Your example video doesn't contain audio so I cannot judge it, and the log shows that seeking is snappy wrt finding the video key frame and playing audio. What I'm not certain of however, is what event they use to display (or stop displaying) the loading circle, because we fire "playing" much faster than the time until the circle goes away in your video.

I'll try to give the best answer but it's really technical and my english is not perfect :).

  • There's no audio before the circle has disappeared. It starts when the circle disappears, video too.
  • For audio after pausing, I'm not sure. I tried after reloading and there's no difference so I think not.

I'll check older versions just to be sure because when I tried older versions it was a long time ago.

Thanks all for help.

Flags: needinfo?(cryptage)

Done !

I tried Firefox 50.1 and Firefox 57.0.

  • With 50.1 I always have the problem, even if I refresh with CTRL+R.
  • With 57.0 I have the same problem than in 69.0.3 : not good at first loading, ok after CTRL+R/CTRL+F5.

Hope this helps.

I suspect the fact that it works after reload could be for the same reason as bug 1571513. The document from before the reload enters the Back-Forward-cache and the media element gets paused. This pauses the audio sink but leaves it open. Creating a second one for the same device could now be faster.

Seeking stops the audio sink, seeks to the new position, then starts it again; perhaps even destroying it in between -- not sure.

I suspect something in your pulseaudio setup is causing creation/start of an output stream to take a while. What audio output device do you have? And do you have similar issues playing audio from any other app (with no other apps open in the background) to the same device? (i.e., that the first time you want to play something back it takes a while to start)

Flags: needinfo?(cryptage)
See Also: → 1571513

You're absolutely right ! I'm using PulseAudio Equalizer (qpaeq) and it's the root cause !

I've changed parameters to use only the sound card without equalizer and I don't have the problem... Crap !
That's a good news for YT videos but not for equalizer because I need it :(.

It's strange because it's working fine in Opera even with equalizer.

Do you think something is possible in Firefox ?

Flags: needinfo?(cryptage)
Attached image SoundFF.png —

Thanks for narrowing it down to paeq/module-equalizer-sink. Unforunately it appears to be an unmaintained/known buggy PA module (it logs "module-equalizer-sink is currently unsupported, and can sometimes cause PulseAudio crashes, increased latency or audible artifacts. If you're facing audio problems, try unloading this module as a potential workaround." on startup). It might be worth investigating other EQ options for PulseAudio.

It's possible we can workaround the slow startup issue, but it's not yet clear exactly what the cause is. Unfortunately module-equalizer-sink has very little logging, so my initial thought to ask for a PA log while reproducing the problem is unlikely to give us many additional ideas.

Are you able to share your EQ configuration and which PulseAudio version you're using? Also, what CPU model do you have? I don't seem to be able to reproduce this locally on Fedora 30/PulseAudio 12.2 (on an E5-2637 v4) with EQ enabled and random EQ adjustments applied. If we can find a simple way to reproduce this locally, the chance of finding a workaround is greater.

Flags: needinfo?(kinetik) → needinfo?(cryptage)

Actually, redoing the Firefox logging with "cubeb:5" included in the MOZ_LOG and also verbose logging the PulseAudio server (https://wiki.ubuntu.com/PulseAudio/Log) might be useful.

Attached file pulseverbose.log —
Flags: needinfo?(cryptage)
Attached file moz.log.child-1.gz —
Attached file equalizer-presets.tdb —
Attached image qpaeq.png —

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

Actually, redoing the Firefox logging with "cubeb:5" included in the MOZ_LOG and also verbose logging the PulseAudio server (https://wiki.ubuntu.com/PulseAudio/Log) might be useful.

Thanks !
You're right pulseEqualizer is no longer maintained but there's no real alternatives or I didn't find one (PulseEffects is too complicated, not native on Debian 10, etc.).

I'm using Debian 10.1 amd64 :

  • Modename : Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz
  • 03:00.0 Audio device: Creative Labs Sound Core3D [Sound Blaster Recon3D / Z-Series] (rev 01)

I've attached 4 files :

  • Mozilla log with cubeb:5 added,
  • PulseAudio debug log,
  • qpaeq config (~/.config/pulse). Don't know if it's enough to get my preset.
  • Screen of equalizer if not possible to get it work with tdb file.

For timing in video :
12:44:50 : Launch YT

12:45:00 : Launch Video
Go to 15s, 35s, 1m, 2m,
Back to 30s, 1m10s

12:45:50 : pause
12:46:00 : reload page
12:46:10 : load video

12:46:30 : pause and exit Firefox.

Priority: -- → P3

Forgot to add PulseAudio versions :

pulseaudio 12.2-4+deb10u1 amd64 PulseAudio sound server
pulseaudio-equalizer 12.2-4+deb10u1 amd64 Equalizer sink module for PulseAudio sound server
pulseaudio-utils 12.2-4+deb10u1 amd64 Command line tools for the PulseAudio sound server

Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: