834945 - GC triggers a late DB write during shutdown

Status: RESOLVED INCOMPLETE

(Core :: XPCOM, defect)

Description

[Vladan Djeric (:vladan)]

My shutdown profile shows GC triggering a flush of IndexedDB very late during shutdown. Are we not explicitly flushing IndexedDB at "profile-before-change"?

http://people.mozilla.com/~bgirard/cleopatra/#report=e2789c613c5c5f1a508ef8a6f0d7fb773b157c95

This is also evidence that skipping GCs at shutdown could cause data loss.

Comment 1

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Where exactly do you see IndexedDB in here?

IndexedDB has code to flush at profile-before-change.  See IndexedDatabaseManager::Observe

Comment 2

[Benoit Girard (:BenWa)]

Link with selection. It's the most expensive one:
http://people.mozilla.com/~bgirard/cleopatra/#report=e2789c613c5c5f1a508ef8a6f0d7fb773b157c95&search=winSync

Comment 3

[Benoit Girard (:BenWa)]

    NtFlushBuffersFile
    NtFlushBuffersFile
    FlushFileBuffersImplementation
    winSync
    `anonymous namespace'::xSync(sqlite3_file *,int)
    walCheckpoint
    sqlite3WalCheckpoint
    sqlite3BtreeClose
    sqlite3LeaveMutexAndCloseZombie
    sqlite3Close
    sqlite3_close
    mozilla::storage::Connection::internalClose()
    mozilla::storage::Connection::~Connection()
    nsCOMPtr<nsIDirectoryServiceProvider>::`scalar deleting destructor'(unsigned int)
    nsTArray_Impl<nsRefPtr<mozilla::dom::CSSValue>,nsTArrayInfallibleAllocator>::DestructRange(unsigned int,unsigned int)
    nsTArray_Impl<nsRefPtr<mozilla::dom::HTMLCanvasElement>,nsTArrayInfallibleAllocator>::RemoveElementsAt(unsigned int,unsigned int)
    nsTArray_Impl<nsRefPtr<mozilla::dom::indexedDB::IndexedDatabaseManager::AsyncUsageRunnable>,nsTArrayInfallibleAllocator>::RemoveElement<mozilla::dom::indexedDB::IndexedDatabaseManager::AsyncUsageRunnable *,nsDefaultComparator<nsRefPtr<mozilla::dom::indexedDB::IndexedDatabaseManager::AsyncUsageRunnable>,mozilla::dom::indexedDB::IndexedDatabaseManager::AsyncUsageRunnable *> >(mozilla::dom::indexedDB::IndexedDatabaseManager::AsyncUsageRunnable * const &,nsDefaultComparator<nsRefPtr<mozilla::dom::indexedDB::IndexedDatabaseManager::AsyncUsageRunnable>,mozilla::dom::indexedDB::IndexedDatabaseManager::AsyncUsageRunnable *> const &)
    mozilla::storage::Service::unregisterConnection(mozilla::storage::Connection *)
    mozilla::storage::Connection::Release()
    mozilla::storage::Statement::~Statement()
    DoDeferredRelease<nsXPCWrappedJS *>
    Collect
    js::GC(JSRuntime *,js::JSGCInvocationKind,js::gcreason::Reason)
    js::DestroyContext(JSContext *,js::DestroyContextMode)
    JS_DestroyContext(JSContext *)
    mozJSComponentLoader::UnloadModules()
    mozJSComponentLoader::Observe(nsISupports *,char const *,wchar_t const *)
    mozilla::ShutdownXPCOM(nsIServiceManager *)
    ScopedXPCOMStartup::~ScopedXPCOMStartup()
    XREMain::XRE_main(int,char * * const,nsXREAppData const *)
    Startup::XRE_Main
    XRE_main
    do_main
    wmain
    __tmainCRTStartup
    BaseThreadInitThunk
    __RtlUserThreadStart
    _RtlUserThreadStart
    (root)

Comment 4

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

That looks like symbol coalescing, not anything real.

The mozstorage stuff used by IDB is never exposed to JS.

Comment 5

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Any particular steps that can be used to reproduce this? If so I can try a debug build to see if the problem is just symbol coalescing, but this looks like a real late write from the NS_XPCOM_SHUTDOWN_LOADERS_OBSERVER_ID notification. Is this windows only? Has it triggered some late write report?

Comment 6

[Vladan Djeric (:vladan)]

The "Late Writes" section of about:telemetry was empty after I restarted the browser. I filed bug 834938 for this. In general, I never see any late writes on my Windows machine

Comment 7

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Looking a bit more, this *might* be safe, but I would still like to clear the statement reference earlier anyway. This is a sync connection (otherwise Connection::Close would leave it open), so sqlite3_close is "just" doing internal work (committing a log?) and should remain consistent.

Any tips on how to reproduce this?

Comment 8

[Vladan Djeric (:vladan)]

I can reproduce this reliably on my work laptop it seems :S

New profile:

http://people.mozilla.com/~bgirard/cleopatra/#report=a45248030d47e8fbe42e76c1b465bd265994ea64

Comment 9

[Vladan Djeric (:vladan)]

I can send you my list of add-ons. I'll try to get the statement string or DB name tomorrow.

Comment 10

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

OK, vladan pointed out that this was only happening with PrivacyChoice TrackerBlock installed. I installed it on OS X and got an assertion failure on mozStorageService.cpp:829, which is almost certainly the same bug.

Comment 11

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

What is going on is:

* The addon keeps a reference to a connection to webappsstore.sqlite.
* On a debug build, we hit the assert about it not being closed.
* When NS_XPCOM_SHUTDOWN_LOADERS_OBSERVER_ID is sent, the reference goes away and GC closes the connection.
* webappsstore.sqlite is in Wal mode, and sqllite3_close will checkpoint. That is, it will copy data from the log(wal) to the btree.

So there is a bug in the addon, but this also shows a more general problem: In a release build, we want to do as little work during shutdown as possible. In particular, we don't want to close sync connections. This means we want them closed after the point we call exit(0), which is also the point where we will poison writes.

The net result is that will have to ignore writes coming from sqlite3WalCheckpoint (or maybe sqlite3_close itself). Since this is past the point were we currently poison writes, I propose that:

* For now, just add a comment to the source code pointing to this bug for well we try to move write poisoning before NS_XPCOM_SHUTDOWN_LOADERS_OBSERVER_ID.
* I will change the MOZ_ASSERT about connections being closed into something controlled by an environment variable (bug 704030) so that we can ping the addon author and ask them to fix their side.

Comment 12

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

Attachment: Add comment pointing to this bug

Comment 13

[Rafael Ávila de Espíndola (:espindola) (not reading bugmail)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a4b75cd17e1c

Comment 14

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/a4b75cd17e1c

Comment 15

[David Teller [:Yoric] - still alive but not very active]

As part of bug 916078, we should be able to force mozStorage to close everything during profile-before-change. Would this change anything for this bug?

Comment 16

[Benoit Girard (:BenWa)]

(In reply to David Rajchenbach Teller [:Yoric] from comment #15)
> As part of bug 916078, we should be able to force mozStorage to close
> everything during profile-before-change. Would this change anything for this
> bug?

With the risk of breaking addons aside, yes it would fix this bug.

Comment 17

[BugBot [:suhaib / :marco/ :calixte]]

The bug assignee didn't login in Bugzilla in the last 7 months, so the assignee is being reset.

Comment 18

[Andrew McCreight [:mccr8]]

A patch adding a comment about this did land. It sounds like this bug is about eliminating late writes caused by some addon, so I'm not sure if that's still relevant. If somebody is working on late writes they can file a new bug.