848161 - Track time required to close WAL databases

Status: RESOLVED INACTIVE

(Core :: Gecko Profiler, defect)

Description

[Vladan Djeric (:vladan)]

Attachment: Labels for cookies, localStorage, places DBs

Closing a WAL database may take a long time since the write-ahead log is merged into the database file on close. This may negatively impact shutdown times.

The profiler's "Performance Monitor" feature can help us shed light on how much time closing WAL databases is adding to shutdown. This patch adds sample labels to methods that close the cookies, localStorage and places WAL databases.

Comment 1

[Vladan Djeric (:vladan)]

Attachment: Labels for cookies, localStorage, places DBs

Comment 2

[Vladan Djeric (:vladan)]

Comment on attachment 721501 [details] [diff] [review]
Labels for cookies, localStorage, places DBs

This patch shouldn't be too hard to review

Comment 3

[Marco Bonardo [:mak]]

Comment on attachment 721501 [details] [diff] [review]
Labels for cookies, localStorage, places DBs

Review of attachment 721501 [details] [diff] [review]:
-----------------------------------------------------------------

Are you sure this is measuring what you expect?

The connection close happens here http://mxr.mozilla.org/mozilla-central/source/storage/src/mozStorageConnection.cpp#763
this is what I expect to merge the wal.
In our services we call asyncClose, that dispatches a runnable to the async thread that does the actual closing. Afaict this label won't mark the time spent in such runnable, and since most of these services shutdown at the same notification, that is "profile-before-change" may be hard to distinguish yet.
Unless I missed something about how SAMPLE_LABEL works.

Comment 4

[Marco Bonardo [:mak]]

oops, somehow me and Olli ended up submitting at close times and I finished by overwriting his flag. sorry.

Comment 5

[Olli Pettay [:smaug][[e-mail]]]

Doesn't matter. You had good comment and know this code :)

Comment 6

[Vladan Djeric (:vladan)]

Comment on attachment 721501 [details] [diff] [review]
Labels for cookies, localStorage, places DBs

I was a bit unclear on the motivation when Benoit asked me to add these labels, I was assuming the labels were going to be parsed by scripts that process submitted profiles. If the intention is just to verify whether WAL checkpointing is causing shutdown delays, I think we should morph this into a Telemetry probe bug or abandon it altogether if we think we can just solve the (presumed) problem by checkpointing the WAL log more aggressively at runtime (off the main thread).

Marco, I think the issue with the Places sample label would have been that it over-estimates the amount of time to checkpoint the WAL: it spins the event loop so the time period covered by the label might include the handling of unrelated events.

Comment 7

[Marco Bonardo [:mak]]

(In reply to Vladan Djeric (:vladan) from comment #6)
> just solve
> the (presumed) problem by checkpointing the WAL log more aggressively at
> runtime (off the main thread).

We already do that for all consumers but DOM Storage afaik

> Marco, I think the issue with the Places sample label would have been that
> it over-estimates the amount of time to checkpoint the WAL: it spins the
> event loop so the time period covered by the label might include the
> handling of unrelated events.

Honestly right now I don't remember the reason we added such spinning, it was probably a first try for an exit(0) approach, at xpcom-shutdown the async thread is spinned and merged back to the main-thread that means internalClose() should be called in any case on the connection.
Could be to cover the case where we try to use a connection between asyncClose and internalClose.
Maybe rafael rememebers the reasoning for that, the bug comments don't help.

Comment 8

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

The spinnig was added to xpcom-shutdown-threads, which is after xpcom-shutdown. We were getting async operations finishing after the point where we now spin and the callbacks they call would be in a very precarious state since most of firefox had already shutdown.

Is this the spinning you are referring to?

Comment 9

[Marco Bonardo [:mak]]

(In reply to Rafael Ávila de Espíndola (:espindola) from comment #8)
> Is this the spinning you are referring to?

Nope, he was referring to the spinning in Database.cpp
http://mxr.mozilla.org/mozilla-central/source/toolkit/components/places/Database.cpp#1891

Comment 10

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

(In reply to Marco Bonardo [:mak] from comment #9)
> (In reply to Rafael Ávila de Espíndola (:espindola) from comment #8)
> > Is this the spinning you are referring to?
> 
> Nope, he was referring to the spinning in Database.cpp
> http://mxr.mozilla.org/mozilla-central/source/toolkit/components/places/
> Database.cpp#1891

Same idea, it is just older code. It might be possible to remove it now that we spin for every connection in xpcom-shutdown-threads.

You might want to do it now or wait until the spin in xpcom-shutdown-threads (or whatever API gets implemented in bug 722648) is moved back past it as part of the exit(0) work.