496646 - gloda registers whittlers multiple times, may whittle content multiple times - bad for gloda plugins, core gloda lucks out

Status: VERIFIED FIXED

(MailNews Core :: Backend, defect)

Description

[Wayne Mery (:wsmwk)]

Attachment: graph of cpu while indexing

+++ This bug was initially created as a clone of Bug #465353 +++

I haven't been using gloda indexign for months ... revisiting it because I'd like to try the gp-bugzilla extension.

as stated in summary, system is borderline unusable during indexing of gloda. all UI is slow - 2-4 seconds to do most things. loading messages very slow, even news. more detail below.

(opening this new bug from bug 465353 comment 6, copied below, rather than reopen bug 479008. will retest T40 laptop of bug 465353 and comment there on it's performance.)

-- comment 6 ---------------------------------------------------------------
P4 3.2GHz, desktop@work, windows XP pro, initial indexing in progress. takes 3-4 sec to load message. Same amount of time from clicking reply to usable compose window. Total 6-8 sec.

cpu graph seems to indicate idle doesn't happen while indexing.

clicking folders slow - perhaps not as bad in days of bug 479008 but still quite bad. 

from IRC
<asuth>    wsmwk: gloda has limited granularity. it can't control how much cpu
that message streaming uses, for example. well, not easily. so in your case it
may end up a little imbalanced. that might explain why you see 0% then 80%
wsmwk: gloda is backing off extremely because the message streaming hits you so
hard, so when it is doing things it controls, it does almost no work
(in order to control the message streaming cpu hit gloda would need to control
the rate at which the message data is delivered to libmime from the offline
store)
--------------------------------------------------------------------------------

to expand on the cpu usage and other observed performance:
1. 11 wall seconds per message to index
2. graph profile is roughly: 2 seconds 0 cpu, split second of 100% cpu, then about 10 sec at 50% cpu
3. cpu graph basically doesn't change - same when system has been left idle for many minutes, versus actively using Thunderbird
4. all messages are local/offline - all folders have been marked for offline use - activity manager indicates no substantial imap activity
5. loading new messages is painful at 3-8 seconds. this includes news
6. compose performance as described above. sending is also slow

in the attached graph, all the "sets" on the left are identical - each set starting with a shot at 0% cpu.

on the right, the last 5 or so sets have changed slightly because there I changed some folders to be offline, so some imap activity was occurring.

Comment 1

[Wayne Mery (:wsmwk)]

delving into the impact of bug 479008...

Folder name being indexed was not being displayed in activity manager, which austh said on IRC "suggests it's doing event-driven indexing so it's indexing either newly received messages or messages you just read or something like that"

By which assume that means bug 479008.  But 
a) folder names are being displayed during indexing (don't know why or when folder names started appearing) and there is still bad performance
b) bad perf even if I am *not* logged in to my imap accounts

In other words, I'm still being killed when the rate of my data being autosynced is zero or very low.
 
quoting asuth/bienvenu from 479008
 > Reasonable options include just kicking off indexing with a fixed delay, or
 > (probably better) keep delaying the indexing kick-off until no new events 
 > (that we care about) have happened for a fixed period of time. 
 That's what I did with the Spotlight indexer

I'd post debug information but I can't anything off the console in windows XP. The console goes ballistic with new messages after a few seconds of thunderbird being started. 

for reference - asuth> sid0: it has two thresholds. 30-40% if you are active, 70-80% if you are idle


Conversely, indexing on this slower Dell D531 laptop with Mozilla/5.0 (Windows; U; Windows NT 6.0; en-US; rv:1.9.1pre) Gecko/20090605 Shredder/3.0b3pre rate is blazing - just finished 37k messages in under 30 minutes. The P4 looks like it's going to be over 3,000 minutes.  14k of 37k messages still to be indexed after almost 2 days (20090604 3.0b3pre). Once initial indexing is finished, if this behavior continues I'll be forced again to turn gloda off.

The only good news is memory hasn't gone ballistic

Comment 2

[Joe Sabash [:JoeS1]]

It's about time for me to try this again, since I initially had perf problems.
I have had Gloda enabled for at least 3 weeks with minimal impact on perf
So now I have deleted the 118 Meg ...Db.sqlite file and started from scratch.

Been running for about a half hour now with minimal impact.
This is with a P3-s (double cache server CPU) 1.6 Gig

See some excursions to 100% CPU usage, but UI seems fine.

Comment 3

[Joe Sabash [:JoeS1]]

Results: Rebuild index from deletion.

Original 118 meg file was re-indexed to 102 meg file.
Total elapsed time (wallclock) 1 hr 23 min.

No real perf impact beyond maybe a 2 sec delay.
Sent, received mail and newsgroup messages.

The biggest visible impact for me was scrolling the folderpane, which delayed, then scrolled OK

For my low-end P3 CPU, the impact was very tolerable.

Comment 4

[Andrew Sutherland [:asuth] (he/him)]

Funny story.  I think the problem is that your messages are being "whittled" 16 times for quoting, and, if using gp-bugzilla, 4 times for bugzilla.  This will drastically slow the indexing process.

This is a serious regression introduced in
http://hg.mozilla.org/comm-central/rev/81998e37543a
for bug 454829.

Last time I just review a patch using bugzilla's diff support.  If I had seen the context at all, it wouldn't have happened.  argh.

I presume your P4 machine has a lot of bugmails and gp-bugzilla is installed, and then your laptop does not have gp-bugzilla installed?

We have sufficient mozmill support at this time (or once bug 474701, the patch that ate everybody lands) that it should be feasible to run a talos sort of setup.

Comment 5

[Andrew Sutherland [:asuth] (he/him)]

Also, Joe, thanks for the update.  We want things to be more than tolerable, but it's nice to know that gloda isn't eating everyone's machine alive! :)

Comment 6

[David Ascher (:davida)]

Argh.  It's the registration of the whittler that's happening in the wrong place, ain't it...

I'm going to be traveling and not guaranteed to be able to hack for the next few days, but if no one else gets to it first, I'll figure out a patch.

Comment 7

[Wayne Mery (:wsmwk)]

Yes to everything in comment 4.  And, disabled gp-bugzilla and performance is better on the P4. Ditto on the D531 with gp-bugzilla disabled vs enabled.

In addition, on the P4 I had a local folder "mess" with 37k copies of
 Re: Reply Partial Quote
 from a posting 2/15/09 2:49pm npm.mail-news by Wayne Mery
which seems to impact indexing along the lines of bug 452221. Indexing of that folder never seems to finish. I removed the folder and indexing zips along.

Comment 8

[Andrew Sutherland [:asuth] (he/him)]

Oh, right.  Gloda is not going to handle you having 37,000 copies of a single message all that well.  A thread with 37k messages in it would be far preferable, although I'll be honest that its performance is not going to be exactly stellar in that case either.

I would dispose of all folders that are entirely populated by duplicated messages.  It is not a realistic test case.  If you need large numbers of synthetic messages, potentially with threading relationships, we can hook up messageGenerator.js to some form of mechanism that you can use to create a more realistic tests corpus.

I am tempted to resolve this bug invalid, but instead let's magic it into the legitimate gloda regression, since that does need a bug.

Comment 9

[Andrew Sutherland [:asuth] (he/him)]

Also, I thought about this and remembered that the whole point of volunteerContent was to avoid having wasteful whittling happening.  fundattr.js's whittler will only whittle the first time, because it will only "win" its volunteering the first time.  In contrast, gp-bugzilla ignores the return value because it knows it is the perfect whittler and does not expect to be called multiple times.  Arguably it should change its logic to be less prideful, but hey.

Downgrading to minor since you have to install an extension to experience any meaningful performance degradation.  We will, of course, fix this for beta 3.

Comment 10

[Wayne Mery (:wsmwk)]

Thanks for the updates. Agree, a 37k folder all same subject is not a realistic testcase - but BenB and others have proven unrealistic situations exist in the wild :)  Anyway, I only mentioned it as an FYI.

nit - I am conflicted about severity given the involvement an extension, and in fact I will keep it disabled.  Still, I will choose to take issue with minor, so setting sev=major (understanding that it doesn't drive priority nor delivery). Severity is impact to the affected user under the conditions of the testcase, not the experience of the average user or a prescription of "Don't do that". But more to the point, it's probable more future functionality will depend on this. Thunderbird is, after all, extensible by design.

Comment 11

[Dan Mosedale (:dmosedale, :dmose)]

I think this probably would block Tb3, since it hurts our platform story and sounds like it should be straightforward to fix.  Since Gloda isn't going to be on by default for beta 3, this won't block b3 itself; moving out.

Comment 12

[David Ascher (:davida)]

I broke it, I'll fix it.

Comment 13

[Andrew Sutherland [:asuth] (he/him)]

Attachment: v1 only register a provider's whittler once, unit test we whittle only once

Comment 14

[Wayne Mery (:wsmwk)]

/me please leave symptoms in summaries - technical accuracy is great but it's not what non-techs will likely search on  :)

Comment 15

[Andrew Sutherland [:asuth] (he/him)]

I was removing the bits that were specific to you having 37k duplicate messages.  While the whittling bug would slow indexing, it is unlikely to slow things down more than one order of magnitude, and it definitely would not be pegging your CPU while it did it.  I probably should have changed the bug to "gloda does not handle it when you have many thousand copies of the same message" and spun off an entirely separate bug for the whittling case...

Comment 16

[Andrew Sutherland [:asuth] (he/him)]

pushed: http://hg.mozilla.org/comm-central/rev/026d2683cf9c

Comment 17

[Wayne Mery (:wsmwk)]

(In reply to comment #15)
> I was removing the bits that were specific to you having 37k duplicate
> messages.  While the whittling bug would slow indexing, it is unlikely to slow
> things down more than one order of magnitude, and it definitely would not be
> pegging your CPU while it did it.  I probably should have changed the bug to
> "gloda does not handle it when you have many thousand copies of the same
> message" and spun off an entirely separate bug for the whittling case...

my bad. I no longer see the problem fixed by this bug+summary :)