722212 - Firefox spins at 100% in sqlite3 thread

Status: RESOLVED DUPLICATE of bug 722188

(Toolkit :: Places, defect)

Description

[Josh Matthews [:jdm]]

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

Comment 1

[Josh Matthews [:jdm]]

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.

Comment 2

[Marco Bonardo [:mak]]

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.

Comment 3

[Marco Bonardo [:mak]]

also, unfortunately that stack is too short to tell if it comes from Places :(

Comment 4

[Josh Matthews [:jdm]]

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

Comment 5

[Marco Bonardo [:mak]]

(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