1296836 - Start-up speed slow caused by local network (wireless router)

Status: NEW

(Toolkit :: Startup and Profile System, defect, P3)

Description

[Guo Yunhe]

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

Steps to reproduce:

I have bought a new wireless router (ZyXEL NBG-418N v2) and use WiFi to connect to the internect.




Actual results:

When I am using this network, Firefox takes 15 ~ 20 seconds to start. But on other network or disconnected (offline), it only takes 2 ~ 3 seconds.

On this network, other browsers like Chrome, are not affected.

Tor Broswer, which is build on Firefox 45.x, is not affected either.


Expected results:

I expect Firefox have the same start speed compared with other network. Network should not affect application start.

Comment 1

[Tooru Fujisawa [:arai]]

Does the issue happen with safe mode and clean profile?

Comment 2

[Guo Yunhe]

Yes, it happen with safe mode and reset firefox and a totally new profile.

Comment 3

[Tooru Fujisawa [:arai]]

If you're using distribution package of Firefox, can you try Mozilla's build instead?
If the issue still happens, can you check what kind of network access/connection is done from Firefox process?

Comment 4

[Tooru Fujisawa [:arai]]

Also, can you check if the issue happens on older versions of Firefox?
If the issue doesn't happen on older versions, you could find out what change introduced the issue by mozregression.
http://mozilla.github.io/mozregression/

Comment 5

[Guo Yunhe]

Mozilla build 48.0: Yes.

Old versions:

47.0: Yes.

46.0: Yes.

45.0: Yes.

Do not know how to check network access/connection. Can you give me some instruction?

Comment 6

[Guo Yunhe]

Here is the firefox performance report when I restart Firefox 51 Nightly, which takes about 20 seconds.

https://cleopatra.io/#report=aff9f82acdd25c7a7345a6a1706e88da32a60e85&selection=0,1,2,3,2,4,4,5,6,2,7,8,2,9,2,10,11,12,13,2,4,1662,1663,2,1675,1676,1679,1680,1706,2,3,2,4,4,5,6,2,1994,1995,2,2290,25,26,2,2296,2,22,24,25,26,2

But probably it doesn't contain useful information.

Comment 7

[Tooru Fujisawa [:arai]]

you could use Wireshark, to monitor network access.

https://www.wireshark.org/

it might be available as a package.

Comment 8

[Guo Yunhe]

Attachment: Wireshark capture file

Comment 9

[Guo Yunhe]

Attachment: Wireshark screenshot

Comment 10

[Guo Yunhe]

In the wireshark results, here are several host names:

linux-onr7.site - My computer, the host name is automatically generated when I install operating system.

zyxel.com - ZyXEL is the brand of my wireless router.

Look like Firefox tried to connect all the following DNS:

----------------------------

linux-onr7.site.site

www.gstatic.com

www.gstatic.com (AAAA)

linux-onr7.site

linux-onr7.site.zyxel.com

linux-onr7.zyxel.com

linux-onr7.site.site

linux-onr7.site

linux-onr7.zyxel.com

----------------------------

Every request takes 1-2 seconds. But these hosts, except gstatic.com, are not existing.

Comment 11

[Dylan Hardison [:dylan] (he/him)]

The content of attachment 8784064 [details] has been deleted for the following reason:

Sensitive data

Comment 12

[Tooru Fujisawa [:arai]]

thanks dylan :)

sorry, I should've mentioned it at first.
network capture may contain private information, so please do not upload the raw capture.

(In reply to Guo Yunhe from comment #10)
> Look like Firefox tried to connect all the following DNS:
> Every request takes 1-2 seconds. But these hosts, except gstatic.com, are
> not existing.

thanks.
moving to Networking: DNS, for now.

Comment 13

[Dragana Damjanovic [:dragana]]

Can you make a http log:
https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging

you can also sent it directly to me per e-mail.

Comment 14

[Guo Yunhe]

I did it before but after Firefox start up it is still empty. So I think HTTP log doesn't give useful information.

Comment 15

[Honza Bambas (:mayhemer)]

Tentatively assigning this unconfirmed to Dragana, feel free to bounce or reassign.

Comment 16

[Dragana Damjanovic [:dragana]]

(In reply to Guo Yunhe from comment #14)
> I did it before but after Firefox start up it is still empty. So I think
> HTTP log doesn't give useful information.

export MOZ_LOG=timestamp,nsHttp:5,nsSocketTransport:5,nsStreamPump:5,nsHostResolver:5
export MOZ_LOG_FILE=/tmp/log.txt
cd /path/to/firefox
./firefox

thanks!

Comment 17

[Guo Yunhe]

I did what you told me to do again:

> export MOZ_LOG=timestamp,nsHttp:5,nsSocketTransport:5,nsStreamPump:5,nsHostResolver:5
> export MOZ_LOG_FILE=/tmp/log.txt
> cd /path/to/firefox
> ./firefox

But the /tmp/log.txt is empty.

Comment 18

[Honza Bambas (:mayhemer)]

Gue, please use NSPR_LOG_MODULES instead of MOZ_LOG and NSPR_LOG_FILE instead of MOZ_LOG_FILE.

Comment 19

[Honza Bambas (:mayhemer)]

Sorry.. Guo! :)

Comment 20

[Dragana Damjanovic [:dragana]]

I got a log from him.

He was saying that NSPR_LOG_MODULES(from https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging) does not work, so I asked him to try with MOZ_LOG.

I do not know which one worked in the end.

Comment 21

[Guo Yunhe]

Both MOZ_LOG_MODULES and MOZ_LOG works on Mozilla build Firefox 51.0 Nightly. I send you the log of MOZ_LOG. I also have a log of MOZ_LOG_MODULES if you need it.

Comment 22

[Dragana Damjanovic [:dragana]]

I will need more help here.
From the log I do not see anything strange.

dns resolution for hosts linux-onr7... are not coming from firefox. They are not in the log, I would see them in the log.

Looking at the log, the networking part of firefox is working just normal. The log starts at 2016-08-24 09:41:34.477083 UTC and 1s later there is data from network coming.

So can you please explain what is going on. When you start firefox you do not see anything for around 20s? or it starts but it does not render any page?

I am trying to figure out where is the delay. Thanks.

Comment 23

[Guo Yunhe]

When I start Firefox, in the first 15 ~ 20 seconds, here is nothing I can see. No window, no dialog, no warning. After 15~20 seconds, the window appears and loads web pages.

Comment 24

[Dragana Damjanovic [:dragana]]

(In reply to Guo Yunhe from comment #23)
> When I start Firefox, in the first 15 ~ 20 seconds, here is nothing I can
> see. No window, no dialog, no warning. After 15~20 seconds, the window
> appears and loads web pages.

Thanks! I will changed the status to untriaged so that other people are notified and we can find a proper place for the bug.

So this is not a networking bug, and from log I see that socketThread is started only after this delay.

Comment 25

[Guo Yunhe]

Another interesting finding: NetBeans IDE has the same delay of 15 ~ 20 seconds.

Maybe NetBeans has something same with Mozilla applications?

Comment 26

[Tooru Fujisawa [:arai]]

Are you using anti-virus or some security related software?
If so, can you try disabling it to see if it's related to the delay?

Comment 27

[Guo Yunhe]

I am using SuSEfirewall2. When I disabled it, I still have the delay.

I do not have other security software.

Comment 28

[Tooru Fujisawa [:arai]]

thanks.

Is firefox process taking much CPU while the delay?

Comment 29

[Guo Yunhe]

No. Firefox just use 0% CPU and 8 MB RAM and no disk IO.

Comment 30

[Guo Yunhe]

I removed my delay by doing following steps:

1. Modify "/etc/hostname"
------------------------------
guo-kudo
------------------------------


2. Modify "/etc/hosts"
------------------------------
127.0.0.1    localhost guo-kudo guo-kudo.guoyunhe.me
------------------------------

3. Restart computer.

Now Firefox starts in 2 ~ 3 seconds, the same with Thunderbird and NetBeans.

Before:

$ hostname -f
Timeout and cannot find

After:

$ hostname -f
localhost

So I think this problem is related to hostname/FQDN lookup.

Comment 31

[Tooru Fujisawa [:arai]]

so far I see only one call for gethostbyname with hostname here, on main thread, before opening window

https://dxr.mozilla.org/mozilla-release/rev/440936afbdbcc443de50100956a446f7702f118d/toolkit/profile/nsProfileLock.cpp#346-355
>     char hostname[256];
>     PRStatus status = PR_GetSystemInfo(PR_SI_HOSTNAME, hostname, sizeof hostname);
>     if (status == PR_SUCCESS)
>     {
>         char netdbbuf[PR_NETDB_BUF_SIZE];
>         PRHostEnt hostent;
>         status = PR_GetHostByName(hostname, netdbbuf, sizeof netdbbuf, &hostent);
>         if (status == PR_SUCCESS)
>             memcpy(&inaddr, hostent.h_addr, sizeof inaddr);
>     }

here's backtrace:
#0  __gethostbyname_r (name=0x7fffffffcd10, resbuf=0x7fffffffc770, buffer=0x7fffffffc790, buflen=1024, 
    result=0x7fffffffc760, h_errnop=0x7fffffffc75c) at ../nss/getXXbyYY_r.c:150
#1  0x00007ffff66d7db4 in PR_GetHostByName () from /usr/firefox/nightly/libnspr4.so
#2  0x00007fffeb21cd6d in nsProfileLock::LockWithSymlink(nsIFile*, bool) () from /usr/firefox/nightly/libxul.so
#3  0x00007fffeb21d32c in nsProfileLock::Lock(nsIFile*, nsIProfileUnlocker**) () from /usr/firefox/nightly/libxul.so
#4  0x00007fffeb21d586 in nsToolkitProfileLock::Init(nsIFile*, nsIFile*, nsIProfileUnlocker**) ()
   from /usr/firefox/nightly/libxul.so
#5  0x00007fffeb21d970 in nsToolkitProfileLock::Init(nsToolkitProfile*, nsIProfileUnlocker**) ()
   from /usr/firefox/nightly/libxul.so
#6  0x00007fffeb21da0e in nsToolkitProfile::Lock(nsIProfileUnlocker**, nsIProfileLock**) ()
   from /usr/firefox/nightly/libxul.so
#7  0x00007fffeb223f5e in XREMain::XRE_mainStartup(bool*) () from /usr/firefox/nightly/libxul.so
#8  0x00007fffeb2252bd in XREMain::XRE_main(int, char**, nsXREAppData const*) () from /usr/firefox/nightly/libxul.so
#9  0x00007fffeb2255e5 in XRE_main () from /usr/firefox/nightly/libxul.so
#10 0x000000000040fdf1 in do_main(int, char**, char**, nsIFile*) ()
#11 0x000000000040c11a in main ()

Comment 32

[Tooru Fujisawa [:arai]]

actually gethostbyname_r

Comment 33

[Dragana Damjanovic [:dragana]]

this is interesting. We can probably fix it. It is not good idea to do gethostbyname on the main thread.

Is toolkit the right place for this bug?

Comment 34

[Tooru Fujisawa [:arai]]

some bugs in "Toolkit -  Startup and Profile System" touched the file.
moving there.
(original code was from "Core Graveyard - Profile: BackEnd")

Comment 36

[Benjamin Smedberg]

This is the right component. I don't know what to do about it: I need a posix expert. It seems that currently the profile lock symlink is keyed off the IP address of the host, which is what this delicate dance is supposed to accomplish. We don't actually use the IP address: we just use it as a kind of unique key to determine if the lock/PID is from this machine or a different one.

I'm wondering if we could instead use uname.nodename or something similar. I don't know what the consequences of that might be for cross-version compatibility.

It's also a little strange: this codepath should only be hit if the normal locking method (using LockWithFcntl) fails. Is your profile mounted on a filesystem (NFS?) that doesn't support fcntl/flock?

Comment 37

[Guo Yunhe]

I have two parts: system root uses Btrfs, user directory (home) uses XFS. Profile is in a XFS part.

Comment 38

[bull500]

Not sure if this helps but sometimes i get this message when pages fail to load and instead of displaying the "Server not found":   

XML Parsing Error: unexpected parser state Location: jar:file:///home/adheeth/firefoxN/browser/omni.ja!/chrome/browser/content/browser/aboutNetError.xhtml Line Number 536, Column 68:
        <div id="ed_connectionFailure">&connectionFailure.longDesc;</div>
-------------------------------------------------------------------^

Comment 39

[Guo Yunhe]

What can we do to move forward? I can still reproduce this issue in Firefox 72 on openSUSE Tumbleweed.

Comment 40

[Celeste Liu [:Coelacanthus]]

(In reply to Tooru Fujisawa [:arai] from comment #31)

so far I see only one call for gethostbyname with hostname here, on main
thread, before opening window

https://dxr.mozilla.org/mozilla-release/rev/
440936afbdbcc443de50100956a446f7702f118d/toolkit/profile/nsProfileLock.
cpp#346-355

char hostname[256];
PRStatus status = PR_GetSystemInfo(PR_SI_HOSTNAME, hostname, sizeof hostname);
if (status == PR_SUCCESS)
{
    char netdbbuf[PR_NETDB_BUF_SIZE];
    PRHostEnt hostent;
    status = PR_GetHostByName(hostname, netdbbuf, sizeof netdbbuf, &hostent);
    if (status == PR_SUCCESS)
        memcpy(&inaddr, hostent.h_addr, sizeof inaddr);
}

The problem still exists in latest Firefox.
And this code is still here.
https://searchfox.org/mozilla-central/rev/f8904f7f9bade1ea9df219e3208b07dd9473792d/toolkit/profile/nsProfileLock.cpp#320-332

I have a question: since we use IP address at the end, why we prefer hostname to localhost to resolve the IP address?

(In reply to Benjamin Smedberg from comment #36)

It's also a little strange: this codepath should only be hit if the normal
locking method (using LockWithFcntl) fails. Is your profile mounted on a
filesystem (NFS?) that doesn't support fcntl/flock?

I don't check the code 8 years ago. But in current code, LockWithSymlock() will also be executed if LockWithFcntl() succeed. Because there may be a symlink style lock although the Firefox acquire a fcntl lock successfully.

https://searchfox.org/mozilla-central/rev/f8904f7f9bade1ea9df219e3208b07dd9473792d/toolkit/profile/nsProfileLock.cpp#475-498