17470 - [PERF] News Mark All Read performance is terrible

Status: VERIFIED FIXED

(MailNews Core :: Backend, defect, P4)

Description

[Phil Peterson]

I tried to mark all read in the mail-news newsgroup today (~5700 messages) and
it took
> 10 minutes. And that was using the release build!

Comment 1

[(not reading, please use [e-mail] instead)]

this is probably something I'm doing.

re-assign to me.

Comment 2

[lchiang]

Suresh - can we add this to our performance test?

Comment 3

[(not reading, please use [e-mail] instead)]

part of the performance problem is that the read / unread status is stored in
mork, instead of the newsrc file.

once I fix that, the performance suckage should go away.

adding dependency.

Comment 4

[(not reading, please use [e-mail] instead)]

accepting.

Comment 5

[David :Bienvenu]

No, this sucks because of all the grief that happens when you tell RDF about a
property change - style rules get re-evaluated, things relayout and repaint,
etc. I'll take this for now. It'll probably get marked a dup of some other bug.
Batching is the way to go here, I think.

Comment 6

[Phil Peterson]

*** Bug 18708 has been marked as a duplicate of this bug. ***

Comment 7

[scottputterman]

Since I'm experiencing this now, I thought I'd comment on this.  As I'm trying
to use this for Dogfood, I've currently made the mistake of marking all 6800
messages in the mail-news newsgroup as read.  It's been over 30 minutes so far
with no sign of stopping any time soon.

Anyway, I agree with David that batching is the way to go.  Even if we don't do
RDF batching, perhaps we should do some of our own batching (or at least
batching notifications).  I'm starting to wonder if in addition to notifications
that go to RDF in our folder listener, if we need something for just mailnews to
use.  I think recent code I've added as added to the problem.  In js now, I
listen to message count chnages in order to change the status bar counts.
Likewise, I change the unread count next to the folder name as well.  Each of
these is giong to happen every time a message gets marked read because we have
no event for when the whole thing is done.  Some internal event won't help the
thread pane since all of the green diamond's getting chnaged is part of RDF.
However, any code that's slow because of message totals changing could be sped
up if there was some way the backend notified the folder when the whole process
is done.  I think there are other cases where this might be important too.

I'm thinking maybe another function on the folder listener, such as
OnFolderEvent might be useful.  In here, we  ould do things like FolderLoaded,
MarkMessagesFinished, MsgsDeletedFinished and any other thing where we'd want to
know when the total job is done, not just the work on individual messages.

Comment 8

[David :Bienvenu]

Seth was right, it is something he's doing - commiting the db after every header
gets marked read. d'oh! I'll fix that.

Comment 9

[(not reading, please use [e-mail] instead)]

I think I originally did that horrible work around when we had problems with ref
counting, and the news db never got the closed and never did a commit.

putterman and davidb have helped the ref counting problem, so that ugly commit
can be removed.

I'm so ashamed.

Comment 10

[David :Bienvenu]

I'll take out that commit and add one after we mark all read. I'll check that in
right now!

Comment 11

[David :Bienvenu]

fix checked in.

Comment 12

[(not reading, please use [e-mail] instead)]

david is the patron saint of fixing my mistakes.

Comment 13

[lchiang]

Marking as verified.  Suresh ran some perf test on 1/13 build.  Results for
marking all as read on a 133mhz system (about 500 msgs)

1/13 build:  19.374s with standard deviation of 0.465
Previous build on 12/16 showed: 73.466s with standard deviation of 2.450.

Great!

Comment 14

[Suresh]

I'm reopening this bug as the current results are not that good. On 4/27 build 
it took 251.842 seconds to mark 500 news msg as read. 

Comment 15

[scottputterman]

my guess is that this is due 37485 which is caused by performance problems in 
RDF that waterson is looking into.

Comment 16

[David :Bienvenu]

ok, I'll mark it as a dup. I haven't changed any of the code that marks news 
messages read, or any code at all for that matter so I don't think I could have 
possibly caused a regression here.

*** This bug has been marked as a duplicate of 37485 ***

Comment 17

[lchiang]

suresh - keep an eye out on that other bug. thanks

Comment 18

[Suresh]

Bug 37485 was marked fixed on 5/4/00. Marking news msgs as read is very slow in
today's build. Reopening the bug.

Comment 19

[David Krause]

Mass moving old milestone bugs to M16.

Comment 20

[scottputterman]

Moving to M18 and nominating for nsbeta3

Comment 21

[leger]

Adding perf keyword

Comment 22

[David :Bienvenu]

David, here's the bug we talked about where it looks like the tree widget is
reflowing off-screen items. Whenever I break into the debugger, we're in layout.

Comment 23

[Peter Trudelle]

nsbeta3-, now takes about 7-8 seconds for 500 messages on a PII 366.  
Renominate if this makes markteting's short list of perf problems to fix.

Comment 24

[David :Bienvenu]

I think you should reconsider this. For one thing, you might ask Hyatt what he
thinks about the importance+cost of fixing this. It is an enormous performance
win for mail/news, for all sorts of operations (see for example 46515 - if you
make that nsbeta3+, then this should be nsbeta3+ as well), and I don't think
it's hard to fix. It's also a regression.

Comment 25

[Peter Trudelle]

okay, nsbeta3+ but lower priority.

Comment 26

[scottputterman]

*** Bug 30961 has been marked as a duplicate of this bug. ***

Comment 27

[David Hyatt]

Ok, I have fixed the problem in the tree view.  Now for me it isn't laying out 
the tree at all (which is good), but it's thrashing like mad in template builder 
code.  I'm re-assigning this to waterson for investigation, since the template 
builder code seems to be the source of the degradation now.

Comment 28

[David :Bienvenu]

*** Bug 46515 has been marked as a duplicate of this bug. ***

Comment 29

[Chris Waterson]

I profiled this. It turns out that mailnews is generating five notifications to 
four observers for each message that's being marked read (that's 20 
notifications per message). So marking 5000 messages read generated 100,000 
notifications to the XUL template builder.

Here are where the notifications are coming from:

  nsMsgFolderDataSource::NotifyFolderTreeNameChanged accounts for one
  nsMsgMessageDataSource::OnChangeStatusString accounts for two
  nsMsgMessageDataSource::OnChangeIsUnread accounts for one
  nsMsgFolderDataSource::OnUnreadMessagePropertyChanged is one

Can we reduce the fan-out here? It seems like we should be able to re-factor 
the observers (do four really need to be involved for each message update?). It 
also seems like we can reduce (or batch) the number of notifications that need 
to be sent to some of the observers (e.g., couldn't we just update the folders 
counts at the end?)

Reassigning to mailnews for further investigation.

Comment 30

[David :Bienvenu]

reassigning to putterman, though I'll look at it a bit - he's much more up to
speed on this stuff. This would be a good candidate for batching :-) My guess is
that the only thing we could cut out from the backend is the unread counts in
the folder pane, which I bet we're notifying on every mark read. Not sure why
there are two status string changes, and I'm not sure what folder tree named has
to do with anything.

Comment 31

[Alec Flett]

the two status string changes are
1) for the localized (english) "read" or "replied" string
2) for the style rule for "read" and "replied"` which is not localized


What I find odd is the number of notifications going around.
By my calculation there should be
4 folder observers, each of which should get one notification for each message, 
about the unread count changing. They are
  - folder pane
  - 2 menus (Move and Copy)
  - the file menu in the toolbar (thanks to waterson for reminding me of this 
one)
1 message observer (the thread pane) which should recieve 4 notifications
  - 2 status string
  - unread-count-per-thread
  - isunread status changing

so with this calculation, we should at most be seeing 1x4 + 4x1 = 8 
notifications happening, instead of the current 20 (1x4 + 4x4). 

On a side note, status string and unread are actually two different states... 
(one is if the message has actually been read, and one records other stuff like 
replied or forwarded.. putterman can elaborate)

Comment 32

[Chris Waterson]

"Batching" (as we'd discussed, by implementing [start|end] update brackets on
nsIRDFObserver) is going to be of little use in this case.

- The fan out is huge, so RDF is spending a lot of its time realizing that it
has nothing to do. (Actually, it's not spending that much time, but it's being
asked to do it a lot!)

- Where there are hits (the three odd attributes that need to be updated on each
of the thread pane's content nodes), RDF has to change the content model anyway.

But if you mean "batching" as in, we'll just tell the folder observers that the
count has changed once, then I'll agree with you.

Comment 33

[Alec Flett]

(the latter is what I meant by batching, when we were talking in IRC)

Comment 34

[scottputterman]

So, the folder name is because we currently display the folder as

Inbox (#Unread)

And the status string is twice because one string represents the display string 
for the status (read, replied, forwarded, etc) and the other represents a 
property that we use to style the message (is it bolded or not).

So, we had talked about doing this a long time ago. Currently we change the 
counts every single time because we don't do batching within mailnews.  We could 
eliminate some of the changing count notifications if we did batching ourselves 
and just didn't notify RDF until the operation was over.

Also, unread counts don't matter to any of the folder observers except for the 
folder pane.  If we could speed up determining that they don't need the 
notification, that could make some difference too.

Comment 35

[Chris Waterson]

Why do all four observers need to be notified of the message-level changes? 
Certainly the folder pane, two menus, and toolbar could care less if an 
individual message's "status" property is "unread"?

Comment 36

[scottputterman]

Like I said, the folder pane cares about whether or not an individual message is 
unread for display purposes.  Currently all of the observers on the folder 
datasource do not care about this, but we don't distinguish between observers. 
anyone who wants to be an observer on the folder datasource gets told about 
this.

Comment 37

[Chris Waterson]

Attachment: don't eagerly re-compute variable assignments

Comment 38

[Chris Waterson]

The above patch chops off about 15-20% of the time it takes to "Mark All Read". 
Of course, this is dropping the time to about 50 seconds from about 60 seconds 
on a 5,000 message newsgroup, so the performance is still way out. (And I think 
we need to continue with the ideas that scottip et. al. have had 
for notification reduction.)

Comment 39

[scottputterman]

I played around with this and tried commenting out the folder notifications that 
were just updating the count each time and the time to mark all read a 1000 
message local folder in my debug build went from 20 to 10 seconds.  When I added 
waterson's patch in it went to 8.5 seconds.  So, if in operations such as this 
we just notified about the changing folder counts at the end of the operation 
we'd see a big speed up.

One thing I think I was seeing is that when I marked an imap message read, I 
seemed to be getting 2 notifications from the db instead of the 1 I'm seeing in 
local folders.  

Comment 40

[Chris Waterson]

I checked in the patch, above, r=rjc.

Comment 41

[Alec Flett]

ok, I've done more research, and discovered a few things:
- we're leaking all 3 of our datasources for each window we open. This means
that they stick around as folder listeners, and recieve notifications from the
mail session on every folder update. This is bad but not hurrendous, because RDF
has removed all it's observers (so these leaked datasources never tell RDF about
these notifications)
- the folder datasource has 8 listeners as it turns out, and 2 notifications on
each... so instead of 4x4 it's 8x2.
- the thread pane only has 1 listener, which is correct, but there are alot of
notifications going on.
- there are also some biff state notifications going on that shouldn't be going
off at all - the result of a quick fix for beta2. I can't remember which DS it
affects though, probably the folder pane.

I'm taking a moment to clean up the leaks before proceding because these leaks
are really bad..I've already stopped us from leaking the folder datasource.

Comment 42

[johng]

Note this also causes serious problems when deleting lots of messages at one 
time.  In POP, I tried deleting several hundred email messages at one time 
9using pop, build 2000081608.  For awhile it worked, but very slowly.  Finally, 
though it kept "working", not even the console changed.  I think I started this 
over an hour ago.

See bug 46515 that was marked as dupe of this, but specifically talked about a 
freeze (which is what is still happening) when you try to delete too many 
messages.

Comment 43

[johng]

Attachment: console when stuck deleting lots of msgs

Comment 44

[scottputterman]

my portion of the fix checked in. I'm reassigning to bienvenu for the rest of 
the fix.  We should probably just nsbeta3- the rest of the work on this bug 
since we will probably not get to it for this release.

When bienvenu checks in the this should cut the time significantly.  On my 
machine 1000 messages went from 19s to 6s.

Comment 45

[David :Bienvenu]

I've checked in my part as well. I'm not sure what more we can do at this point.

Comment 46

[lchiang]

Would anyone mind if we minused this bug for any more work done?  Or, I think we 
can mark this fixed?

Comment 47

[David :Bienvenu]

I think we can just mark it fixed. Remaining performance problem is pretty
general and not specific to news mark all read :-(

Comment 48

[lchiang]

Pratik - can you do some timings on this?

Comment 49

[Pratik Dhupia]

Using build: 2000-08-30-08 M18 on Performance Machines
MAC : 14.12 sec
LINUX: 16.69 sec
WIN95: 11.10 sec

Verified: Fixed

Comment 50

[Pratik Dhupia]

BTW, the folder I tested on, had 500 new news messages.