1462718 - 5.5 minute hang in PlacesView constructor when opening Bookmarks menu

Status: RESOLVED DUPLICATE of bug 1462046

(Toolkit :: Places, enhancement)

Description

[Markus Stange [:mstange]]

Similarly to bug 1462135, I just encountered another long hang due to synchronous Places operations.

This time the hang happened when opening the Bookmarks menu. Here's the relevant part of the stack:

> onpopupshowing
> PlacesMenu constructor
> PlacesViewBase constructor
> set place
> nsNavHistory::ExecuteQuery
> nsNavBookmarks::ResultNodeForContainer(long long, nsNavHistoryQueryOptions*, nsNavHistoryResultNode**)
> nsNavBookmarks::FetchItemInfo(long long, mozilla::places::BookmarkData&)
> mozilla::storage::StatementCache<mozIStorageStatement>::GetCachedStatement(nsTSubstring<char> const&)
> mozilla::storage::StatementCache<mozIStorageStatement>::CreateStatement(nsTSubstring<char> const&)
> mozilla::storage::Connection::CreateStatement(nsTSubstring<char> const&, mozIStorageStatement**)
> mozilla::storage::Statement::initialize(mozilla::storage::Connection*, sqlite3*, nsTSubstring<char> const&)
> mozilla::storage::Connection::prepareStatement(sqlite3*, nsTString<char> const&, sqlite3_stmt**)
> sqlite3_extended_result_codes
> _pthread_mutex_lock_slow
> ___psynch_mutexwait

I don't see any new slow SQL statements on about:telemetry.

Which thread is it blocking on here? I can add it to the list of threads that the profiler is profiling. Do we have profiler stack labels that include the statement that's being executed on those threads?

Comment 1

[Markus Stange [:mstange]]

Forgot the source information for the JS stack frames:

> onpopupshowing chrome://browser/content/browser.xul:0
> PlacesMenu constructor chrome://browser/content/places/browserPlacesViews.js:1891
> PlacesViewBase constructor chrome://browser/content/places/browserPlacesViews.js:11
> set place chrome://browser/content/places/browserPlacesViews.js:54

Comment 2

[Marco Bonardo [:mak]]

I suspect there's something broken in some recent changes that does long operations on the connection helper thread, and main thread queries queue up waiting for that work to finish.
I can't explain this spike in long hangs any other way. Could be related to the recent autofill work?

Very likely that thread is blocked on the connection helper thread (a mozStorage thread), unfortunately we don't have labels including the statement being executed, we only have MOZ_LOG.

Comment 3

[Drew Willcoxon :adw]

Thanks for filing this and debugging it.  I think I've fixed it in bug 1461753.  We'll see when it lands.

Comment 4

[Marco Bonardo [:mak]]

please let us know if this is still common

Comment 5

[Marco Bonardo [:mak]]

since the underlying cause is the same, let's dupe to bug 1462046 and track everything in a single place.