515952 - Regular 20+ second hangs on shutdown with beachball, etc

Status: RESOLVED WORKSFORME

(Toolkit :: Places, defect)

Description

[Boris Zbarsky [:bzbarsky]]

Most of the time when I shut down an m-c build that uses my "testing" profile, I get 20+ second hangs with the beachball spinning.  CPU usage seems to be minimal. This is particularly a problem if I happen to be compiling or linking or copying files or anything like that at the time, but happens even on an idle system.

Profiles suggest disk i/o and ExpireHistoryParanoid.

Anything I can provide here that would help with debugging this?  It's being a serious problem for little things like debugging....

Comment 1

[Marco Bonardo [:mak]]

Are you clearing history on shutdown? Anything special?
I can't understand how can paranoid expiration take so much.
How big is places.sqlite?

Comment 2

[Marco Bonardo [:mak]]

could you also check DB integrity with PRAGMA integrity_check; please?

Comment 3

[Boris Zbarsky [:bzbarsky]]

> Are you clearing history on shutdown? Anything special?

Don't think so.

> I can't understand how can paranoid expiration take so much.

It doesn't always; only about 2/3 of the time.  Sometimes it's instant.

> How big is places.sqlite?

26599424 bytes at the moment.

> could you also check DB integrity with PRAGMA integrity_check; please?

How do I go about doing that?

Comment 4

[David Dahl :ddahl]

(In reply to comment #3)

> > could you also check DB integrity with PRAGMA integrity_check; please?
> 
> How do I go about doing that?

$ sqlite3 /path/to/profile/places.sqlite

> PRAGMA integrity_check;

Comment 5

[Boris Zbarsky [:bzbarsky]]

sqlite3 ~/Library/Application\ Support/Firefox/Profiles/ankrljc6.testing/places.sqlite
SQLite version 3.6.14.2
Enter ".help" for instructions
Enter SQL statements terminated with a ";"
sqlite> PRAGMA integrity_check;
ok
sqlite>

Comment 6

[Mike Beltzner [:beltzner, not reading bugmail]]

Are you getting this on mozilla-1.9.2 as well, bz? I don't think we can block release on this, but obviously we want a fix.

Comment 7

[Boris Zbarsky [:bzbarsky]]

I can try 1.9.2, but I generally don't use those builds... Is it safe to try those builds on a profile I usually use m-c on?

Comment 8

[Shawn Wilsher :sdwilsh]

Do you run mochitests in this profile by chance?

Comment 9

[Boris Zbarsky [:bzbarsky]]

Mochitests, no (since those create their own profile).

I do run reftests in it.

Comment 10

[Shawn Wilsher :sdwilsh]

Sorry - I was really asking about any set of tests that cycle through a bunch of pages that end up causing a bunch of visits.  You end up adding way more visits than our normal expiration code can get rid of (expire six pages every two minutes).  As a result, we have a lot to expire on shutdown.

Comment 11

[Boris Zbarsky [:bzbarsky]]

But this is happening even if I didn't run reftest during the current run....

Comment 12

[Marco Bonardo [:mak]]

well, i'm taking a look at what we are doing, i don't think we can rewrite all expiration for 3.6, but maybe we could make it better with some simple changes to the constants.

Comment 13

[Marco Bonardo [:mak]]

assigning to me for small investigation and first look.
The scope is not to rewrite expiration, but to find if we can identify some cause, and provide a first experimental change for 3.6 that we can then inherit in 3.7 expiration rewrite.

As a first step i'm thinking about a really simple auto-adapting algo that can guess if user is an heavy or casual history user, so that we can expire more things during idle runs rather than during shutdown.

Comment 14

[Marco Bonardo [:mak]]

Attachment: wip v0.1

this removes a bunch of useless stuff at shutdown trying to distribute it better.
I still have to hammer ExpireOrphans though, if i should be hosnest i'm not sure we still need it, we could just consider that db cleanup and move it into PlacesDBUtils. Btw, i'll look into it next.

Comment 15

[Marco Bonardo [:mak]]

as a thought, i think partially this is due to the fact we now expire some of the visits in DBFlush, but as i said when we implemented this, it won't bother expiring orphan pages. Previous implementation was expiring pages with visits if needed.
We partially do this on idle, but, but we do this heavily on exit, about 5 times more. if the user is not going idle, it could expire up to 500 pages at shutdown.

Comment 16

[Marco Bonardo [:mak]]

Attachment: wip 0.2

This also tries to expire some orphan asynchronously, but requires some deep thought about how it is hooking in the actual system (esp. notifications).

I pushed this to the tryserver to get some number.

Boris, in the meantime, if you would like to try this and see if anything changes for your use-case, would be awesome.

Comment 17

[Marco Bonardo [:mak]]

this brought some reduction in Tshutdown, even if i would have expected more, for the medium dirty profile the gain is something more than 500ms, for the max dirty profile about 2s, with some fluctuation.
The max dirty profile TShutdown is still around 8s :\
On the other side i've not appreciated any Tp4 movement, and that's positive.

Comment 18

[Marco Bonardo [:mak]]

on the other side, ExpireHistoryParanoid, as pure query time, does not go over 250ms here on a quite big db, so looks like the vast majority of time is really spent in disk I/O to flush the journal to the db. For the max dirty profile iirc we are talking about a 200MB database. Btw i'll still do an experimental push to the tryserver along with bug 478718 that simplifies other shutdown paths.

Comment 19

[Marco Bonardo [:mak]]

the 2 patches together gave a further imrpovement by 200ms-2s, still a bit high (5-6s), but at this point i'm starting fearing this is just I/O binded.

Comment 20

[Marco Bonardo [:mak]]

Comment on attachment 400615 [details] [diff] [review]
wip 0.2

i'll move the patch to a separate bug about reducing expiration work at shutdown, since i have doubts this patch can fix Boris case, it could maybe make it better, but not fix it.
I cannot reproduce it with his db, nor in opt or in debug mode, so really sounds like just bad I/O, for sure needs better profiling.

Comment 21

[Marco Bonardo [:mak]]

Boris, can you please tell if you see any improvement with latest trunk (after changeset 123e48c8edf4)

Comment 22

[Boris Zbarsky [:bzbarsky]]

Will do.  I think we should mark this wfm for now, and if I see it again I'll reopen.