1164518 - Page loading is long paused due to safebrowsing, and Process remains for long term after quit browser while the pause sometimes

Status: RESOLVED FIXED

(Toolkit :: Safe Browsing, defect)

Comment 1

[Boris Zbarsky [:bzbarsky]]

Alice0775, is there more info forthcoming?

Comment 2

[Alice0775 White]

This is initially reported on http://forum.mozilla.gr.jp/cbbs.cgi?mode=all&namber=58541 .

If safebrowsing is enabled(default), page loading is long paused in certain web pages[1],[2].
and Process remains for long term after quit browser while the pause sometimes.

[1] http://www.b-ch.com/  -- login needed
[2] http://tokyo-ame.jwa.or.jp/

Disabling the safebrowsing solves the problem. (Options > Security, Uncheck "Block reported attack site" and "Block reported web forgeries").

The problem does not happen on Chrome and IE.

Steps To Reproduce:
1. Clear everything(cache, cookies and so om) from "Clear Recent History"
2. Restart.
3. Open the site [1] or [2]

Actual Results:
Page loading is long paused for more than 60sec.


Expected Results:
Page loading should be completed within 10sec.

Regression window:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=d0a80ba46f6f&tochange=f3192b2f9195

Via local build
Last Good: 6810b2fa1afe
First Bad: f3192b2f9195
Regressed by: 
f3192b2f9195	Monica Chew — Bug 1029781: Set NS_LOAD_CLASSIFY_URI in image loader (r=seth)

Comment 3

[Alice0775 White]

Attachment: HTTP log

NSPR_LOG_MODULES=timestamp,nsHttp:5,nsSocketTransport:5,nsStreamPump:5,nsHostResolver:5

Comment 4

[Boris Zbarsky [:bzbarsky]]

Doug, who owns the safebrowsing stuff now?

Comment 5

[yassan]

I think these pages have the same problem.

http://www.calpis.co.jp/index.html
http://monipla.jp/

Comment 6

[gnaka]

The url tokyo-ame.jwa.or.jp/ja/images/button/ seems to match the prefix of the hash in the table goog-malware-shavar, which makes url-classifier get the full hash and update the table. Because there are many images for the page in the directory, url-classifier repeats it many times.

Comment 7

[gnaka]

Attachment: debug log

debug log for http://tokyo-ame.jwa.or.jp/
NSPR_LOG_MODULES=UrlClassifierDbService:5

Comment 8

[gnaka]

Product should be Toolkit and component should be Safe Browsing.

Comment 10

[François Marier [:francois]]

This is similar, but not actually a duplication of bug 1165816 since it's about page loads, not downloads. This is more like bug 1024555.

I can't reproduce with either site 1 or 2.

Can someone who can reproduce this bug test the following work-around:

1. go to about:config
2. set urlclassifier.gethash.timeout_ms to 1

Comment 11

[gnaka]

(In reply to François Marier [:francois] from comment #10)
> 1. go to about:config
> 2. set urlclassifier.gethash.timeout_ms to 1

The workaround worked.

Comment 12

[François Marier [:francois]]

Ok, that means we might need to change the default value of urlclassifier.gethash.timeout_ms then. It's currently at 5000ms as of bug 1024555.

The downside of reducing the timeout is that it will decrease the protection that users on slow connections get from SafeBrowsing.

I will look into how Chrome handles that.

Comment 13

[gnaka]

(In reply to François Marier [:francois] from comment #12)
> Ok, that means we might need to change the default value of
> urlclassifier.gethash.timeout_ms then. It's currently at 5000ms as of bug
> 1024555.

Although it worked, I suspect it will virtually disable the safe browsing feature. For example, with timeout_ms set to 1, http://www.66fu.com.deletethispart/pk/ (be careful, this is a phishing site) would not be warned.

Comment 14

[François Marier [:francois]]

(In reply to gnaka from comment #13)
> (In reply to François Marier [:francois] from comment #12)
> Although it worked, I suspect it will virtually disable the safe browsing
> feature. For example, with timeout_ms set to 1,
> http://www.66fu.com.deletethispart/pk/ (be careful, this is a phishing site)
> would not be warned.

Exactly, that's the difficult trade-off we're facing. If we drop it to 1ms, we're essentially turning off Safe Browsing entirely. So we should _not_ do that.

Maybe 5 seconds is too long though. Would 3-4 seconds improve the situation?

I'm surprised that connecting to https://safebrowsing.google.com/safebrowsing/gethash would be that slow. What sort of connection are you using? Mobile? ADSL? Dial-up? Are you based in Japan, China, somewhere else?

Comment 15

[Alice0775 White]

At least, Process hang should be fixed.

Comment 16

[François Marier [:francois]]

Since I haven't been able to reproduce it, can someone experiencing this problem maybe post a screencast showing what happens when loading one of these pages?

Comment 17

[gnaka]

(In reply to François Marier [:francois] from comment #16)
> Since I haven't been able to reproduce it, can someone experiencing this
> problem maybe post a screencast showing what happens when loading one of
> these pages?

https://youtu.be/emhqdAFLmzU

On the machine (Core i5 2520M) which the video was recorded on, Firefox 38.0.1 hardly reproduced. Nightly build did.
On the other hand, on a slower machine (Core 2 Duo E6600), 38.0.1 always reproduces.

Comment 18

[gnaka]

(In reply to François Marier [:francois] from comment #14)
> Maybe 5 seconds is too long though. Would 3-4 seconds improve the situation?

I have tried 3000 as timeout_ms, but the problem didn't seem to have been fixed.

> I'm surprised that connecting to
> https://safebrowsing.google.com/safebrowsing/gethash would be that slow.
> What sort of connection are you using? Mobile? ADSL? Dial-up? Are you based
> in Japan, China, somewhere else?

I'm in Japan. The RTT to safebrowsing.google.com(sb.l.google.com[216.58.220.206]) by ping.exe is 6 ms. The web developer tool of Firefox reported 60-100 ms to receive 400 request for the URL.

Comment 19

[François Marier [:francois]]

(In reply to gnaka from comment #18)
> I'm in Japan. The RTT to
> safebrowsing.google.com(sb.l.google.com[216.58.220.206]) by ping.exe is 6
> ms. The web developer tool of Firefox reported 60-100 ms to receive 400
> request for the URL.

Thanks for that gnaka. It's not as simple as adjusting the timeout then. I will need to look into how these network requests are created. Perhaps the problem is that they are all done synchronously (i.e. serially, not in parallel).

Comment 20

[EarlgreyTea]

Attachment: tokyo-ame-firefox(100ms).mp4

Comment 21

[EarlgreyTea]

Attachment: tokyo-ame-chrome.mp4

Comment 22

[EarlgreyTea]

(In reply to François Marier [:francois] from comment #16)
> Since I haven't been able to reproduce it, can someone experiencing this
> problem maybe post a screencast showing what happens when loading one of
> these pages?

I am the person who made the first report to http://forum.mozilla.gr.jp/cbbs.cgi?mode=all&namber=58541 .

Situation of site 1 (http://www.b-ch.com/) was improved. On April 29: more than 110sec. => Now: 5-10 sec.
Situation of site 2 (http://tokyo-ame.jwa.or.jp/) is still same.

tokyo-ame-chrome.mp4： Loading site 2 using Google Chrome.
tokyo-ame-firefox(100ms).mp4: Loading site 2 using Firefox 38.0.1 (urlclassifier.gethash.timeout_ms=100).

Comment 23

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)]

http://tokyo-ame.jwa.or.jp/ is one of the major websites in Japan, especially for the citizens of Tokyo.

Comment 24

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)]

francois:

The website is very important for Japanese marketing because I see a lot of people who complain about this bug. If we should contact Google Japan, we should move this bug to TechEvangelism. Otherwise, could you take a look?

Comment 25

[yassan]

(In reply to yassan from comment #5)
> http://www.calpis.co.jp/index.html
I think that the problem of this page was solved.

Comment 26

[François Marier [:francois]]

(In reply to Masayuki Nakano (:masayuki) (Mozilla Japan) from comment #24)
> francois:
> 
> The website is very important for Japanese marketing because I see a lot of
> people who complain about this bug. If we should contact Google Japan, we
> should move this bug to TechEvangelism. Otherwise, could you take a look?

I'm still struggling to reproduce this bug. I will add more debugging info to Nightly to see if we can narrow the problem down a bit that way.

In the meantime, can someone reproduce the problem with Nightly while exporting the following environment variables:

  export NSPR_LOG_MODULES="UrlClassifierDbService:5,nsChannelClassifier:5"

and then attach the log here. The log from comment 7 unfortunately doesn't have enough info.

Comment 27

[EarlgreyTea]

Attachment: debuglog2.zip

Nightly 43.0a1 (20150909030223)
NSPR_LOG_MODULES=timestamp,UrlClassifierDbService:5,nsChannelClassifier:5

tokyo-ame-e10s.log ... e10s
tokyo-ame-Non-e10s.log ... Non-e10s
tokyo-ame-en-e10s.log ... English site(http://tokyo-ame.jwa.or.jp/en/index.html)

Comment 28

[Alice0775 White]

Hmm...
I cannot reproduce the problem anymore......

I think that Google seems to have modified their server/network or something.

Comment 29

[Alice0775 White]

Attachment: log.txt

Reproduced on Nightly43.0a1(2015-09-09) win10 ( http://tokyo-ame.jwa.or.jp/ )

Comment 30

[Honza Bambas (:mayhemer)]

(In reply to Alice0775 White from comment #29)
> Created attachment 8659309 [details]
> log.txt
> 
> Reproduced on Nightly43.0a1(2015-09-09) win10 ( http://tokyo-ame.jwa.or.jp/ )

There is nothing in the log.  You will have to add nsHttp:5 to the list of modules.

Comment 31

[Alice0775 White]

Attachment: log.zip

(In reply to Honza Bambas (not reviewing) (:mayhemer) from comment #30)
> (In reply to Alice0775 White from comment #29)
> > Created attachment 8659309 [details]
> > log.txt
> > 
> > Reproduced on Nightly43.0a1(2015-09-09) win10 ( http://tokyo-ame.jwa.or.jp/ )
> 
> There is nothing in the log.  You will have to add nsHttp:5 to the list of
> modules.

attached

Comment 32

[Honza Bambas (:mayhemer)]

how exactly the symptoms look like?  I can see the top level page html loads in less then a second (from an http channel creation to full content delivery from the network layer).

I only see a one minute delay here:

	Line 118375: 2015-09-10 17:17:49.038000 UTC - 0[caa000]: Preparing to write data into the cache [uri=http://tokyo-ame.jwa.or.jp/favicon.ico]
	Line 124704: 2015-09-10 17:18:57.569000 UTC - 0[caa000]: Preparing to write data into the cache [uri=http://tokyo-ame.jwa.or.jp/scripts/jswidget/SlideController/spacer.gif]


Is this what we are hunting?

Comment 33

[Honza Bambas (:mayhemer)]

OK, this is the classifier that misbehaves:

	Line 115341: 2015-09-10 17:17:47.733000 UTC - 0[caa000]: nsHttpChannel::Starting nsChannelClassifier bb06140 [this=1152c700]
	Line 115343: 2015-09-10 17:17:47.733000 UTC - 0[caa000]: nsChannelClassifier[bb06140]: suspended channel 1152c72c
	Line 124654: 2015-09-10 17:18:57.569000 UTC - 0[caa000]: nsChannelClassifier[bb06140]:OnClassifyComplete 0 (suspended channel)
	Line 124656: 2015-09-10 17:18:57.569000 UTC - 0[caa000]: nsChannelClassifier[bb06140]: resuming channel 1152c72c from OnClassifyComplete


Unfortunatelly the log implementation for nsChannelClassifier is poor or I don't know how to get info from it.

hopefully identifying at least the classifier ptr will help.

Comment 34

[Honza Bambas (:mayhemer)]

Is this normal:


	Line 717: 2015-09-10 17:17:39.431000 UTC - 3540[13c1c600]: update took 563ms
	Line 113148: 2015-09-10 17:17:46.648000 UTC - 3540[13c1c600]: update took 2192ms
	Line 117536: 2015-09-10 17:17:48.478000 UTC - 3540[13c1c600]: update took 1830ms
	Line 118755: 2015-09-10 17:17:50.038000 UTC - 3540[13c1c600]: update took 1560ms
	Line 118851: 2015-09-10 17:17:51.600000 UTC - 3540[13c1c600]: update took 1562ms
	Line 118947: 2015-09-10 17:17:53.116000 UTC - 3540[13c1c600]: update took 1516ms
	Line 119043: 2015-09-10 17:17:54.647000 UTC - 3540[13c1c600]: update took 1531ms
	Line 119139: 2015-09-10 17:17:56.178000 UTC - 3540[13c1c600]: update took 1531ms
	Line 119349: 2015-09-10 17:17:57.725000 UTC - 3540[13c1c600]: update took 1547ms
	Line 119455: 2015-09-10 17:17:59.334000 UTC - 3540[13c1c600]: update took 1610ms
	Line 119551: 2015-09-10 17:18:00.881000 UTC - 3540[13c1c600]: update took 1547ms
	Line 119647: 2015-09-10 17:18:02.412000 UTC - 3540[13c1c600]: update took 1531ms
	Line 119746: 2015-09-10 17:18:03.897000 UTC - 3540[13c1c600]: update took 1484ms
	Line 119902: 2015-09-10 17:18:05.351000 UTC - 3540[13c1c600]: update took 1454ms
	Line 119998: 2015-09-10 17:18:06.944000 UTC - 3540[13c1c600]: update took 1593ms
	Line 120094: 2015-09-10 17:18:08.475000 UTC - 3540[13c1c600]: update took 1531ms
	Line 120190: 2015-09-10 17:18:10.178000 UTC - 3540[13c1c600]: update took 1703ms
	Line 120286: 2015-09-10 17:18:11.819000 UTC - 3540[13c1c600]: update took 1641ms
	Line 120382: 2015-09-10 17:18:13.319000 UTC - 3540[13c1c600]: update took 1500ms
	Line 120478: 2015-09-10 17:18:14.788000 UTC - 3540[13c1c600]: update took 1469ms
	Line 120574: 2015-09-10 17:18:16.287000 UTC - 3540[13c1c600]: update took 1500ms
	Line 120670: 2015-09-10 17:18:17.787000 UTC - 3540[13c1c600]: update took 1500ms
	Line 120766: 2015-09-10 17:18:19.257000 UTC - 3540[13c1c600]: update took 1469ms
	Line 120862: 2015-09-10 17:18:20.772000 UTC - 3540[13c1c600]: update took 1515ms
	Line 120958: 2015-09-10 17:18:22.288000 UTC - 3540[13c1c600]: update took 1516ms
	Line 121054: 2015-09-10 17:18:23.772000 UTC - 3540[13c1c600]: update took 1484ms
	Line 121150: 2015-09-10 17:18:25.303000 UTC - 3540[13c1c600]: update took 1531ms
	Line 121246: 2015-09-10 17:18:26.788000 UTC - 3540[13c1c600]: update took 1485ms
	Line 121342: 2015-09-10 17:18:28.319000 UTC - 3540[13c1c600]: update took 1531ms
	Line 121438: 2015-09-10 17:18:29.850000 UTC - 3540[13c1c600]: update took 1531ms
	Line 121534: 2015-09-10 17:18:31.506000 UTC - 3540[13c1c600]: update took 1657ms
	Line 121630: 2015-09-10 17:18:33.069000 UTC - 3540[13c1c600]: update took 1562ms
	Line 121905: 2015-09-10 17:18:34.709000 UTC - 3540[13c1c600]: update took 1641ms
	Line 122624: 2015-09-10 17:18:36.288000 UTC - 3540[13c1c600]: update took 1578ms
	Line 123008: 2015-09-10 17:18:37.866000 UTC - 3540[13c1c600]: update took 1578ms
	Line 123179: 2015-09-10 17:18:39.319000 UTC - 3540[13c1c600]: update took 1453ms
	Line 123295: 2015-09-10 17:18:40.850000 UTC - 3540[13c1c600]: update took 1531ms
	Line 123435: 2015-09-10 17:18:42.303000 UTC - 3540[13c1c600]: update took 1453ms
	Line 123531: 2015-09-10 17:18:43.850000 UTC - 3540[13c1c600]: update took 1547ms
	Line 123740: 2015-09-10 17:18:45.412000 UTC - 3540[13c1c600]: update took 1563ms
	Line 123836: 2015-09-10 17:18:46.944000 UTC - 3540[13c1c600]: update took 1531ms
	Line 123932: 2015-09-10 17:18:48.506000 UTC - 3540[13c1c600]: update took 1563ms
	Line 124028: 2015-09-10 17:18:49.975000 UTC - 3540[13c1c600]: update took 1469ms
	Line 124134: 2015-09-10 17:18:51.475000 UTC - 3540[13c1c600]: update took 1499ms
	Line 124230: 2015-09-10 17:18:53.006000 UTC - 3540[13c1c600]: update took 1531ms
	Line 124326: 2015-09-10 17:18:54.491000 UTC - 3540[13c1c600]: update took 1485ms
	Line 124422: 2015-09-10 17:18:55.991000 UTC - 3540[13c1c600]: update took 1500ms
	Line 124518: 2015-09-10 17:18:57.569000 UTC - 3540[13c1c600]: update took 1578ms

Comment 35

[François Marier [:francois]]

(In reply to Honza Bambas (not reviewing) (:mayhemer) from comment #33)
> Unfortunatelly the log implementation for nsChannelClassifier is poor or I
> don't know how to get info from it.

I'm working on this in bug 1203347 and should have a patch that makes the logging more useful today.

Comment 36

[EarlgreyTea]

(In reply to EarlgreyTea from comment #27)

I forgot to write the environment. 
OS: Windows 7 (Windows NT 6.1; Win64; x64) Time: 18:07-18:12 (JST)

I do not know would be helpful, but this problem seems to have started from Firefox 33.0. 
It has been reported in http://skyblues.org/arts/2828 (Japanese blog).

Comment 37

[François Marier [:francois]]

(In reply to Honza Bambas (not reviewing) (:mayhemer) from comment #34)
> Is this normal:
> 
> 	Line 717: 2015-09-10 17:17:39.431000 UTC - 3540[13c1c600]: update took 563ms
> 	Line 113148: 2015-09-10 17:17:46.648000 UTC - 3540[13c1c600]: update took
> 2192ms

CCing gcp, he might know.

Comment 38

[François Marier [:francois]]

From the logs provided by EarlgreyTea and Alice0775, I can see that one of the resources on that page hashes to 3D8D92FB which is on the goog-malware-shavar list:

2015-09-10 15:36:10.994000 UTC - 1220[12e8c800]: Probe in goog-malware-shavar: 3D8D92FB, found 1
2015-09-10 15:36:10.994000 UTC - 1220[12e8c800]: Found a result in goog-malware-shavar: Not complete. (Age: 86400s)

Unfortunately, I haven't been able to figure out what URL actually maps to that hash.

I extracted all of the fragments and all of the HTTP URIs from Alice0775's log:

  grep "Checking fragment" log.txt | cut -d' ' -f8 | sort | uniq
  grep ": uri=http://" log-full.txt | cut -d' ' -f 6 | sort | uniq

and then hashed all of the possible fragments using a script I wrote:

  https://github.com/fmarier/safebrowsing-tools/blob/master/regex-lookup.py

but 3D8D82FB is nowhere to be found.

Hopefully the extra logging I'm adding will help identify that resource.

Comment 39

[gnaka]

Attachment: safebrowsing.zip

goog-malware-shavar database files of my profile. Replace files in your safebrowsing folder of your profile by these files and it might be reproduced.

Comment 40

[François Marier [:francois]]

Could someone please re-test with today's Nightly and the following environment variables:

  export NSPR_LOG_MODULES="UrlClassifierDbService:5,nsChannelClassifier:5,nsHttp:5"

and then attach a log to this bug?

It should have more information about what the URL classifier is doing.

Comment 41

[François Marier [:francois]]

Also, please go into "about:config" and set "browser.safebrowsing.debug" to "true".

Comment 42

[EarlgreyTea]

Attachment: tokyo-ame-201509171802.log

Nightly 43.0a1 (20150916030203)
NSPR_LOG_MODULES=UrlClassifierDbService:5,nsChannelClassifier:5,nsHttp:5
browser.safebrowsing.debug: true
Time:18:02 (JST)

Comment 43

[François Marier [:francois]]

The offending resource is:

7000[1a73a900]: Checking fragment tokyo-ame.jwa.or.jp/ja/images/, hash FB928D3D9BB6B30740D5C8BD9D82B50B4CD53692752DB091B3C61C9F4AE3E031 (3D8D92FB)
7000[1a73a900]: Probe in goog-malware-shavar: 3D8D92FB, found 1

Looking at my local goog-malware-shavar DB, I do have that entry:

[goog-malware-shavar] addPrefix[chunk:177585] 3d8d92fb

I will try to reproduce the problem locally.

Comment 44

[Gian-Carlo Pascutto [:gcp]]

(In reply to François Marier [:francois] from comment #37)
> (In reply to Honza Bambas (not reviewing) (:mayhemer) from comment #34)
> > Is this normal:
> > 
> > 	Line 717: 2015-09-10 17:17:39.431000 UTC - 3540[13c1c600]: update took 563ms
> > 	Line 113148: 2015-09-10 17:17:46.648000 UTC - 3540[13c1c600]: update took
> > 2192ms
> 
> CCing gcp, he might know.

Yes, that's the time including rebuilding all the DBs and writing them out, so that's fine.

Comment 45

[Gian-Carlo Pascutto [:gcp]]

(In reply to Gian-Carlo Pascutto [:gcp] from comment #44)

> > CCing gcp, he might know.
> 
> Yes, that's the time including rebuilding all the DBs and writing them out,
> so that's fine.

	Line 717: 2015-09-10 17:17:39.431000 UTC - 3540[13c1c600]: update took 563ms
	...repeated many times...
	Line 124518: 2015-09-10 17:18:57.569000 UTC - 3540[13c1c600]: update took 1578ms


WAIT, WAIT, why are we completely rebuilding and rewriting the database 20 to 30 times in one minute?

That would certainly make things slow and time out!

Comment 46

[Honza Bambas (:mayhemer)]

(In reply to Gian-Carlo Pascutto [:gcp] from comment #45)
> WAIT, WAIT, ...

Sorry, I forgot to mention it repeats several times in the log, apparently in serial order and probably is the cause of the overall slowdown.

Comment 47

[François Marier [:francois]]

Attachment: goog-malware-shavar.*

Just attaching a SB DB which has the colliding entry in goog-malware-shavar to help with reproducing this bug.

Comment 48

[François Marier [:francois]]

Alright, I was finally able to reproduce this problem:

1. create a new profile
2. shutdown Firefox
3. put the contents of goog-malware.* from attachment 8663898 [details] into the safebrowsing cache
4. start firefox
5. wait 10 seconds for the SB updates to finish
6. open http://tokyo-ame.jwa.or.jp/

Note that the second visit to the site in the same session will not be slow, which indicates that we are caching completion misses. Also, this has nothing to do with timeouts while talking to the Google servers.

This is what's happening:

- We load http://tokyo-ame.jwa.or.jp/ and that has several images that collide with partial hash 3D8D92FB (chunk 177585).
- For each image, we start a completion and add three noise entries.
- When all four completions for that image finish, we update the goog-malware-shavar table.
- When the completions for the next image come back, we again update the table.

So we need to figure out a way to put a limit on the frequency of database updates.

Comment 49

[Gian-Carlo Pascutto [:gcp]]

>- We load http://tokyo-ame.jwa.or.jp/ and that has several images that collide with partial hash 3D8D92FB (chunk 177585).

How is this possible? Common prefix that hits the normalizations we try to match?

>- For each image, we start a completion and add three noise entries.

For the same prefix? That's a bug - there should be only one. I guess the problem is the new queries come in while the response for the original is still outstanding? IMHO we should remember which queries are outstanding and not launch new ones for the same prefix.

>So we need to figure out a way to put a limit on the frequency of database updates.

Can we short circuit the case where the updates only contain completion updates? Most of the heavy duty work is (un)compressing the PrefixSet and that could be skipped entirely.

Comment 50

[Gian-Carlo Pascutto [:gcp]]

(In reply to Gian-Carlo Pascutto [:gcp] from comment #49)
> Can we short circuit the case where the updates only contain completion
> updates? Most of the heavy duty work is (un)compressing the PrefixSet and
> that could be skipped entirely.

I looked into this and the answer is no, because completes are cached in .cache but stored in .sbtore (together with the add chunks) - and .sbtore is the expensive file to process. Even just skipping the PrefixSet rebuild didn't work, probably due to the atomic updates.

I guess we have to try to first fix, i.e. don't allow multiple outstanding queries for the same prefix.

Comment 51

[gnaka]

I've got not to be able to reproduce the issue since around yesterday or today on Firefox 41.0. Something in goog-malware-shavar server may be changed.

Comment 52

[EarlgreyTea]

Today, I also can not reproduce the issue. Loading completed in about two seconds.

Comment 54

[Loic]

From the dupe:
Another website to test with crash at exit after Firefox stays too long in the process manager.
http://www.pferdekaemper.de/

Comment 56

[François Marier [:francois]]

Attachment: MozReview Request: Bug 1164518 - Better logging of completions. r?gcp

Review commit: https://reviewboard.mozilla.org/r/37703/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/37703/

Comment 57

[François Marier [:francois]]

Attachment: MozReview Request: Bug 1164518 - Minor optimizations for Safe Browsing completions. r?gcp

- added an early exit to skip table string comparisons on a 204
- removed an unnecessary NS_WARNING on gethash errors (e.g. 503s)
- do the noise check first since it's the majority of completions

Review commit: https://reviewboard.mozilla.org/r/37705/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/37705/

Comment 58

[François Marier [:francois]]

Attachment: MozReview Request: Bug 1164518 - Avoid unnecessary DB updates when caching Safe Browsing results. r?gcp

Review commit: https://reviewboard.mozilla.org/r/37707/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/37707/

Comment 59

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8725949 [details]
MozReview Request: Bug 1164518 - Better logging of completions. r?gcp

https://reviewboard.mozilla.org/r/37703/#review34409

Comment 60

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8725950 [details]
MozReview Request: Bug 1164518 - Minor optimizations for Safe Browsing completions. r?gcp

https://reviewboard.mozilla.org/r/37705/#review34411

Comment 61

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8725951 [details]
MozReview Request: Bug 1164518 - Avoid unnecessary DB updates when caching Safe Browsing results. r?gcp

https://reviewboard.mozilla.org/r/37707/#review34413

::: toolkit/components/url-classifier/nsUrlClassifierDBService.cpp:1473
(Diff revision 1)
> +  mWorker->ClearLastResults();

This needs a lock or proxy to the worker thread. Is it required to pass some tests? It's not clear why because there is supposed to be no functional impact from this change.

Comment 62

[François Marier [:francois]]

Comment on attachment 8725951 [details]
MozReview Request: Bug 1164518 - Avoid unnecessary DB updates when caching Safe Browsing results. r?gcp

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/37707/diff/1-2/

Comment 63

[François Marier [:francois]]

https://reviewboard.mozilla.org/r/37707/#review34413

> This needs a lock or proxy to the worker thread. Is it required to pass some tests? It's not clear why because there is supposed to be no functional impact from this change.

Yeah, it's for [a test](https://dxr.mozilla.org/mozilla-central/rev/2b5237c178ea02133a777396c24dd2b713f2b8ee/toolkit/components/url-classifier/tests/unit/test_partial.js#561-599) that does something weird with multiple completers.

I added a proxy to the worker thread.

Comment 64

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8725951 [details]
MozReview Request: Bug 1164518 - Avoid unnecessary DB updates when caching Safe Browsing results. r?gcp

https://reviewboard.mozilla.org/r/37707/#review34677

::: toolkit/components/url-classifier/Entries.h:185
(Diff revision 2)
> +  bool operator!=(const AddComplete& aOther) const

nit: inconsistent bracing

::: toolkit/components/url-classifier/LookupCache.h:72
(Diff revision 2)
> +  {

nit: inconsitent bracing

Comment 65

[Gian-Carlo Pascutto [:gcp]]

Attachment: MozReview Request: Bug 1164518 - Avoid unnecessary DB updates when caching Safe Browsing results. r?gcp

Review commit: https://reviewboard.mozilla.org/r/38235/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/38235/

Comment 66

[François Marier [:francois]]

Comment on attachment 8725951 [details]
MozReview Request: Bug 1164518 - Avoid unnecessary DB updates when caching Safe Browsing results. r?gcp

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/37707/diff/2-3/

Comment 67

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/3f15dd1859d8
https://hg.mozilla.org/integration/mozilla-inbound/rev/105eec7abaf0
https://hg.mozilla.org/integration/mozilla-inbound/rev/7f5b604e1b5a

Comment 68

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/3f15dd1859d8
https://hg.mozilla.org/mozilla-central/rev/105eec7abaf0
https://hg.mozilla.org/mozilla-central/rev/7f5b604e1b5a

Comment 69

[Matt Wobensmith [:mwobensmith][:matt:]]

I tried to reproduce the original problem in some builds from January and February, pre-checkin, but wasn't able to see it. I followed the steps in comment 48, and also tried the sample URL in comment 54. 

Obviously web sites change, so that could very well be the issue here. But currently, I won't be able to verify this fix. If someone feels strongly that I do so, please provide another example.