Closed Bug 425664 Opened 17 years ago Closed 15 years ago

Location bar/ places performance issue

Categories

(Firefox :: Address Bar, defect)

Product:
Firefox
Component:
Address Bar
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: cpuidle, Unassigned)

References

Details

(Keywords: perf)

Attachments

(1 file)

filemon log
228.80 KB, text/plain
Details
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9pre) Gecko/2008032705 Minefield/3.0pre Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9pre) Gecko/2008032705 Minefield/3.0pre Experiencing long wait times when using location bar autocomplete. Attached file access log shows 10secs of activity in places.sqlite (only 15mb) when using autocomplete. Machine is dual core laption with 2gb mem. Reproducible: Always Steps to Reproduce: 1. start ff 2. enter "qui" into location bar (something that will find matches) 3. application is blocked, disk activity; see log-> 10 secs places.sqlite access Actual Results: 10s application blocked Expected Results: non-blocking ui behaviour
Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9pre) Gecko/2008032801 Minefield/3.0pre I noticed too this morning that when I typed 3 words in the locationbar with the intend to do a Google search, when I had finished typing and had hit enter the words hadn't yet appeared in the locationbar. It went to the right address however. I had changed browser.urlbar.search.chunkSize to 5000 so I tried going back to the default value and although it still takes time it *seems* to be not as bad as before.
Not sure this does anything. Is there a chance to see want going on- e.g. routing the SQL queries to console.log?
My places.sqlite is only 16,1 MB. This doesn't differ much from the 13,5 MB a few months ago..
Mine is 15.5 also not very big. I'm also seing this problem the first time I'm using the location bar only- chunkSize doesn't seem to influence it much. other experiences I've had with sqlite where very positive- I don't believe the issue is on that side. Do we have any chance to look into the processes there? Too many small queries executed? I think it would help to understand where the time is spent- on DB level or in FF?
This morning I started typing in the location bar, after some time the dropdown appeared, I clicked on an entry, and nothing happened, just the disk was rattling for 5 seconds, then suddenly the dropdown appeared or reappeared, the right address was filled in in the locationbar and then it went to the URL. I have the impression, not the prove, that this could be caused by Bug 415403. I'm not sure if Andreas and I are talking about the same issue, if not, sorry :).
Status: UNCONFIRMED → NEW
Ever confirmed: true
Flags: blocking-firefox3?
Well- bug 415403 is verified fixed but I'm still seing the location bar performance issue with currently nightly. Are you sure you've picked the right bug?
I don't know yet how to reproduce this exactly, in a new profile it is not blazingly fast but still doable. With my default profile with 16 extensions the browser reacts a lot slower so the problem is much more clear.
Andreas, did you mean to attach a log? It's probably not bug 415403 because it's just the UI doing some DOM manipulation.. nothing with sqlite. If you make a new profile and copy the places.sqlite file from the old profile to the new profile, do you still see the issue? Additionally, if you copy a new profile's places.sqlite to the profile with lots of extensions, are things slow. And yet another, when you copy the original profile's places.sqlite back to the original profile, are things still slow. (Copying might cause the file to defragment.. maybe..)
ok, here we go: 1) old profile w/ extensions - search moz -> slow (even interuppted before the z appears) - search moz -> fast - search heise -> slow --> so it depends on caching 2) new profile, no extensions, plain places - search moz -> fast - search heise -> fast 3) new profile, no extensions, old places from 1) copied in - search moz -> slow - search heise -> slow --> its not fragmentation 4) old profile, w/ extensions, plain places from 2) copied back - search moz -> fast - search heise -> fast --> its due to places filesize 5) old profile, w/ extensions, old places from 3) copied back - search moz -> slow - search heise -> slow --> its not fragmentation 6) old profile w/o extensions (safe mode) - search moz -> slow - search heise -> slow --> its not extensions At this point I'd really love to see what is going on against the database. Also my feeling is that the typeahead timeout is _really_ low as experienced in 1)
Attached file filemon log —
Shawn: Know anything about sqlite performance? See comment 0 and attachment 313365 [details]. From the log, there's 1250 reads of 4KB so almost 5MB of data. Andreas, could you generate a file access log when searching for "/". It should only search 1 chunk. So if you additionally reduce browser.urlbar.search.chunkSize, it should read fewer rows. And just a sanity check, could you execute this query either with sqlite command line app or an extension like "mozStorage Explorer" or "SQLite Manager" EXPLAIN QUERY PLAN SELECT h.url, h.title, f.url, (SELECT b.parent FROM moz_bookmarks b JOIN moz_bookmarks t ON t.id = b.parent AND t.parent != 4 WHERE b.type = 1 AND b.fk = h.id ORDER BY b.lastModified DESC LIMIT 1) parent, (SELECT b.title FROM moz_bookmarks b JOIN moz_bookmarks t ON t.id = b.parent AND t.parent != 4 WHERE b.type = 1 AND b.fk = h.id ORDER BY b.lastModified DESC LIMIT 1) bookmark, (SELECT GROUP_CONCAT(t.title, ',') FROM moz_bookmarks b JOIN moz_bookmarks t ON t.id = b.parent AND t.parent = 4 WHERE b.type = 1 AND b.fk = h.id) tag FROM moz_places h LEFT OUTER JOIN moz_favicons f ON f.id = h.favicon_id WHERE h.frecency <> 0 ORDER BY h.frecency DESC LIMIT 1000 OFFSET 0 You should see these rows: TABLE moz_places AS h WITH INDEX moz_places_frecencyindex ORDER BY TABLE moz_favicons AS f USING PRIMARY KEY TABLE moz_bookmarks AS b WITH INDEX moz_bookmarks_itemindex TABLE moz_bookmarks AS t USING PRIMARY KEY TABLE moz_bookmarks AS b WITH INDEX moz_bookmarks_itemindex TABLE moz_bookmarks AS t USING PRIMARY KEY TABLE moz_bookmarks AS b WITH INDEX moz_bookmarks_itemindex TABLE moz_bookmarks AS t USING PRIMARY KEY
frick. I wanted to see whats going on and had implemented some triggers: CREATE TABLE IF NOT EXISTS x_log_places ( x_log_id INTEGER PRIMARY KEY, id INTEGER, id_old INTEGER, url LONGVARCHAR, url_old LONGVARCHAR, title LONGVARCHAR, title_old LONGVARCHAR, rev_host LONGVARCHAR, rev_host_old LONGVARCHAR, visit_count INTEGER, visit_count_old INTEGER, hidden INTEGER, hidden_old INTEGER, typed INTEGER, typed_old INTEGER, favicon_id INTEGER, favicon_id_old INTEGER, frecency INTEGER, frecency_old INTEGER ); CREATE TRIGGER IF NOT EXISTS update_places AFTER UPDATE ON moz_places BEGIN INSERT INTO x_log_places (id, id_old, url, url_old, title, title_old, rev_host, rev_host_old, visit_count, visit_count_old, hidden, hidden_old, typed, typed_old, frecency, frecency_old, favicon_id, favicon_id_old) VALUES (new.id, old.id, new.url, old.url, new.title, old.title, new.rev_host, old.rev_host, new.visit_count, old.visit_count, new.hidden, old.hidden, new.typed, old.typed, new.frecency, old.frecency, new.favicon_id, old.favicon_id); END; CREATE TRIGGER IF NOT EXISTS insert_places AFTER INSERT ON moz_places BEGIN INSERT INTO x_log_places (id, url, title, rev_host, visit_count, hidden, typed, frecency, favicon_id) VALUES (new.id, new.url, new.title, new.rev_host, new.visit_count, new.hidden, new.typed, new.frecency, new.favicon_id); END; working, producing log, fine. Only now: problem is gone- and with it my test case as I didn't expect this. Ria- could you be sure to keep a backup of your places file for further tests?
Ria- could you possibly also try running the VACUUM statement against the sqlite db, e.g. on windows using sqlitespy?
if the OS is backlogged on file IO maybe sqlite could be the issue, or the db could be too big to fit in the cache. For what it's worth, I've started to see this laggy issue every so often too :(
Keywords: perf
Summary: [performance] Location bar/ places performance issue → Location bar/ places performance issue
Can again reproduce- not sure why I couldn't earlier: - explain plan is as you'd expected - vacuum'ing the db doesn't fix the issue
(In reply to comment #13) > I'll try when I find time. OK I found a regression range, on my computer at least it is the cause of the delay, don't know if it is the whole cause and if it has anything to do with Andreas' issue. Steps to reproduce this specific case: - I copied places.sqlite of about 17 MB to a new profile - Shut down computer and started it again - Started Firefox, waited for some time until the disk was quiet - Typed in locationbar "Elian" without the quotes and started stop watch Before the regression range it took 10 seconds before all 4 entries showed up in the autocomplete and after the regression range it took 28 seconds. Regression range for this issue is http://bonsai.mozilla.org/cvsquery.cgi?module=PhoenixTinderbox&date=explicit&mindate=1205858700&maxdate=1205864219
if that's true, could be bug 419170, before that fix we were dumping away much more history than now (by error), we were minly limiting history table to 40000 entries (if you didn't change the expiration prefs), that limit is now more relaxed and having a bigger history *could* bring to having slower queries. How many entries do you actually have in moz_historyvisits table? However the expiration should happen on idle, so shouldn't involve autocomplete during normal browsing... At least until you are not searching exactly while idle cleanup happens. > - Started Firefox, waited for some time until the disk was quiet how much time? seconds, minutes?
(In reply to comment #17) > 22227 items in the bottom pane of the History window. I waited at least until I thought the 2 feeds had loaded, so at least 20 seconds, but probably longer, about 30 seconds.
Regarding comment 16 I do not see how fetching 4 db entries should- even if going to disk- take 10 seconds (which would be the pre-bug time) even. Could we supply Ria with the DB queries relevant for his case and re-execute them using sqlite manager? I believe it would be beneficial to understand what the execution times directly against the DB are.
it would be cool knowing which queries are executed in that time mainly
Version: unspecified → Trunk
Tony: as part of the "large bookmark query" work you guys are doing, can you see if Bob can generate a large history DB as well? Various sizes could help us determine where we're seeing the performance hits, here. I would expect more people on nightlies to be yelling about this. My history includes 10k entries and I'm not seeing it. But we only fixed bug 419170 about a month ago, so theoretically I'm only seeing 30 days of history now. Blocking for now to investigate, might end up being worked around by dropping default max history to 60 days.
Flags: blocking-firefox3? → blocking-firefox3+
Keywords: qawanted
Any further ideas while ff is preparing for RC1? Tried to research lxr for moz_places but couldn't really find any hints on where its used and which queries might be executed.
It should be the query I mentioned in comment 11.. without the EXPLAIN QUERY PLAN.
(In reply to comment #16) > Before the regression range it took 10 seconds before all 4 entries showed up > in the autocomplete and after the regression range it took 28 seconds. > > Regression range for this issue is > http://bonsai.mozilla.org/cvsquery.cgi?module=PhoenixTinderbox&date=explicit&mindate=1205858700&maxdate=1205864219 How big are the places.sqlite files after running those builds and quitting? SELECT COUNT(*) FROM moz_historyvisits what does that report?
(In reply to comment #24) > It should be the query I mentioned in comment 11.. without the EXPLAIN QUERY > PLAN. > so why do you ask about moz_historyvisits? that should be problematic with many places or a big number of bookmarks. Hwv i've never been able to reproduce this :(
Running latest nightly (Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9pre) Gecko/2008041707) I believe I'm not seing the performance problem anymore. I can confirm that: - query from comment 11 executes immediately using sqlite mgr (w/o the explain) - query from comment 25 returns 43000 Will retest to confirm issue is really solved.
Just checked- could the fix be due to the sqlite upgrade from bug 429336? Mentions performence regression on outer joins?
unless you are downloading hourlies, no. That fix landed within the last few hours.
May be WFM, might be a random failure state, hard to say, but not going to block on this given reporter's comment.
Flags: wanted-firefox3+
Flags: blocking-firefox3-
Flags: blocking-firefox3+
Still an open issue, also blocking browser for 10+ secs in bad cases. Nothing reporters could do right now. I've also noticed that the first results often seem to come in right away, only then ff blocks and loads more matches- could a seconds query (from other table?) be involved as well? Please let's fix this one!
Guys- is there really no tracing functionality for the SQL queries executed available? I have SQL knowledge and would be happy to analyze if I could only get hold of some sort of debug build that logs queries and execution times. Still an issue with latest nightlies and not WFM.
we are 1 year later, and this bug does not have a clear target. Can anybody with slowness problems try current shiretoko (3.5) build and report some step or situation where this happens. Otherwise we should consider this WFM.
Whiteboard: CLOSEME 06/15
This is still an issue for me, potentially enhanced by the fact that my notebook harddisk is not the fastest one. It is not possible to provide a clear test case. Best approach imho. would be to have SQL tracing available in MOZ codebase to allow analysis of logfiles.
there is sql tracing through storage, that would not help. I'm going to mark this as dependant on bug 455555, that is probably the only solution atm.
Depends on: 455555
Whiteboard: CLOSEME 06/15
I've tested against 3.5 beta 4 and see little improvement from 10-15 seconds to 5-7 seconds of lock. Also I still have problems when entering url in location bar and press enter FF waits about 1-2 seconds before starts connecting is this related or there another bug on that?
(In reply to comment #36) > I've tested against 3.5 beta 4 and see little improvement from 10-15 seconds to > 5-7 seconds of lock. Also I still have problems when entering url in location > bar and press enter FF waits about 1-2 seconds before starts connecting is this > related or there another bug on that? Are you by chance running portable Firefox or are you maybe on a networked drive?
Everything is local and NOT portable version. I've been suffering such problems since 3.0.0 release. My machine is 4GB memory and not low end hard drive so this is not shortcoming of my hardware.
(In reply to comment #35) > there is sql tracing through storage, that would not help. I'm going to mark > this as dependant on bug 455555, that is probably the only solution atm. Marco not sure if I understood you correctly. Do you mean by fixing bug 455555, this problem could be gone too?
(In reply to comment #39) > (In reply to comment #35) > Marco not sure if I understood you correctly. Do you mean by fixing bug 455555, > this problem could be gone too? it could give back first results faster. So potentially it's possible, this bug is quite generic as "location bar is slow".
Keywords: qawanted
Haven't seen the issue in 3.6 release cycle for some time now. WFM?
This is too generic and referring to the old implementation, not really useful. if performance bugs should rise from the new implementation they should be less generic, but so far i don't see complains. Thanks.
Status: NEW → RESOLVED
Closed: 15 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: