227011 - Mailnews hangs when marking large amount of messages as read

Status: RESOLVED FIXED

(MailNews Core :: Database, defect)

Description

[Aleksander Adamowski]

I've got a folder with about 50000 messages, all of them unread (yes, that's the
same folder as in bug 226730 and bug 172786).

When I markall messages as read, it starts to consume all CPU and doesn't finish
(at least in satisfying amount of time).

Strace of Mozilla process reveals something interesting: if I understang the
strace correctly, Mozilla makes lots of lseek() calls the do nothing - they seek
to the current position in the file!

Look at this fragment:

     0.000109 read(31, "X-Mozilla-Status: 0000\nX-Mozilla"..., 49) = 49
     0.000139 lseek(31, 0, SEEK_CUR)    = 21156785
     0.000096 lseek(31, 0, SEEK_CUR)    = 21156785
     0.000091 lseek(31, 0, SEEK_END)    = 57705469
     0.000065 lseek(31, 21156785, SEEK_SET) = 21156785
     0.000021 lseek(31, 21156759, SEEK_SET) = 21156759
     0.000023 lseek(31, 0, SEEK_CUR)    = 21156759
     0.000020 lseek(31, 0, SEEK_CUR)    = 21156759
     0.000018 lseek(31, 0, SEEK_END)    = 57705469
     0.000019 lseek(31, 21156759, SEEK_SET) = 21156759
     0.000019 lseek(31, 21156736, SEEK_SET) = 21156736
     0.000051 lseek(31, 0, SEEK_CUR)    = 21156736
     0.000023 write(31, "X-Mozilla-Status: 0001", 22) = 22
     0.000049 lseek(31, 0, SEEK_CUR)    = 21156758
     0.000021 lseek(31, 0, SEEK_CUR)    = 21156758
     0.000018 lseek(31, 0, SEEK_END)    = 57705469
     0.000019 lseek(31, 21156758, SEEK_SET) = 21156758
     0.000019 lseek(31, 21156737, SEEK_SET) = 21156737
     0.000019 lseek(31, 0, SEEK_CUR)    = 21156737
     0.000020 read(31, "-Mozilla-Status: 0001\nX-Mozilla-"..., 49) = 49
     0.000032 lseek(31, 0, SEEK_CUR)    = 21156786
     0.000019 lseek(31, 0, SEEK_CUR)    = 21156786
     0.000019 lseek(31, 0, SEEK_END)    = 57705469
     0.000018 lseek(31, 21156786, SEEK_SET) = 21156786
     0.000019 lseek(31, 21156759, SEEK_SET) = 21156759
     0.000022 fsync(31)                 = 0
     0.018982 close(31)                 = 0
     0.001855 stat64("/home/olo/.mozilla/winda/4oali5gr.slt/Mail/Local
Folders-1/Admin.sbd/NMAIL Message Notifi
cations", {st_mode=S_IFREG|0644, st_size=57705469, ...}) = 0
     0.003865 stat64("/home/olo/.mozilla/winda/4oali5gr.slt/Mail/Local
Folders-1/Admin.sbd/NMAIL Message Notifi
cations", {st_mode=S_IFREG|0644, st_size=57705469, ...}) = 0
     0.004045 stat64("/home/olo/.mozilla/winda/4oali5gr.slt/Mail/Local
Folders-1/Admin.sbd/NMAIL Message Notifi
cations", {st_mode=S_IFREG|0644, st_size=57705469, ...}) = 0
     0.003930 _llseek(21, 0, [8557585], SEEK_CUR) = 0
     0.001852 fstat64(21, {st_mode=S_IFREG|0644, st_size=8557585, ...}) = 0
     0.001929 _llseek(21, 8557585, [8557585], SEEK_SET) = 0
     0.001846 _llseek(21, 8557585, [8557585], SEEK_SET) = 0
     0.001838 fstat64(21, {st_mode=S_IFREG|0644, st_size=8557585, ...}) = 0
     0.001932 _llseek(21, 8557585, [8557585], SEEK_SET) = 0
     0.001844 _llseek(21, 8557585, [8557585], SEEK_SET) = 0
     0.001875 fstat64(21, {st_mode=S_IFREG|0644, st_size=8557585, ...}) = 0
     0.001950 _llseek(21, 8557585, [8557585], SEEK_SET) = 0
     0.001851 _llseek(21, 8557585, [8557585], SEEK_SET) = 0
     0.001839 fstat64(21, {st_mode=S_IFREG|0644, st_size=8557585, ...}) = 0
     0.001933 _llseek(21, 8557585, [8557585], SEEK_SET) = 0


If I undertand the lseek() semantics correctly, the following call:

lseek(31, 0, SEEK_CUR)

does nothing, it seeks to +0 bytes relative to current position.

There are numerous seeks like this one visible in the syscall trace.

Backtrace from gdb looks like this:

#0  0x400af7e9 in PR_GetSpecialFD () from /usr/local/mozilla/libnspr4.so
#1  0x4009b81b in PR_Sync () from /usr/local/mozilla/libnspr4.so
#2  0x4118e461 in FileImpl::InternalFlush(int) () from
/usr/local/mozilla/libxpcom_compat.so
#3  0x4118e2e9 in FileImpl::Flush() () from /usr/local/mozilla/libxpcom_compat.so
#4  0x42df8084 in NSGetModule () from /usr/local/mozilla/components/libmsgdb.so
#5  0x42df6347 in NSGetModule () from /usr/local/mozilla/components/libmsgdb.so
#6  0x42dea9f0 in NSGetModule () from /usr/local/mozilla/components/libmsgdb.so
#7  0x42deaa9f in NSGetModule () from /usr/local/mozilla/components/libmsgdb.so
#8  0x42deb5a5 in NSGetModule () from /usr/local/mozilla/components/libmsgdb.so
#9  0x42dadfc7 in NSGetModule () from /usr/local/mozilla/components/libmailnews.so
#10 0x42daded3 in NSGetModule () from /usr/local/mozilla/components/libmailnews.so
#11 0x42da9b0b in NSGetModule () from /usr/local/mozilla/components/libmailnews.so
#12 0x42da91d0 in NSGetModule () from /usr/local/mozilla/components/libmailnews.so
#13 0x42da87d4 in NSGetModule () from /usr/local/mozilla/components/libmailnews.so
#14 0x40856a31 in XPTC_InvokeByIndex () from /usr/local/mozilla/libxpcom.so
#15 0x40e6416c in NSGetModule () from /usr/local/mozilla/components/libxpconnect.so
#16 0x40e69e33 in NSGetModule () from /usr/local/mozilla/components/libxpconnect.so
#17 0x40047e39 in js_Invoke () from /usr/local/mozilla/libmozjs.so
#18 0x4004f39f in js_Interpret () from /usr/local/mozilla/libmozjs.so
#19 0x40047e8e in js_Invoke () from /usr/local/mozilla/libmozjs.so
#20 0x40e5fdcd in NSGetModule () from /usr/local/mozilla/components/libxpconnect.so
#21 0x40e5b8af in NSGetModule () from /usr/local/mozilla/components/libxpconnect.so
#22 0x40856be0 in XPTC_InvokeByIndex () from /usr/local/mozilla/libxpcom.so
#23 0x40856a31 in XPTC_InvokeByIndex () from /usr/local/mozilla/libxpcom.so
#24 0x40e6416c in NSGetModule () from /usr/local/mozilla/components/libxpconnect.so
#25 0x40e69e33 in NSGetModule () from /usr/local/mozilla/components/libxpconnect.so
#26 0x40047e39 in js_Invoke () from /usr/local/mozilla/libmozjs.so
#27 0x4004f39f in js_Interpret () from /usr/local/mozilla/libmozjs.so
#28 0x40047e8e in js_Invoke () from /usr/local/mozilla/libmozjs.so
#29 0x4004809b in js_InternalInvoke () from /usr/local/mozilla/libmozjs.so
#30 0x40029074 in JS_CallFunctionValue () from /usr/local/mozilla/libmozjs.so
#31 0x4140a00a in NSGetModule () from /usr/local/mozilla/components/libjsdom.so
#32 0x4143b4a5 in NSGetModule () from /usr/local/mozilla/components/libjsdom.so
#33 0x40d15d3f in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#34 0x40d135c2 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#35 0x40d13d38 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#36 0x40d13de9 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#37 0x40be786c in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#38 0x40bea5a3 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#39 0x40d28cd8 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#40 0x40d6dd24 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#41 0x40d6dcf5 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#42 0x40d6dcf5 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#43 0x40d6dcf5 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#44 0x40d6dcf5 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#45 0x40d6dcf5 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#46 0x40d6dcf5 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#47 0x40d6dcf5 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#48 0x40d6dcf5 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#49 0x40a81ec9 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#50 0x40a81ac0 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#51 0x40d47351 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#52 0x40d4009c in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#53 0x40d46c7a in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#54 0x40d3f922 in NSGetModule () from /usr/local/mozilla/components/libgklayout.so
#55 0x411617f4 in parent_class_set_focus () from
/usr/local/mozilla/components/libwidget_gtk.so
#56 0x411616df in parent_class_set_focus () from
/usr/local/mozilla/components/libwidget_gtk.so
#57 0x4115f6e2 in parent_class_set_focus () from
/usr/local/mozilla/components/libwidget_gtk.so
#58 0x4115b8a4 in parent_class_set_focus () from
/usr/local/mozilla/components/libwidget_gtk.so
#59 0x4115bea9 in parent_class_set_focus () from
/usr/local/mozilla/components/libwidget_gtk.so
#60 0x4115bcee in parent_class_set_focus () from
/usr/local/mozilla/components/libwidget_gtk.so

Comment 1

[Aleksander Adamowski]

Attachment: Log of several backtraces in gdb plus a short strace

Comment 2

[Aleksander Adamowski]

Attachment: A long strace; compressed with BZip2 (uncompressed has 861K size)

Comment 3

[Aleksander Adamowski]

One more detail: I 've just realised that I always mark messages as read using
the "R" key, which is actually "Mark thread as read".

So basically I've selected all messages and marked thread as read. This bug may
be related to bug 226730 anyway...

Moreover, when I click on Mozilla MailNews's close button, it eventually closes
(after a long delay) and broser runs fine.

When I completely close Mozilla and enter the problematic folder, all messages
are indeed marked as read, so the marking processa apparently did its job.

Comment 4

[Aleksander Adamowski]

May be important:
I still have this pref set to false:

user_pref("mail.thread_without_re", false);

And all messages in the folder have tha same subject, but it doesn't start with
"Re:".

So Mozilla doesn't thread them (or at least isn't supposed to).

Comment 5

[Oliver Klee]

Sorry, didn't mean to set this as a blocker.

Comment 6

[David :Bienvenu]

it's not a hang; it's just slow. A hang implies an infinite loop, whereas we're
just spending a lot of time updating your berkeley mailbox folder and the
x-mozilla-status lines of all the messages getting deleted. I'm changing the
severity as well - marking 50,000 messages as read is not a normal operation.

Comment 7

[Aleksander Adamowski]

David, that deleting problem from bug 226730 was probably a problem of the OS
with large files (the mbox file had 120 MB). So a red herrging probably, and bug
226730 is about slow threading anyway.

This bug, however, is about a hang when marking all threads in that large folder
as read. Even when pref mail.thread_without_re is set to false.

It really looks like a hang - on all messages in the folder, marking thread as
read runs much longer than a succesfull delete of majority of messages in that
folder, and still doesn't end.

But after a restart of Mozilla, all messages are in "read" state in that folder.
So the operation seems to have finished, then enter an infinite loop (or
semi-infinite, I didn't have time to check if it would exit that operation after
a couple of hours)... The folder now has only only 50000 messages and deleting
most of them takes about one minute. Marking as read operation had run for half
an hour before I made strace and gdb logs and closed Mozilla.

Strace shows Mozilla executing large amounts of system calls that do nothing and
are probably incorrect.

I can't determine anything more, as I have no knowledge of Mozilla's internal
architecture and code...

Comment 8

[David :Bienvenu]

I think we're doing a lot of db commits - I hear a lot of disk thrashing when I
try this. I'll investigate.

Comment 9

[David :Bienvenu]

Attachment: proposed fix

this will speed up mass operations on local messages enormously (other than
delete, which is already taken care of). It uses batching to avoid committing
the db for every message, and keeps the local mailbox folder stream open across
messages, which also speeds things up.

Comment 10

[Aleksander Adamowski]

That would be wonderful - I'll test as soon as possible after it gets checked in.

Comment 11

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

Comment on attachment 136503 [details] [diff] [review]
proposed fix

r/a=sspitzer

Comment 12

[David :Bienvenu]

fix checked in; please try tomorrow's build

Comment 13

[Aleksander Adamowski]

I've installed build 2003120209.

The performance and responsiveness improvement is amazing!

I've performed several tests on the original version of that "NMAIL Message
Notifications" folder, which has about 75400 messages and its mbox file has a
size of 160MB.

1) Building summary file for that folder doesn't cause a hang, and on my machine
it progresses at about 200 messages/sec. Status bar is correctly updated during
that operation ("Building summary file for folder_name", "Unread: 67686",
"Total: 67686") so I can finally see that Mozilla is doing something useful and
assess how much time is remaining.

Rebuilding summary for the whole folder took about 400 seconds.

2) Marking all messages as read took only 106 seconds!
Unfortunately, Mozilla was unresponsive during that operation.

3) Deleting works much better too, but there are 2 visible phases:

I've performed a test by deleting half of messages from that folder. During the
first phase Mozilla was responsive and was updating properly the status bar
text, which displayed "Moving XXXXX of 38105 messages to Trash". It took about
60 seconds. During the seconde phase Mozilla became unresponsive, which could be
perceived as a hang by the user. It took about 90 seconds.

4) Drag and drop

When I've entered Trash, selected all messages and moved all those messages back
to the origin folder ("NMAIL Message Notifications"), there was another
responsiveness issue: during the drag move, between the click on selected
messages and drop on the origin folder, there was a 12 second period during
which Mozilla was completely unresponsive. I had to click on one of selected
messages, move the mouse, wait 12 seconds until the drag'n'drop icon appears
next to mouse cursor, then point to the destination folder and release the mouse.

Ordinary user might not be able to infer that this is necessary.

5) Moving

Moving those 38000 mails from Trash back to the origin folder ("NMAIL Message
Notifications") was the most costly operation (10 minutes), during which Mozilla
was completely unresponsive.

6) Compacting

Compacting after both moving operations ("NMAIL Message Notifications" ->
"Trash"; "Trash" -> "NMAIL Message Notifications") took reasonable time (about 1
minute), and Mozilla was responsive during that operation.


   Summary

In short, incredibly great improvement (especially considering how small the
patch was :) )!

But there are still issues with responsiveness uder some circumstances.

Comment 14

[Aleksander Adamowski]

During those unresponsive states Mozilla updates the X-Mozilla-Status headers.

Here's a fragment of strace made during marking as read:

     0.000000 write(25, "X-Mozilla-Status2: 00000000", 27) = 27
     0.002235 lseek(25, 0, SEEK_CUR)    = 108648288
     0.001841 lseek(25, 0, SEEK_CUR)    = 108648288
     0.001801 lseek(25, 0, SEEK_END)    = 169382433
     0.001797 lseek(25, 108648288, SEEK_SET) = 108648288
     0.001895 lseek(25, 127885099, SEEK_SET) = 127885099
     0.001838 lseek(25, 0, SEEK_CUR)    = 127885099
     0.001811 read(25, "X-Mozilla-Status: 0000\nX-Mozilla"..., 49) = 49
     0.001935 lseek(25, 0, SEEK_CUR)    = 127885148
     0.001814 lseek(25, 0, SEEK_CUR)    = 127885148
     0.001798 lseek(25, 0, SEEK_END)    = 169382433
     0.001759 lseek(25, 127885148, SEEK_SET) = 127885148
     0.001818 lseek(25, 127885122, SEEK_SET) = 127885122
     0.001831 lseek(25, 0, SEEK_CUR)    = 127885122
     0.001815 lseek(25, 0, SEEK_CUR)    = 127885122
     0.001797 lseek(25, 0, SEEK_END)    = 169382433
     0.002233 lseek(25, 127885122, SEEK_SET) = 127885122
     0.001829 lseek(25, 127885099, SEEK_SET) = 127885099
     0.001866 write(25, "X-Mozilla-Status: 0001", 22) = 22
     0.001913 lseek(25, 0, SEEK_CUR)    = 127885121
     0.001816 lseek(25, 0, SEEK_CUR)    = 127885121
     0.001831 lseek(25, 0, SEEK_END)    = 169382433
     0.001809 lseek(25, 127885121, SEEK_SET) = 127885121
     0.001885 lseek(25, 127885122, SEEK_SET) = 127885122
     0.001856 lseek(25, 0, SEEK_CUR)    = 127885122
     0.001816 read(25, "X-Mozilla-Status2: 00000000\nTo: "..., 49) = 49
     0.002351 lseek(25, 0, SEEK_CUR)    = 127885171
     0.002041 lseek(25, 0, SEEK_CUR)    = 127885171
     0.001809 lseek(25, 0, SEEK_END)    = 169382433
     0.001797 lseek(25, 127885171, SEEK_SET) = 127885171
     0.001803 lseek(25, 127885150, SEEK_SET) = 127885150
     0.001836 lseek(25, 0, SEEK_CUR)    = 127885150
     0.001932 lseek(25, 0, SEEK_CUR)    = 127885150
     0.001832 lseek(25, 0, SEEK_END)    = 169382433
     0.001802 lseek(25, 127885150, SEEK_SET) = 127885150
     0.001824 lseek(25, 127885122, SEEK_SET) = 127885122
     0.002149 write(25, "X-Mozilla-Status2: 00000000", 27) = 27

Comment 15

[Aleksander Adamowski]

Attachment: Fragment of strace from marking as read

This strace was made while Mozilla was unresponsive.

Comment 16

[Aleksander Adamowski]

Attachment: Strace from phase 2 of moving messages to Trash

This strace was made while Mozilla was unresponsive.

Comment 17

[David :Bienvenu]

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

Comment 18

[Asa Dotzler [:asa]]

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