Closed Bug 722212 Opened 12 years ago Closed 12 years ago

Firefox spins at 100% in sqlite3 thread

Categories

(Toolkit :: Places, defect)

x86
macOS
defect
Not set
normal

Tracking

()

RESOLVED DUPLICATE of bug 722188

People

(Reporter: jdm, Unassigned)

References

Details

I'm pretty certain this behaviour wasn't present in the Jan 27 nightly, and maybe not in the one from the 28th. If I leave my OS X nightly sitting while I watch TV, the screen turns off and when I return to Firefox, the sqlite thread is consuming 100% of the CPU, and Firefox won't shut down. The following shark profile shows what this looks like (captured while it was spinning outside of shutdown).

0.0%	74.3%	libSystem.B.dylib	 _pthread_start
0.0%	74.3%	libnspr4.dylib	  _pt_root
0.0%	74.3%	XUL	   nsThread::ThreadFunc(void*)
0.0%	74.3%	XUL	    NS_ProcessNextEvent_P(nsIThread*, bool)
0.0%	74.3%	XUL	     nsThread::ProcessNextEvent(bool, bool*)
0.0%	74.2%	XUL	      mozilla::storage::AsyncExecuteStatements::Run()
0.0%	74.2%	XUL	       mozilla::storage::AsyncExecuteStatements::executeAndProcessStatement(sqlite3_stmt*, bool)
0.0%	74.2%	XUL	        mozilla::storage::AsyncExecuteStatements::executeStatement(sqlite3_stmt*)
0.0%	74.2%	XUL	         mozilla::storage::Connection::stepStatement(sqlite3_stmt*)
0.0%	74.2%	libmozsqlite3.dylib	          sqlite3_step
18.5%	72.8%	libmozsqlite3.dylib	           sqlite3Step
0.6%	34.5%	libmozsqlite3.dylib	            sqlite3VdbeCursorMoveto
17.1%	33.2%	libmozsqlite3.dylib	             sqlite3BtreeMovetoUnpacked
Component: General → Places
Product: Core → Toolkit
QA Contact: general → places
It's conceivable that this is related to the idle service/maintenance stuff, since this never seems to occur when I'm actively using the browser.
may be bug 722242. Though that'd not be something new or in recent nightlies.
Next time you can reproduce, please go to about:telemetry 8provided you have the addon) and report the list of hanging queries from there.
adding a dependency for now.
also, unfortunately that stack is too short to tell if it comes from Places :(
Looking at the about:telemetry data that currently exists, this stands out to me:

1	1232754	UPDATE moz_places SET frecency = ROUND(frecency * .975) WHERE frecency > 0

There is also a 3 second VACUUM and a 2 second PRAGMA integrity_check(1). Here's the full list:

1	3377	VACUUM
19	149	ANALYZE moz_places
1	232	INSERT INTO moz_cookies (baseDomain, name, value, host, path, expiry, lastAccessed, creationTime, isSecure, isHttpOnly) VALUES (:baseDomain, :name, :value, :host, :path, :expiry, :lastAccessed, :creationTime, :isSecure, :isHttpOnly)
4	336	SELECT 1 FROM moz_places h WHERE url = ?1 AND last_visit_date NOTNULL
19	160	ANALYZE moz_historyvisits
1	636	UPDATE moz_places SET visit_count = (SELECT count(*) FROM moz_historyvisits WHERE place_id = moz_places.id AND visit_type NOT IN (0,4,7,8)), last_visit_date = (SELECT MAX(visit_date) FROM moz_historyvisits WHERE place_id = moz_places.id) WHERE id IN ( SELECT h.id FROM moz_places h WHERE visit_count <> (SELECT count(*) FROM moz_historyvisits v WHERE v.place_id = h.id AND visit_type NOT IN (0,4,7,8)) OR last_visit_date <> (SELECT MAX(visit_date) FROM moz_historyvisits v WHERE v.place_id = h.id) )
1	1232754	UPDATE moz_places SET frecency = ROUND(frecency * .975) WHERE frecency > 0
16	343	SELECT h.id, h.favicon_id, h.guid, (SELECT h.url FROM moz_bookmarks b WHERE b.fk = h.id UNION ALL SELECT (SELECT url FROM moz_places WHERE id = COALESCE(greatgrandparent.place_id, grandparent.place_id, parent.place_id)) FROM moz_historyvisits self JOIN moz_bookmarks b ON b.fk = COALESCE(greatgrandparent.place_id, grandparent.place_id, parent.place_id) LEFT JOIN moz_historyvisits parent ON parent.id = self.from_visit LEFT JOIN moz_historyvisits grandparent ON parent.from_visit = grandparent.id AND parent.visit_type IN (5, 6) LEFT JOIN moz_historyvisits greatgrandparent ON grandparent.from_visit = greatgrandparent.id AND grandparent.visit_type IN (5, 6) WHERE self.visit_type IN (5, 6) AND self.place_id = h.id LIMIT 1 ) FROM moz_places h WHERE h.url = :page_url
60	490	SELECT h.url, h.title, f.url, EXISTS(SELECT 1 FROM moz_bookmarks WHERE fk = h.id) AS bookmarked, ( SELECT title FROM moz_bookmarks WHERE fk = h.id AND title NOTNULL ORDER BY lastModified DESC LIMIT 1 ) AS btitle, ( SELECT GROUP_CONCAT(t.title, ',') FROM moz_bookmarks b JOIN moz_bookmarks t ON t.id = +b.parent AND t.parent = :parent WHERE b.fk = h.id ) AS tags, h.visit_count, h.typed, h.id, :query_type, t.open_count FROM moz_places h LEFT JOIN moz_favicons f ON f.id = h.favicon_id LEFT JOIN moz_openpages_temp t ON t.url = h.url WHERE h.frecency <> 0 AND AUTOCOMPLETE_MATCH(:searchString, h.url, IFNULL(btitle, h.title), tags, h.visit_count, h.typed, bookmarked, t.open_count, :matchBehavior, :searchBehavior) ORDER BY h.frecency DESC, h.id DESC LIMIT :maxResults
1	256	DELETE FROM moz_historyvisits WHERE id IN (SELECT id FROM moz_historyvisits v WHERE NOT EXISTS (SELECT id FROM moz_places WHERE id = v.place_id LIMIT 1) )
1	160	DELETE FROM moz_cookies WHERE name = :name AND host = :host AND path = :path
1	742	UPDATE moz_places SET frecency = CALCULATE_FRECENCY(id) WHERE frecency < 0
1	258	UPDATE moz_places SET title = :page_title WHERE id = :page_id
1	2394	PRAGMA integrity_check(1)

The following histograms also look interesting to my untrained eye:

MOZ_SQLITE_PLACES_WRITE_B
65462 samples, average = 18945.6, sum = 1240213792

MOZ_SQLITE_PLACES_READ_B
40373299 samples, average = 32768, sum = 1322952163628

MOZ_SQLITE_OTHER_READ_B
696 samples, average = 2887.4, sum = 2009622

MOZ_SQLITE_OTHER_WRITE_B
1753 samples, average = 14682.5, sum = 25738468

MOZ_SQLITE_COOKIES_WRITE_B
20073 samples, average = 17982.6, sum = 360964328

MOZ_SQLITE_URLCLASSIFIER_WRITE_B
7025 samples, average = 16365.8, sum = 114969800

MOZ_SQLITE_URLCLASSIFIER_READ_B
9091 samples, average = 31885.5, sum = 289870656
(In reply to Josh Matthews [:jdm] from comment #4)
> Looking at the about:telemetry data that currently exists, this stands out
> to me:
> 
> 1	1232754	UPDATE moz_places SET frecency = ROUND(frecency * .975) WHERE
> frecency > 0

yep, this is an idle task that creates contention, we are working on it
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.