1399879 - Remove from history when right-clicking a download in the download button list is slow to act

Status: RESOLVED FIXED

(Toolkit :: Places, defect, P1)

Description

[Clément Lefèvre]

STR:
- Download any file
- Open the download button, and go onto the file you downloaded
- Right click it and select "remove from history"
- Observe that nothing happened while it should removed the download from the list, as stated on the button.

Comment 1

[Clément Lefèvre]

It seems I was a little bit too quick to open the bug.
The button actually does its job but seems very slow to act and use up to tens of seconds to do its job.

This might be related to my slow HDD though, which is why I'll let some other people test this.

Comment 2

[Clément Lefèvre]

(Note that if this is really caused by my slow HDD, then why would that button need so much I/O on the disk?)

Comment 3

[:Gijs (he/him)]

It's not slow for me... can you get a gecko profiler profile for this being really slow ( see https://perf-html.io/ for further instructions etc.) and share it here?

Comment 4

[Clément Lefèvre]

(In reply to :Gijs from comment #3)
> It's not slow for me... can you get a gecko profiler profile for this being
> really slow ( see https://perf-html.io/ for further instructions etc.) and
> share it here?

Mmmh. I have a little problem here. I correctly have captured a profile and can reliably reproduce the problem on my usual profile. However, the website and addon state that it'll also share URLs of opened tabs and so on, which I don't really wish.

I tried to reproduce it in a new, clean profile and couldn't.

Here come two guesses:
I'm using my browser with a kind of extreme way with hundreds if not thousands of opened tabs.

Could this performance issue be caused either by:
- The high number of opened tabs in the browser?
- I guess that those informations are stored in a sqlite file. If this sqlite db is kinda old and big, can it slow it down?

Comment 5

[:Gijs (he/him)]

(In reply to Clément Lefèvre from comment #4)
> (In reply to :Gijs from comment #3)
> > It's not slow for me... can you get a gecko profiler profile for this being
> > really slow ( see https://perf-html.io/ for further instructions etc.) and
> > share it here?
> 
> Mmmh. I have a little problem here. I correctly have captured a profile and
> can reliably reproduce the problem on my usual profile. However, the website
> and addon state that it'll also share URLs of opened tabs and so on, which I
> don't really wish.
> 
> I tried to reproduce it in a new, clean profile and couldn't.
> 
> Here come two guesses:
> I'm using my browser with a kind of extreme way with hundreds if not
> thousands of opened tabs.
> 
> Could this performance issue be caused either by:
> - The high number of opened tabs in the browser?

That seems unlikely.

> - I guess that those informations are stored in a sqlite file. If this
> sqlite db is kinda old and big, can it slow it down?

This seems testable by copying your old crufty sqlite files from the old profile to the new profile. Does that reproduce the issue?

Comment 6

[Clément Lefèvre]

(In reply to :Gijs from comment #5)
> (In reply to Clément Lefèvre from comment #4)
> > (In reply to :Gijs from comment #3)
> > > It's not slow for me... can you get a gecko profiler profile for this being
> > > really slow ( see https://perf-html.io/ for further instructions etc.) and
> > > share it here?
> > 
> > Mmmh. I have a little problem here. I correctly have captured a profile and
> > can reliably reproduce the problem on my usual profile. However, the website
> > and addon state that it'll also share URLs of opened tabs and so on, which I
> > don't really wish.
> > 
> > I tried to reproduce it in a new, clean profile and couldn't.
> > 
> > Here come two guesses:
> > I'm using my browser with a kind of extreme way with hundreds if not
> > thousands of opened tabs.
> > 
> > Could this performance issue be caused either by:
> > - The high number of opened tabs in the browser?
> 
> That seems unlikely.
> 
> > - I guess that those informations are stored in a sqlite file. If this
> > sqlite db is kinda old and big, can it slow it down?
> 
> This seems testable by copying your old crufty sqlite files from the old
> profile to the new profile. Does that reproduce the issue?

After copying places.sqlite files over a new profile and reproducing issue with it even if it was less slow and sometimes even fast, it gave that perf file:
https://perfht.ml/2x4HAWz

If result isn't good enough inside, I might try to dig more into it and to close most of what's running on my computer.

Comment 7

[:Gijs (he/him)]

I don't see any UI hangs or other obvious delays here. Marco, do we need to add the sqlite thread to the list of threads that the gecko profiler profiles, maybe? What would be the thread name?

Clément: it would be helpful if you ensured you started the profiler right before removing the item, and stopped it right after. I'm assuming it takes less than 45 seconds to complete?

Comment 8

[Marco Bonardo [:mak]]

The sqlite threads are named "mozStorage#N" but it's hard to know which one is associated with places.sqlite, since each connection has its own thread.
Another alternative may be to use environment variable MOZ_LOG with mozStorage:5 and storing the log to a file (MOZ_LOG_FILE), see https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Gecko_Logging
The log may be a bit verbose (many MBs), but for any query slower than a threshold, there should be a TRACE_TIME line stating how much time that query took.

Comment 9

[Marco Bonardo [:mak]]

For better result, only one instance of Firefox (the one being tested) should be open.
I also suggest to remove MOZ_LOG once done since it can slowdown firefox.

Comment 10

[Clément Lefèvre]

So, here's another perf-html.io: https://perfht.ml/2x4WOep
I ran it just before, and opened it at most one or two seconds after button effectively disappeared (which is exactly when the download disappear).

Comment 11

[Clément Lefèvre]

Attachment: Mozstorage logs

Here are joined logs I could gather using your method, in the hope it can be useful.

Comment 12

[:Gijs (he/him)]

(In reply to Clément Lefèvre from comment #11)
> Created attachment 8908254 [details]
> Mozstorage logs
> 
> Here are joined logs I could gather using your method, in the hope it can be
> useful.

Marco, can you take a look at this and check how this should be prioritized? I assume this doesn't need to block 57 or anything like that, but I'd like to be sure.

Clément: I assume this has "always" been like this, not recently regressed (otherwise I assume you would have mentioned this) - though maybe you've noticed it more recently because of the other, unrelated changes to the downloads button?

Comment 13

[Clément Lefèvre]

(In reply to :Gijs from comment #12)
> (In reply to Clément Lefèvre from comment #11)
> > Created attachment 8908254 [details]
> > Mozstorage logs
> > 
> > Here are joined logs I could gather using your method, in the hope it can be
> > useful.
> 
> Marco, can you take a look at this and check how this should be prioritized?
> I assume this doesn't need to block 57 or anything like that, but I'd like
> to be sure.
> 
> Clément: I assume this has "always" been like this, not recently regressed
> (otherwise I assume you would have mentioned this) - though maybe you've
> noticed it more recently because of the other, unrelated changes to the
> downloads button?

Well, this is an option I just never used until then. I noticed that by pure luck while testing and taking screenshots for other bugs. I even thought at first it didn't worked at all because user gets no feedback when doing it.
So yes, that might be here for a very long time, I actually don't know at all.

In the meantime I managed to reproduce the issue on another side-computer running W7 and with a better-shaped HDD.
This one also have strong usage (~300 opened tabs) with a couple of months old profile (yourner profile than my first primary computer).
The used time to remove the download can differ depending on the profile or computer and we already saw that a clean new one don't reproduce, so this might come over the course of time in the life of a profile, but why?

Comment 14

[Mike Conley (:mconley) (:⚙️)]

These profiles don't show any jank or hanging in the default threads, but we might be waiting a long time in the MozStorage threads.

Clément, could you please make the following modification:

1. Open the Gecko Profiler Add-on panel
2. In the text box next to where it says "Threads", replace whatever is in there with just a comma, so:

,

3. Click Apply (Restart Profiler)
4. Re-gather the profile as you did before

This will give us all of the profiled threads, and not just the main threads. If there's a long delay in a MozStorage thread, perhaps it will show up.

Comment 15

[Clément Lefèvre]

Here's the new one with the coma: https://perfht.ml/2x8QnH7
I hope everything is well in the options. I did let the three checkboxes in their default state, ie. "Stack walk" and "JavaScript" checked and "Task tracer" unchecked. Buffer size to 9MB and interval to 1ms.

Comment 16

[Mike Conley (:mconley) (:⚙️)]

Thanks Clément! This looks interesting: https://perfht.ml/2xFQHyE

It's not 10 seconds or anything, but that might be because the circular buffer ran out of tape; we're spending a ton of time here in mozilla::places::HashFunction::OnFunctionCall on the MozStorage #2 thread.

Any of this useful, mak?

Comment 17

[Marco Bonardo [:mak]]

Yes, I started looking at the log yesterday, but didn't finish, there is a sql query taking 9 seconds, and it seems to spend most of the time hashing a very long data uri, I didn't post yet because I didn't finish my analysys.

That's very interesting, since it confirms my first finding. We indeed hash uris to match them to the db, and we never profile the time needed to hash a very long uri. I think we may need to change the hashing so that we crop the uri before hashing it, assuming most of the time is indeed spent hashing it and not in copying the string (9s sounds unlikely).
Unfortunately that may not be upliftable too far away, because it will require recalculating all the hashes for any uri longer than a given amount.

Comment 18

[Marco Bonardo [:mak]]

Having slow sql telemetry (bug 1367023) may have helped us avoiding this, but that's broken from a long time and no sign of progress.

Comment 19

[Marco Bonardo [:mak]]

Attachment: scratchpad.js

On my system the same query takes 20ms :\ 9s is a loooong time.

Could you please tell me some more about your system specs (CPU, HDD, RAM at least) and whether you increased history expiration limits in about:config?

Could you please also open the Scratchpad from devtools, load this js snippet, select Environment / Browser from its menu and run it?
I'd like to see the output, it should be a timing and a list of indices.

Comment 20

[Clément Lefèvre]

So, system specs for the computer I originally opened the bug from are:
OS X 10.9
CPU: i7 2775QM (from memory, late 2011 macbook pro 15" model)
Memory: 10GB 2GB from original Hynix memory + 8GB Corsair
HDD: Some 5400RPM 500GB Toshiba one, very very tired/dying
I didn't changed history expiration setting, but here's the key if needed:
places.history.expiration.transient_current_max_pages;153880
It was in bold which I understand means setting was changed. Maybe some addon work? Because I'm sure I never touched that value by hand.
Most of the addon I can remember I installed here (and I see no reason would modify this setting) were uBlock origin, uMatrix, NoScript, HTTPS everywhere. Maybe a session manager but not sure at all this profile got it and that's probably all.


I also could notice same kind of issue later on, on a Windows 7 side-computer I have.
I don't have it at hand right now, but from memory, CPU is some kind of third generation i5 CPU, it have 4GB memory and a 500GB 7200RPM HDD in a lot better shape than the mac one.
Can't give the about:config value here as I can't access this computer in the immediate days.

Comment 21

[Clément Lefèvre]

Oh, and I forgot the scratchpad result on the mac:

7.360000000335276  Scratchpad/4:13:1
["sqlite_autoindex_moz_inputhistory_1","sqlite_autoindex_moz_hosts_1","sqlite_autoindex_moz_keywords_1","sqlite_autoindex_moz_favicons_1","sqlite_autoindex_moz_anno_attributes_1","sqlite_autoindex_moz_bookmarks_deleted_1","moz_places_faviconindex","moz_places_hostindex","moz_places_visitcount","moz_places_frecencyindex","moz_places_lastvisitdateindex","moz_historyvisits_placedateindex","moz_historyvisits_fromindex","moz_historyvisits_dateindex","moz_bookmarks_itemindex","moz_bookmarks_parentindex","moz_bookmarks_itemlastmodifiedindex","moz_places_url_hashindex","moz_places_guid_uniqueindex","moz_bookmarks_guid_uniqueindex","moz_keywords_placepostdata_uniqueindex","moz_annos_placeattributeindex","moz_items_annos_itemattributeindex","moz_bookmarks_dateaddedindex"]  Scratchpad/4:21:1

Comment 22

[Clément Lefèvre]

Mmmh, sorry for the hard readability, I don't know if I could provide this in a more readable way…?

Comment 23

[Marco Bonardo [:mak]]

It's fine, I wanted to be sure you had all the indices and it looks ok.

What I still don't understand is how it's possible the original log shows this query taking 9 seconds, but here it took a few ms. There must be some interaction I'm still missing.

Comment 24

[Marco Bonardo [:mak]]

I can try to create a more efficient Try build and pass it to you to test, as far as I understood you can reproduce this bug at will, so that would help us greatly.

Comment 25

[Clément Lefèvre]

(In reply to Marco Bonardo [::mak] from comment #24)
> I can try to create a more efficient Try build and pass it to you to test,
> as far as I understood you can reproduce this bug at will, so that would
> help us greatly.

Yup, feel free to provide one build to mesure more things. Still available to test that here on through IRC for direct debugging :)

Comment 26

[Marco Bonardo [:mak]]

So, I have a try build here:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a3f02df4583346380c898fa85eba897be0e6dfe5

Ensure that you use this on a throw-away profile, since it will upgrade the places.sqlite file to a new version that is not final. Always use a backup or a copy of your good places.sqlite file.

This is the macos opt build:
https://queue.taskcluster.net/v1/task/WwLanm2bRwmPkRrFmkzcRQ/runs/0/artifacts/public/build/target.dmg

last reminder: do not overwrite your default install nor launch your default profile with this one.

Comment 27

[Clément Lefèvre]

(In reply to Marco Bonardo [::mak] from comment #26)
> So, I have a try build here:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=a3f02df4583346380c898fa85eba897be0e6dfe5
> 
> Ensure that you use this on a throw-away profile, since it will upgrade the
> places.sqlite file to a new version that is not final. Always use a backup
> or a copy of your good places.sqlite file.
> 
> This is the macos opt build:
> https://queue.taskcluster.net/v1/task/WwLanm2bRwmPkRrFmkzcRQ/runs/0/
> artifacts/public/build/target.dmg
> 
> last reminder: do not overwrite your default install nor launch your default
> profile with this one.

So, a test on the test profile I used in previous comments here with places files copied over gave the following result:
- It is instantly removed without any delay with your try build
- Just to be sure I then reopened the exact same profile with the standard Nightly build, it was once again very slow.

Then I guess we can say your hashes optimizations fixes it?

Comment 28

[Marco Bonardo [:mak]]

Awesome, thank you for the testing. We can take my patch for Firefox 58, unfortunately I don't feel confident enough to push it on 57, even if it's a quite simple idea.

Comment 29

[Marco Bonardo [:mak]]

Attachment: Bug 1399879 - The Places hash SQL function is expensive on large urls.

This patch limits the amount of chars we hash and avoids some string copies.

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

Comment 30

[Marco Bonardo [:mak]]

Release Note Request (optional, but appreciated)
[Why is this notable]: The patch partially breaks places.sqlite backwards compatibility. In particular certain URIs (either longer than 1500 chars or containing unicode chars) may not match anymore, that means some UI operations like removals or editing on bookmarks and history may break when acting on those uris. It could also affect Sync of those URIs. Upgrading again doesn't cause problems. For the most common cases this may not be a big deal, but it could cause unexpected edge-case bugs.
[Affects Firefox for Android]: No
[Suggested wording]: Firefox doesn't support downgrading its a profile to a previous. In case of downgrade it is suggested to use a new profile.
[Links (documentation, blog post, etc)]:

Comment 31

[Drew Willcoxon :adw]

Comment on attachment 8911185 [details]
Bug 1399879 - The Places hash SQL function is expensive on large urls.

https://reviewboard.mozilla.org/r/182686/#review188012

Makes sense.  I notice that HashString is overloaded to take a length, e.g.: https://dxr.mozilla.org/mozilla-central/source/mfbt/HashFunctions.h#246  I don't know whether you can pass in an arbitrary length to have HashString truncate the string, but did you look into that, instead of making your own substring?

I also wonder about the FindInReadable(":") call.  It's O(length of string) -- I think?  Since `end` is the end of the string at that point?  My string API knowledge is rusty.  If it is, we could make it O(1) by checking only the first N chars, and N would be very small.  But, I expect it wouldn't make much difference in practice since we're always hashing URLs, right?  And it wouldn't make a difference for a long data URI that I think was mentioned in an earlier comment.  Anyway, something for a follow-up if you agree.

Curious why you chose 1500.  Seems OK to me, but worth a comment probably of why you chose that ballpark, even if there's no concrete reason for 1500 in particular.

Comment 32

[Drew Willcoxon :adw]

(In reply to Drew Willcoxon :adw from comment #31)
> Makes sense.  I notice that HashString is overloaded to take a length, e.g.:
> https://dxr.mozilla.org/mozilla-central/source/mfbt/HashFunctions.h#246  I
> don't know whether you can pass in an arbitrary length to have HashString
> truncate the string, but did you look into that, instead of making your own
> substring?

I should add I'm not worried about that from a perf/memory perspective since it's a dependent substring, more from a simpler don't-reinvent-the-wheel perspective.

Comment 33

[Marco Bonardo [:mak]]

(In reply to Drew Willcoxon :adw from comment #31)
> Curious why you chose 1500.  Seems OK to me, but worth a comment probably of
> why you chose that ballpark, even if there's no concrete reason for 1500 in
> particular.

Not particularly scientific, I tried with my large profile, 1000 was giving more collisions, 2000 none, I just picked in the middle to stay on the safe side.

Comment 34

[Marco Bonardo [:mak]]

Actually, since allocations are multiples of 2 in general, I may pick something close to jemalloc allocation buckets.

Comment 35

[Marco Bonardo [:mak]]

(In reply to Drew Willcoxon :adw from comment #31)
> Makes sense.  I notice that HashString is overloaded to take a length, e.g.:
> https://dxr.mozilla.org/mozilla-central/source/mfbt/HashFunctions.h#246

Ah, that's nice, I'll use it instead of StringHead.

> I also wonder about the FindInReadable(":") call.  It's O(length of string)
> -- I think?  Since `end` is the end of the string at that point?  My string
> API knowledge is rusty.  If it is, we could make it O(1) by checking only
> the first N chars, and N would be very small.  But, I expect it wouldn't
> make much difference in practice since we're always hashing URLs, right?

yes, so far. There would be no benefit for uris.
I actually noticed there is also a FindCharInReadable, maybe it's a tiny bit more efficient too.

Comment 36

[Marco Bonardo [:mak]]

(In reply to Marco Bonardo [::mak] from comment #34)
> Actually, since allocations are multiples of 2 in general, I may pick
> something close to jemalloc allocation buckets.

This wouldn't actually matter, since the hashing functions runs a loop. so the less chars the more efficient it is. I'll check the actual limit for collisions in my profile and bump it up a bit, maybe we can go with 1200-1300.
Collisions are not extremely critical, fwiw, we already have them, so it's an expected case and the reason why most queries compare both url_hash AND url.

Comment 37

[Marco Bonardo [:mak]]

Comment on attachment 8911185 [details]
Bug 1399879 - The Places hash SQL function is expensive on large urls.

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

Comment 38

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e0005dc883ee
The Places hash SQL function is expensive on large urls. r=adw

Comment 39

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/e0005dc883ee

Comment 40

[Gerry Chang [:gchang]]

Added in Beta58 release notes.