Closed Bug 1485480 Opened 6 years ago Closed 2 years ago

Frecency recalculation query in bookmarks mirror takes over 6 seconds

Categories

(Toolkit :: Places, defect, P5)

Product:
Toolkit
Component:
Places
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: lina, Unassigned)

References

(Blocks 1 open bug)

Details

From bug 1472963, comment 23: > This time telemetry shows this SQL statement: > UPDATE moz_places SET frecency = CALCULATE_FRECENCY(id) WHERE id IN ( SELECT id FROM moz_places WHERE frecency < 0 ORDER BY frecency ASC LIMIT :limit ) /* places.sqlite */ > > It easily takes over 6000 ms. I don't think Sync logs are going to help much here, unfortunately. :-( TMart, would you mind running `CALCULATE_FRECENCY(id) WHERE id IN ( SELECT id FROM moz_places WHERE frecency < 0 ORDER BY frecency ASC LIMIT 400 )` from the SQL tab About Sync, and seeing if you notice a similar hang? Thanks! It would also be great to see the output of `EXPLAIN QUERY PLAN` for that query, along with: * `SELECT count(*) FROM moz_places WHERE frecency < 0`, to see how many URLs need new frecencies, and... * `SELECT count(*) FROM moz_places`, for total URLs.
Flags: needinfo?(Tobias.Marty)
Blocks: 1433177
I would love to, unfortunately about:sync doesn't load for me anymore with the addon (version 0.0.23) enabled. I have no idea why that is.
(In reply to TMart from comment #1) > I would love to, unfortunately about:sync doesn't load for me anymore with > the addon (version 0.0.23) enabled. I have no idea why that is. I hope to have that fixed very soon.
(In reply to Lina Cambridge (she/her) [:lina] from comment #0) > TMart, would you mind running `CALCULATE_FRECENCY(id) WHERE id IN ( SELECT > id FROM moz_places WHERE frecency < 0 ORDER BY frecency ASC LIMIT 400 )` > from the SQL tab About Sync, and seeing if you notice a similar hang? Thanks! This returns an error: Error running SQL: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [mozIStorageConnection.createStatement]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: chrome://aboutsync/content/build.js :: getSqlColumnNames :: line 27674" data: no] > It would also be great to see the output of `EXPLAIN QUERY PLAN` for that > query, along with: > * `SELECT count(*) FROM moz_places WHERE frecency < 0`, to see how many URLs > need new frecencies, and... 33 > * `SELECT count(*) FROM moz_places`, for total URLs. 133219
Flags: needinfo?(Tobias.Marty)
(In reply to TMart from comment #3) > This returns an error: > Error running SQL: [Exception... "Component returned failure code: > 0x80004005 (NS_ERROR_FAILURE) [mozIStorageConnection.createStatement]" > nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: > chrome://aboutsync/content/build.js :: getSqlColumnNames :: line 27674" > data: no] Oops, sorry, I accidentally a statement. :-O UPDATE moz_places SET frecency = CALCULATE_FRECENCY(id) WHERE id IN ( SELECT id FROM moz_places WHERE frecency < 0 ORDER BY frecency ASC LIMIT 400 > > * `SELECT count(*) FROM moz_places`, for total URLs. > 133219 Hmm, that's not many URLs. Do you see any other statements in telemetry? We might be waiting for another to finish.
(In reply to Lina Cambridge (she/her) [:lina] from comment #4) > Oops, sorry, I accidentally a statement. :-O > > UPDATE moz_places SET frecency = CALCULATE_FRECENCY(id) WHERE id IN ( SELECT > id FROM moz_places WHERE frecency < 0 ORDER BY frecency ASC LIMIT 400 Ok, that gives me 0 changes. > Hmm, that's not many URLs. Do you see any other statements in telemetry? We > might be waiting for another to finish. Not really. I can't really reproduce this right now, so it doesn't seem as bad as the problem I had before, which I could reproduce very easily. Maybe I triggered a worst case scenario somehow that happens only rarely. I will keep this ticket in mind however if I notice it again.
Just had another main process freeze while clicking on the Library button, then Downloads, after setting a few bookmarks. This statement shows up in telemetry: SELECT h.id, h.url, h.title AS page_title, h.rev_host, h.visit_count, h.last_visit_date, null, null, null, null, null, null AS tags , h.frecency, h.hidden, h.guid, null, null, null FROM moz_places h WHERE 1 AND hidden = 0 AND last_visit_date NOTNULL AND ( h.id IN (SELECT place_id FROM moz_historyvisits WHERE visit_type = :transition0_ ) ) ORDER BY 6 DESC LIMIT 42 /* places.sqlite */
Unfortunately it looks like the common "main-thread IO is unpredictable" problem, where the disk may be busy doing something else and then any operation, even a fast one, can take seconds to complete :(
Keywords: stalled
Priority: -- → P5
Severity: normal → S3

I think we could close this since I moved the recalculation to idle in bug 1806666
The only thing that may still recalculate immediately is adding visits, that surely happens for syncing history, but it doesn't seem to be relevant for this specific bug.

Flags: needinfo?(lina)

That sounds right! It's been a while, but I think the other source of hangs we saw early on was writing to Places from a second connection, which we fixed in https://phabricator.services.mozilla.com/D39890. Between moving frecency recalculation to idle, and avoiding contended writes in general, we should be in a better place today! 😊

Status: NEW → RESOLVED
Closed: 2 years ago
Flags: needinfo?(lina)
Resolution: --- → WORKSFORME

Since the bug is closed, the stalled keyword is now meaningless.
For more information, please visit auto_nag documentation.

Keywords: stalled
You need to log in before you can comment on or make changes to this bug.