Description of problem: Firefox now takes 4 minutes to start. When I first purchased my computer in 2017 Firefox would take one minute to start. Version-Release number of selected component (if applicable): firefox-84.0.1-2.fc33.x86_64 How reproducible: Always Steps to Reproduce: 1. Log into Fedora (graphically) 2. Start Firefox Actual results: It takes Firefox more than 4 minutes to open a window. Expected results: I expect Firefox to open its window in less than 15 seconds. Additional info: Lots of power here, but maybe Firefox can't handle lots of core or RAM: AMD Ryzen 7 1700 Eight-Core Processor 32 GB of RAM
That's very weird. I have similar setup and Firefox starts in 1-3 sec (cold start). Do you have any extensions installed? Can you try standard troubleshooting steps [1] ? Especially "Create a new profile" and "Testing Mozilla binaries". Can you attach your about:support page? Thanks. [1] https://fedoraproject.org/wiki/How_to_debug_Firefox_problems?rd=Bug_info_Firefox
Created attachment 1745039 [details] firefox about:support information
Startup time for a new profile is the same as for my default profile. The Mozilla binaries seemed to start a little faster - 2(?) minutes. While firefox is starting, the top command never shows it.
I see. There's something fundamentally wrong or you have extra slow hard drive. Please try to start Firefox on terminal as: strace -f firefox and you should see which files/sockets/kernel calls are performed and you should also see where firefox waits.
Created attachment 1745411 [details] strace -f --timestamps=time firefox 2>firefox-strace; gzip firefox-strace --timestames added to see where I was waiting. Of note are jumps at these times: 17:33:45-17:34:00-17:35:44 some 5-second waits: 17:35:44-17:35:49-17:35:54 and a big one: 17:35:54-17:37:50 I deleted everything after 17:37:50 as well as many lines with that timestamp. I have also edited my hostname.
There's the important part: [pid 17920] 17:35:54 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 17 [pid 17920] 17:35:54 getsockopt(17, SOL_SOCKET, SO_RCVBUF, [212992], [4]) = 0 [pid 17920] 17:35:54 setsockopt(17, SOL_SOCKET, SO_RCVBUF, [8388608], 4) = 0 [pid 17920] 17:35:54 getsockopt(17, SOL_SOCKET, SO_RCVBUF, [425984], [4]) = 0 [pid 17920] 17:35:54 setsockopt(17, SOL_SOCKET, SO_RCVBUFFORCE, [8388608], 4) = -1 EPERM (Operation not permitted) [pid 17920] 17:35:54 getsockopt(17, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0 [pid 17920] 17:35:54 setsockopt(17, SOL_SOCKET, SO_SNDBUF, [8388608], 4) = 0 [pid 17920] 17:35:54 getsockopt(17, SOL_SOCKET, SO_SNDBUF, [425984], [4]) = 0 [pid 17920] 17:35:54 setsockopt(17, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = -1 EPERM (Operation not permitted) [pid 17920] 17:35:54 connect(17, {sa_family=AF_UNIX, sun_path="/run/dbus/system_bus_socket"}, 30) = 0 [pid 17920] 17:35:54 getsockopt(17, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0 [pid 17920] 17:35:54 getsockopt(17, SOL_SOCKET, SO_PEERSEC, "system_u:system_r:system_dbusd_t"..., [64->48]) = 0 [pid 17920] 17:35:54 getsockopt(17, SOL_SOCKET, SO_PEERGROUPS, 0x7f12c0d22200, [256->0]) = 0 [pid 17920] 17:35:54 fstat(17, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 [pid 17920] 17:35:54 getsockopt(17, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0 [pid 17920] 17:35:54 getsockname(17, {sa_family=AF_UNIX}, [128->2]) = 0 [pid 17920] 17:35:54 sendmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0AUTH EXTERNAL\r\nDATA\r\n", iov_len=22}, {iov_base="NEGOTIATE_UNIX_FD\r\n", iov_len=19}, {iov_base="BEGI [pid 17920] 17:35:54 recvmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="DATA\r\nOK 6a96fcb37afa1bf148cbd79"..., iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_ [pid 17920] 17:35:54 sendmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/fre"..., iov_len=128}], msg_iovlen=1, msg_controllen=0, [pid 17920] 17:35:54 recvmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\f\0\0\0\377\377\377\377?\0\0\0\5\1u\0\1\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_ [pid 17920] 17:35:54 recvmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0"..., iov_len=68}], msg_iovlen=1, msg_controllen=0, msg_flags= [pid 17920] 17:35:54 sendmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\2\1 \0\0\0\2\0\0\0\242\0\0\0\1\1o\0\31\0\0\0/org/fre"..., iov_len=184}, {iov_base="\0\0\0\0\7\0\0\0gol [pid 17920] 17:35:54 recvmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\4\1\1\f\0\0\0\377\377\377\377\217\0\0\0\7\1s\0\24\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, [pid 17920] 17:35:54 recvmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="org.freedesktop.DBus\0\0\0\0\6\1s\0\7\0\0\0"..., iov_len=148}], msg_iovlen=1, msg_controllen=0, msg_flags= [pid 17920] 17:35:54 recvmsg(17, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) [pid 17920] 17:35:54 ppoll([{fd=17, events=POLLIN}], 1, {tv_sec=119, tv_nsec=999835000}, NULL, 8) = 1 ([{fd=17, revents=POLLIN}], left {tv_sec=4, tv_nsec=726632179}) [pid 17920] 17:37:50 recvmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1@\0\0\0\214R\0\0005\0\0\0\5\1u\0\2\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags= [pid 17920] 17:37:50 recvmsg(17, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\1s\0\7\0\0\0:1.5172\0\10\1g\0\ta(iiay)st\0\0"..., iov_len=112}], msg_iovlen=1, msg_controllen=0, msg_fl [pid 17920] 17:37:50 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 [pid 17920] 17:37:50 close(17) = 0 This one may be related: https://bugzilla.redhat.com/show_bug.cgi?id=1271394 Looks like DBus issue. Do you see a similar problem with any other application or is Firefox the only one?
Starting Firefox is the only situation where I've noticed a problem. Current dbus version = dbus-1.12.20-2.fc33.x86_64 Looking at the bottom of bug 1271394, I saw the comment about removing fprintd, fprintd-pam and libfprint. Removing these packages didn't help.
Okay. Moving to DBus to get DBus people to CC. I'm not sure how it's possible the DBus communication takes so long.
Do you have dbus-broker or dbus-daemon running on your system? Could you attach the journal output for the one you have (the --user journal, not the system one)?
systemctl shows dbus-broker running. Can you give me more details on how to create the journal you want? Meanwhile, I've discovered that if I pkill firefox after my first attempt to start it, it will start immediately on the second attempt.
I confirm this issue with Mozilla binary and a new profile, and fedora package and a new profile. I have a nvme SSD and 16G memory, and the startup is about 4 seconds (fedora packages run a bit slower). This is still pretty slow, because previously it should start within 1-2 seconds.
I have the same issue with firefox-87.0-7.fc34.x86_64 on Fedora 34 Silverblue. Also for me it takes 4 minutes until Firefox starts. My dbus version is dbus-1.12.20-3.fc34.x86_64. After I start Firefox the process list looks like this: [fansari@bat ~]$ ps -ef | grep -i firefox | grep -v grep fansari 8191 2763 0 13:00 ? 00:00:00 /usr/lib64/firefox/firefox fansari 8200 2466 0 13:00 ? 00:00:00 /usr/libexec/cgroupify app-gnome-firefox-8191.scope fansari 8221 8191 0 13:00 ? 00:00:00 [firefox] <defunct> After Firefox had finally started it looks like this: [fansari@bat ~]$ ps -ef | grep -i firefox | grep -v grep fansari 8191 2763 1 13:00 ? 00:00:04 /usr/lib64/firefox/firefox fansari 8200 2466 0 13:00 ? 00:00:00 /usr/libexec/cgroupify app-gnome-firefox-8191.scope fansari 8465 8191 28 13:04 ? 00:00:01 /usr/lib64/firefox/firefox -contentproc -childID 1 -isForBrowser -prefsLen 1 -prefMapSize 247477 -parentBuildID 20210331181906 -appdir /usr/lib64/firefox/browser 8191 tab fansari 8535 8191 53 13:04 ? 00:00:02 /usr/lib64/firefox/firefox -contentproc -childID 2 -isForBrowser -prefsLen 6160 -prefMapSize 247477 -parentBuildID 20210331181906 -appdir /usr/lib64/firefox/browser 8191 tab fansari 8583 8191 19 13:04 ? 00:00:00 /usr/lib64/firefox/firefox -contentproc -childID 3 -isForBrowser -prefsLen 6955 -prefMapSize 247477 -parentBuildID 20210331181906 -appdir /usr/lib64/firefox/browser 8191 tab fansari 8675 8191 14 13:04 ? 00:00:00 /usr/lib64/firefox/firefox -contentproc -childID 4 -isForBrowser -prefsLen 9085 -prefMapSize 247477 -parentBuildID 20210331181906 -appdir /usr/lib64/firefox/browser 8191 tab I have also tested the flatpak version of Firefox. This also starts not very fast but much faster than the rpm version. It takes about 30s.
I took the strace myself and found the issue: systems-resolved was hanging for some reason. [pid 5648] 13:30:57 connect(7, {sa_family=AF_UNIX, sun_path="/run/systemd/resolve/io.systemd.Resolve"}, 42 <unfinished ...> After this was fixed Firefox opened immediately.
This message is a reminder that Fedora 33 is nearing its end of life. Fedora will stop maintaining and issuing updates for Fedora 33 on 2021-11-30. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a Fedora 'version' of '33'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 33 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
This problem continues in Fedora 35, dbus-1.12.20-5.fc35.x86_64. I'm still waiting for more explicit instructions for getting the --user journal information requested in comment 9.
(In reply to Tom Gundersen from comment #9) > Do you have dbus-broker or dbus-daemon running on your system? Could you > attach the journal output for the one you have (the --user journal, not the > system one)? journalctl -b --user (In reply to Frank Ansari from comment #13) > I took the strace myself and found the issue: systems-resolved was hanging > for some reason. > > [pid 5648] 13:30:57 connect(7, {sa_family=AF_UNIX, > sun_path="/run/systemd/resolve/io.systemd.Resolve"}, 42 <unfinished ...> > > After this was fixed Firefox opened immediately. What process is this strace from? Please attach the full strace. > Created attachment 1745411 [details] [pid 17920] 17:35:44 openat(AT_FDCWD, "/lib64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = 13 [pid 17920] 17:35:44 read(13, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P#\0\0\0\0\0\0"..., 832) = 832 [pid 17920] 17:35:44 fstat(13, {st_mode=S_IFREG|0755, st_size=39696, ...}) = 0 [pid 17920] 17:35:44 mmap(NULL, 32776, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 13, 0) = 0x7f12c110e000 [pid 17920] 17:35:44 mmap(0x7f12c1110000, 16384, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 13, 0x2000) = 0x7f12c1110000 [pid 17920] 17:35:44 mmap(0x7f12c1114000, 4096, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 13, 0x6000) = 0x7f12c1114000 [pid 17920] 17:35:44 mmap(0x7f12c1115000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 13, 0x6000) = 0x7f12c1115000 [pid 17920] 17:35:44 mmap(0x7f12c1116000, 8, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f12c1116000 [pid 17920] 17:35:44 close(13) = 0 [pid 17920] 17:35:44 mprotect(0x7f12c1115000, 4096, PROT_READ) = 0 [pid 17920] 17:35:44 munmap(0x7f12c2176000, 89794) = 0 [pid 17920] 17:35:44 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 13 [pid 17920] 17:35:44 setsockopt(13, SOL_IP, IP_RECVERR, [1], 4) = 0 [pid 17920] 17:35:44 connect(13, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0 [pid 17920] 17:35:44 poll([{fd=13, events=POLLOUT}], 1, 0) = 1 ([{fd=13, revents=POLLOUT}]) [pid 17920] 17:35:44 sendto(13, "\17\353\1 \0\1\0\0\0\0\0\1\7goliath\nhomerouter\3"..., 51, MSG_NOSIGNAL, NULL, 0) = 51 [pid 17920] 17:35:44 poll([{fd=13, events=POLLIN}], 1, 5000) = 0 (Timeout) [pid 17920] 17:35:49 poll([{fd=13, events=POLLOUT}], 1, 0) = 1 ([{fd=13, revents=POLLOUT}]) [pid 17920] 17:35:49 sendto(13, "\17\353\1 \0\1\0\0\0\0\0\1\7goliath\nhomerouter\3"..., 51, MSG_NOSIGNAL, NULL, 0) = 51 [pid 17920] 17:35:49 poll([{fd=13, events=POLLIN}], 1, 5000) = 0 (Timeout) [pid 17920] 17:35:54 close(13) = 0 [pid 17920] 17:35:54 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 13 [pid 17920] 17:35:54 setsockopt(13, SOL_IP, IP_RECVERR, [1], 4) = 0 [pid 17920] 17:35:54 connect(13, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0 [pid 17920] 17:35:54 poll([{fd=13, events=POLLOUT}], 1, 0) = 1 ([{fd=13, revents=POLLOUT}]) [pid 17920] 17:35:54 sendto(13, "\204N\1 \0\1\0\0\0\0\0\1\7goliath\0\0\1\0\1\0\0)\4\260\0\0"..., 36, MSG_NOSIGNAL, NULL, 0) = 36 [pid 17920] 17:35:54 poll([{fd=13, events=POLLIN}], 1, 5000) = 1 ([{fd=13, revents=POLLIN}]) [pid 17920] 17:35:54 ioctl(13, FIONREAD, [68]) = 0 [pid 17920] 17:35:54 recvfrom(13, "\204N\201\200\0\1\0\2\0\0\0\1\7goliath\0\0\1\0\1\300\f\0\1\0\1\0"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, [28->16]) = 68 [pid 17920] 17:35:54 close(13) = 0 [pid 17920] 17:35:54 getpid() = 17920 [pid 17920] 17:35:54 symlink("192.168.1.7:+17920", "/tmp/firefox/lock") = 0 Firefox here is spending 10 s resolving some hostname (goliath.homerouter.…) and blocking on that. It then queries just goliath, and that is resolved immediately. So I think those delays are related to DNS, and there's a search domain set? Someone who can reproduce this, please attach the output from: 1. resolvectl 2. grep -v '^#' /etc/nsswitch.conf 3. systemctl status systemd-resolved 4. cat /etc/resolv.conf
[fred@goliath ~]$ resolvectl Global Protocols: LLMNR=resolve -mDNS -DNSOverTLS DNSSEC=no/unsupported resolv.conf mode: foreign Current DNS Server: 192.168.1.1 DNS Servers: 192.168.1.1 DNS Domain: homerouter.cpe salumetsnew.ee Link 2 (enp6s0) Current Scopes: none Protocols: -DefaultRoute +LLMNR -mDNS -DNSOverTLS DNSSEC=no/unsupported Link 3 (wlp7s0) Current Scopes: DNS LLMNR/IPv4 LLMNR/IPv6 Protocols: +DefaultRoute +LLMNR -mDNS -DNSOverTLS DNSSEC=no/unsupported Current DNS Server: 192.168.1.1 DNS Servers: 192.168.1.1 fe80::8ace:faff:fecf:2abf%32763 DNS Domain: homerouter.cpe Link 4 (virbr0) Current Scopes: none Protocols: -DefaultRoute +LLMNR -mDNS -DNSOverTLS DNSSEC=no/unsupported ------------------------------ [fred@goliath ~]$ grep -v "^#" /etc/nsswitch.conf passwd: sss files systemd group: sss files systemd netgroup: sss files automount: sss files services: sss files shadow: files sss hosts: files myhostname mdns4_minimal [NOTFOUND=return] resolve [!UNAVAIL=return] dns bootparams: files ethers: files netmasks: files networks: files protocols: files rpc: files publickey: files aliases: files ------------------------------ [fred@goliath ~]$ sudo systemctl status systemd-resolved ● systemd-resolved.service - Network Name Resolution Loaded: loaded (/usr/lib/systemd/system/systemd-resolved.service; enabled; vendor preset: enabled) Active: active (running) since Sat 2021-11-06 14:26:07 EET; 13min ago Docs: man:systemd-resolved.service(8) man:org.freedesktop.resolve1(5) https://www.freedesktop.org/wiki/Software/systemd/writing-network-configuration-managers https://www.freedesktop.org/wiki/Software/systemd/writing-resolver-clients Main PID: 1022 (systemd-resolve) Status: "Processing requests..." Tasks: 1 (limit: 38379) Memory: 13.3M CPU: 310ms CGroup: /system.slice/systemd-resolved.service └─1022 /usr/lib/systemd/systemd-resolved Nov 06 14:26:11 goliath.salumetsnew.ee systemd-resolved[1022]: wlp7s0: Bus client set DNS server list to: 192.168.1.1 Nov 06 14:26:13 goliath.salumetsnew.ee systemd-resolved[1022]: wlp7s0: Bus client set DNS server list to: 192.168.1.1, fe80::8ace:faff:fecf:2abf Nov 06 14:27:38 goliath.salumetsnew.ee systemd-resolved[1022]: Using degraded feature set UDP instead of UDP+EDNS0 for DNS server fe80::8ace:faff:fecf:2abf%3. Nov 06 14:27:38 goliath.salumetsnew.ee systemd-resolved[1022]: Using degraded feature set UDP instead of UDP+EDNS0 for DNS server fe80::8ace:faff:fecf:2abf%3. Nov 06 14:28:10 goliath.salumetsnew.ee systemd-resolved[1022]: Using degraded feature set TCP instead of UDP for DNS server fe80::8ace:faff:fecf:2abf%3. Nov 06 14:28:10 goliath.salumetsnew.ee systemd-resolved[1022]: Using degraded feature set TCP instead of UDP for DNS server fe80::8ace:faff:fecf:2abf%3. Nov 06 14:28:26 goliath.salumetsnew.ee systemd-resolved[1022]: Using degraded feature set UDP instead of TCP for DNS server fe80::8ace:faff:fecf:2abf%3. Nov 06 14:28:26 goliath.salumetsnew.ee systemd-resolved[1022]: Using degraded feature set UDP instead of TCP for DNS server fe80::8ace:faff:fecf:2abf%3. Nov 06 14:30:13 goliath.salumetsnew.ee systemd-resolved[1022]: Using degraded feature set UDP instead of UDP+EDNS0 for DNS server 192.168.1.1. Nov 06 14:30:13 goliath.salumetsnew.ee systemd-resolved[1022]: Using degraded feature set UDP instead of UDP+EDNS0 for DNS server 192.168.1.1. ------------------------------ [fred@goliath ~]$ cat /etc/resolv.conf # Generated by NetworkManager search homerouter.cpe salumetsnew.ee nameserver 192.168.1.1 nameserver fe80::8ace:faff:fecf:2abf%wlp7s0
Created attachment 1840439 [details] journalctl -b --user > user-journal-2021-11-06a.txt Made after firefox finished starting.
Resolved by adding the hostname to /etc/hosts
Comment on attachment 1840439 [details] journalctl -b --user > user-journal-2021-11-06a.txt I don't see anything interesting in the --user journal.
(In reply to Fred New from comment #20) > Resolved by adding the hostname to /etc/hosts That is a valid workaround, though it doesn't fix the original problem really. OK, so you have a search domain set, by NetworkManager: > cat /etc/resolv.conf > # Generated by NetworkManager > search homerouter.cpe salumetsnew.ee > nameserver 192.168.1.1 > nameserver fe80::8ace:faff:fecf:2abf%wlp7s0 ... and the default nsswitch.conf contents with resolve and dns: > hosts: files myhostname mdns4_minimal [NOTFOUND=return] resolve [!UNAVAIL=return] dns Based on the strace in comment #17 and the snippets above, it seems that firefox tries to resolve goliath.homerouter.cpe and goliath.salumetsnew.ee, and for some reason that times out instead of immediately returning an error. The interesting thing is that it's nss_dns that's doing that, not nss_resolve. I think it would be useful to diagnose this without firefox being involved.
If you would like to continue diagnosing this problem, I'm willing to keep going. Re-open this bug?