search

mumble-voip / mumble

Mumble is an open-source, low-latency, high quality voice chat software.
https://www.mumble.info
Other
6.28k stars 1.11k forks source link

On systems with a lot of fonts mumble freezes for a few seconds on the first console entry #5922

Closed hashworks closed 1 year ago

hashworks commented 1 year ago

Description

My Mumble client freezes for a few seconds on the first chat message send and the CPU usage spikes to 100% (single thread). After that everything works as expected, only the first message is affected.

EDIT: It doesn't have to be a chat message, any console log is enough, even the "Welcome to Mumble" message. EDIT2: This is only noticeable on systems with a lot of fonts.

Steps to reproduce

  1. Start mumble
  2. Connect to server
  3. Try to send message to room
  4. Observe freeze and high CPU for a few seconds
  5. Send another message
  6. Observe normal operation

Mumble version

1.4.287

Mumble component

Client

OS

Linux

Reproducible?

Yes

Additional information

No response

Relevant log output

No log output at all.

Krzmbrzl commented 1 year ago

Have you been using Mumble before and if so: did this ever happen to you with an older version of Mumble?

What distro are you using?

hashworks commented 1 year ago

I think this only happens since 1.4.287. I'm using Arch Linux, mumble community package.

Build options: https://github.com/archlinux/svntogit-community/blob/packages/mumble/trunk/PKGBUILD#L57

hashworks commented 1 year ago

I've repeated the bug with trace, it spams this during the freeze:

 22959.037 ( 0.004 ms): mumble/160828 mmap(len: 22736, prot: READ, flags: PRIVATE, fd: 36)                  = 0x7f2dcefc6000
 22959.042 ( 0.001 ms): mumble/160828 close(fd: 36)                                                         = 0
 22959.054 ( 0.003 ms): mumble/160828 munmap(addr: 0x7f2dcefc6000, len: 22736)                              = 0
 22963.326 ( 0.005 ms): mumble/160828 openat(dfd: CWD, filename: 0x269c2c38)                                = 36
 22963.332 ( 0.001 ms): mumble/160828 fcntl(fd: 36, cmd: SETFD, arg: 0)                                     = 0
 22963.333 ( 0.001 ms): mumble/160828 newfstatat(dfd: 36, filename: 0xf20dddd5, statbuf: 0x7ffe33dc6320, flag: 4096) = 0
vimpostor commented 1 year ago

Can't reproduce this with the same version on Arch Linux. Does this happen on all servers?

hashworks commented 1 year ago

Does this happen on all servers?

I tested a random public server, same result.

It's definitely something in my configuration, when I remove ~/.config/Mumble and ~/.local/share/Mumble temporarily the bug disappears. I'll debug this a bit...

hashworks commented 1 year ago

Well, I can move the bug: When I enable "Console" for the Server connected message, the bug occurs when I connect instead of on the first message I send. Same thing for Information, which displays "Welcome to Mumble" when Mumble launches - then the bug occurs directly at launch, freezing Mumble and displaying a black window for a few seconds.

Basically: Mumble freezes on the first entry in the console window.

hashworks commented 1 year ago

Here is a video of the bug with Console enabled for the Information message: https://fb.hash.works/5RTgV/

Mumble launches normally until that point:

<D>2022-10-18 15:28:36.231 PortAudio V19.7.0-devel, revision unknown from libportaudio.so
<D>2022-10-18 15:28:36.231 PulseAudio 16.1.0 from libpulse.so
<W>2022-10-18 15:28:36.233 Theme: "Mumble"
<W>2022-10-18 15:28:36.233 Style: "Dark"
<W>2022-10-18 15:28:36.233 --> qss: ":themes/Mumble/Dark.qss"
<W>2022-10-18 15:28:36.233 Locale is "en_US" (System: "en_US")
<W>2022-10-18 15:28:36.241 Database SQLite: "3.39.4"
<W>2022-10-18 15:28:36.248 Overlay: Removing old socket on "/run/user/1000/MumbleOverlayPipe"
<W>2022-10-18 15:28:36.248 Overlay: Listening on "/run/user/1000/MumbleOverlayPipe"
<W>2022-10-18 15:28:36.256 GlobalShortcutX: Using XI2 2.4
<W>2022-10-18 15:28:36.450 QMetaObject::connectSlotsByName: No matching signal for on_qtvUsers_customContextMenuRequested(QPoint,bool)
<W>2022-10-18 15:28:36.558 SocketRPC: Removing old socket on "/run/user/1000/MumbleSocket"

After this it freezes for a while, some stuff happens in another thread:

<W>2022-10-18 15:28:45.080 AudioInput: Opus encoder set for low delay
<W>2022-10-18 15:28:45.080 AudioInput: 192000 bits/s, 48000 hz, 480 sample
<W>2022-10-18 15:28:45.082 AudioInput: Initialized mixer for 1 channel 48000 hz mic and 0 channel 48000 hz echo
<W>2022-10-18 15:28:45.082 AudioOutput: Initialized 2 channel 48000 hz mixer
<W>2022-10-18 15:28:45.104 Public list disabled
<W>2022-10-18 15:28:45.118 AudioInput: Noise canceller disabled
warning: The VAD has been replaced by a hack pending a complete rewrite

The next log messages after the freeze are:

<W>2022-10-18 15:28:54.173 Updating application palette
<W>2022-10-18 15:28:54.192 Updating application palette
hashworks commented 1 year ago

Found the culprit: I have a lot of fonts.

$ fc-list | wc -l
9924

I did another strace run - mumble simply opens every font file I have.

[...]
openat(AT_FDCWD, "/usr/share/fonts/noto/NotoSansTifinaghTawellemmet-Regular.ttf", O_RDONLY) = 23
fcntl(23, F_SETFD, FD_CLOEXEC)          = 0
newfstatat(23, "", {st_mode=S_IFREG|0644, st_size=39752, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 39752, PROT_READ, MAP_PRIVATE, 23, 0) = 0x7f2d613f6000
close(23)                               = 0
munmap(0x7f2d613f6000, 39752)           = 0
openat(AT_FDCWD, "/usr/share/fonts/noto-sans-tirhuta/NotoSansTirhuta-Regular.ttf", O_RDONLY) = 23
fcntl(23, F_SETFD, FD_CLOEXEC)          = 0
newfstatat(23, "", {st_mode=S_IFREG|0644, st_size=96864, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 96864, PROT_READ, MAP_PRIVATE, 23, 0) = 0x7f2d613e8000
close(23)                               = 0
munmap(0x7f2d613e8000, 96864)           = 0
openat(AT_FDCWD, "/usr/share/fonts/noto/NotoSansZanabazarSquare-Regular.ttf", O_RDONLY) = 23
fcntl(23, F_SETFD, FD_CLOEXEC)          = 0
newfstatat(23, "", {st_mode=S_IFREG|0644, st_size=19896, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 19896, PROT_READ, MAP_PRIVATE, 23, 0) = 0x7f2d61d60000
close(23)                               = 0
munmap(0x7f2d61d60000, 19896) 
[...]

That takes a while. It shouldn't do that.

So, to reproduce this: Install stuff like noto-fonts, noto-fonts-extra or ttf-google-fonts-git (AUR).

Krzmbrzl commented 1 year ago

Do you have other Qt application on your system that you could use to see if they suffer from the same problem? 'cause my gut tells me that we don't do any explicit font handling ourselves and therefore I would tend to suspect a Qt bug here :eyes:

vimpostor commented 1 year ago

I have installed both noto-fonts and noto-fonts-extra and now have 2660 fonts installed, but still can't reproduce it - I don't notice any delay at startup.

When I use strace -e openat, I also see only about 80 fonts being tried, not 2000.

vimpostor commented 1 year ago

@hashworks Does the problem also happen when you start mumble with the following environment variable: FONTCONFIG_FILE=/etc/fonts/

hashworks commented 1 year ago

I've tested telegram-desktop, a qt6 app, and speedcrunch, a qt5 app. No delay. Both don't really care about the amount of installed fonts and open a single TTF file at most.

$ fc-list | wc -l
450
$ strace -e openat mumble 2>&1 | grep "\.ttf" | wc -l
37
$ strace -e openat telegram-desktop 2>&1 | grep "\.ttf" | wc -l; pkill -9 telegram-deskto
0
$ strace -e openat speedcrunch 2>&1 | grep "\.ttf" | wc -l
1
$ sudo pacman -Sy noto-fonts noto-fonts-extra
$ fc-list | wc -l
2905
$ strace -e openat mumble 2>&1 | grep "\.ttf" | wc -l
479
$ strace -e openat telegram-desktop 2>&1 | grep "\.ttf" | wc -l; pkill -9 telegram-deskto
0
$ strace -e openat speedcrunch 2>&1 | grep "\.ttf" | wc -l
1
$ sudo pacman -U ttf-google-fonts-git-1:r4058.97004a80c-1-any.pkg.tar.zst ttf-merriweather-1:2.100-1-any.pkg.tar.zst ttf-merriweather-sans-1.008-3-any.pkg.tar.zst ttf-oswald-4.101-3-any.pkg.tar.zst ttf-quintessential-1.001-6-any.pkg.tar.zst ttf-signika-2.000-1-any.pkg.tar.zst
$ fc-list | wc -l
9645
$ strace -e openat mumble 2>&1 | grep "\.ttf" | wc -l
3028
$ strace -e openat telegram-desktop 2>&1 | grep "\.ttf" | wc -l; pkill -9 telegram-deskto
0
$ strace -e openat speedcrunch 2>&1 | grep "\.ttf" | wc -l
1

While measurable, it isn't really noticeable with 2905 fonts. But with 9645 it really starts to hurt. No simple linear scaling here.

@vimpostor I guess you mean FONTCONFIG_FILE=/etc/fonts/fonts.conf, if you specify a directory it finds no fonts at all.

$ FONTCONFIG_FILE=/etc/fonts/fonts.conf strace -e openat mumble 2>&1 | grep "\.ttf" | wc -l
3028

So no, this isn't something my ~/.config/fontconfig/fonts.conf is causing :)

hashworks commented 1 year ago

For testing purposes I've thrown the ttf-google-fonts-git pacman package-files in my filebin, feel free to download them since the build takes a while:

$ wget --content-disposition https://fb.hash.works/fag6xjgM/ https://fb.hash.works/plLS9QY/ https://fb.hash.works/mWFhzU3/ https://fb.hash.works/PzIiQrA/ https://fb.hash.works/kShaSUH/ https://fb.hash.works/2dR57Wz/
$ file ttf-*
ttf-google-fonts-git-1:r4058.97004a80c-1-any.pkg.tar.zst: Zstandard compressed data (v0.8+), Dictionary ID: None
ttf-merriweather-1:2.100-1-any.pkg.tar.zst:               Zstandard compressed data (v0.8+), Dictionary ID: None
ttf-merriweather-sans-1.008-3-any.pkg.tar.zst:            Zstandard compressed data (v0.8+), Dictionary ID: None
ttf-oswald-4.101-3-any.pkg.tar.zst:                       Zstandard compressed data (v0.8+), Dictionary ID: None
ttf-quintessential-1.001-6-any.pkg.tar.zst:               Zstandard compressed data (v0.8+), Dictionary ID: None
ttf-signika-2.000-1-any.pkg.tar.zst:                      Zstandard compressed data (v0.8+), Dictionary ID: None
$ sudo pacman -U ttf-google-fonts-git-1:r4058.97004a80c-1-any.pkg.tar.zst ttf-merriweather-1:2.100-1-any.pkg.tar.zst ttf-merriweather-sans-1.008-3-any.pkg.tar.zst ttf-oswald-4.101-3-any.pkg.tar.zst ttf-quintessential-1.001-6-any.pkg.tar.zst ttf-signika-2.000-1-any.pkg.tar.zst
Hartmnt commented 1 year ago

I can reproduce this with a custom 1.5 client build, on an Ubuntu system. Having 1203 fonts (mostly LaTeX related) the Mumble client takes 3 seconds to start up with the "Welcome to Mumble message" enabled. I confirmed I reproduce the issue stated here by running strace and observing the font file calls.

However, this problem fixes itself for me for undefined reasons at some point. I recompile mumble often when I work on features and re-start the client dozens of times each session. Sometimes, the problem just vanishes and stays fixed for some unknown period of time. In the future I will try to note what I did when the problem vanishes.

Edit: I already confirmed via strace that the font-calls are gone, when the problem fixes itself. I just do not know why.

sbruder commented 1 year ago

For me, this problem is fixed when using 1.5.517.

I tried bisecting it which returned 15ac2c5e65a7f3e999e75ebabf02e0223a196371 / ece450aa3d8363a9b0728e23204c6b97e727ff62 as the fix (which seems likely because it changes text handling), though in another test, those revisions still opened all fonts on startup, but that might be because of an issue at my side building them.

Krzmbrzl commented 1 year ago

Thanks for letting us know! This is certainly interesting given that the commits don't actually deal with fonts :shrug:

In any cade though, I'm glad to hear that it is fixed!

Hartmnt commented 1 year ago

I kinda doubt this was fixed because, as I said, I was experiencing the bug on the 1.5 branch in November. I think this bug triggers conditionally, with the specific conditions still unknown. But let's keep this closed until, I or someone else, can reproduce this with a recent version of Mumble.