452221 - When many mails have the same subject (e.g. very long thread), time to take Shift+Delete of all mail seems to be O(num_of_mail**2), and "CPU 100% by the Shift+Delete" locks UI while delete operation

Status: NEW

(MailNews Core :: Database, defect)

Description

[WADA:World Anti-bad-Duping Agency]

When all mails has same subject(i.e. very long thread), time to take Shift+Delete of all mail seems to be O(num_of_mail**2), and "CPU 100%" by the Shift+Delete locks UI while delete operation.

This bug is for issues observed while test for problem of Bug 296453.
Tested with Tb latest-trunk on Win-XP SP3, on Core2Duo, T5500 @ 1.66GHz, 981 MHz, 0.99GB RAM.
> Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1a2pre) Gecko/20080825031404 Shredder/3.0b1pre

[Test Procedure]
1. Unzip attached file, and copy unzipped files to Tb's mail directory.
2. Restart Tb, and check four mail folders. (with single Tb window only)
   Rebuild index ends within reasonable time.
   Four mail folders: 4000 mails, 8000 mails, 16000 mails, 32000 mails.
   Mail subject of all mails in a mail folder is same(==very long thread)
3. Create mail folder of X-04000, X-08000, X-16000, X-32000
4. Copy mails to X-04000, X-08000, X-16000, X-32000
   Copy speed is very fast.
5. "CTRL+A" & "Shift+Delete" at each mail folder

[Test Result]
X-04000 : "Shift+Delete" of  4000 mails took less than 10 seconds
X-08000 : "Shift+Delete" of  8000 mails took  25 seconds
X-16000 : "Shift+Delete" of 16000 mails took 100 seconds
X-32000 : "Shift+Delete" of 32000 mails took 430 seconds

(A) While execution of "Shift+Delete", CPU 50%(because Core2Duo) was observed.
(B) While execution of "Shift+Delete", UI was locked.
    - Click of other folder prodecues "sandglass" only.
    - Other click of folder prodecued "Unresponsive" message.
    No other UI action was possible while "Shift+Delete" execution.

CPU 100%(50% when Dual Core) at first step of Shift+Delete itself is one of evidences of good efficiency in chaging X-Mozilla-Status: header data of deleted mails.
However, following two issues are critical, and I think these are some of causes of Bug 296453.
  (Prob-1) O(mail_count**2) of time to execute Shift+Delete.
           CPU 100%(50% when Dual Core) continues until end of Shift+Delete.
  (Prob-2) Unresponsiveness(UI lock) while long "Shift+Delete" execution. 

I think (Prob-1) is similar issue to (a) Rebuild Index takes long when long thread, (b) View/Thread takes long when long thread.
I think (Prob-2) is same issue as UI lock while re-sync of big IMAP mail folder, while mail folder open of very very huge mail folder.

Comment 1

[WADA:World Anti-bad-Duping Agency]

Note-1:
In above test, virtual memory size increase was not observed. It is possibly due to  "no need of Undo delete(or move)" when Shift+Delete.
Note-2:
Same result(shift+delete took same time) was obtained with Thunderbird 2.0.0.14.
Note-3:
If all 16000 mails has different subject(16000 threads with length=1, no In-Reply-To: Header), Shift+Delete ended in 6 to 8 seconds. (both Tb 2.0.0.14 & Tb trunk)

CC-ing to Andrew Sutherland who is owner of 296453.

Comment 2

[WADA:World Anti-bad-Duping Agency]

Attachment: Test Case 01: Mail folder files of 4000,8000,16000 mails. Newest mail is placed at lowest(=0) off-set. No In-Reply-To:

This is mail folder files for test of Comment #0.
  - Mail folder files of 4000,8000,16000 mails.
    (folder of 32000 mails is not contained, due to size limit of Bugzilla) 
  - All mails has same subject(single long thread).
  - Newest mail is placed at highest off-set.
  - No In-Reply-To: header exists.

Comment 3

[WADA:World Anti-bad-Duping Agency]

Correction about test case 01. Sorry for spam.
  (Correct) - Newest mail is placed at lowest off-set(=0).
  (Wrong)   - Newest mail is placed at highest off-set.

Comment 4

[WADA:World Anti-bad-Duping Agency]

Attachment: Test Case 02: Mail folder files of 250,500,1000,2000 mails. Newest mail is placed

This is mail folder files for test case 02.
  - Mail folder files of 250,500,1000,2000 mails.
  - All mails has same subject(single long thread).
  - Newest mail is placed at highest off-set. (normal order)
  - No In-Reply-To: header exists.

[Test Result of test case 02]
Y-00250 : "Shift+Delete" of  250 mails took   4 seconds
Y-00500 : "Shift+Delete" of  500 mails took  17 seconds
Y-01000 : "Shift+Delete" of 1000 mails took  65 seconds
Y-02000 : "Shift+Delete" of 2000 mails took 260 seconds
(I did 4000,8000,16000 cases, but I killed Tb because I couldn't wait)

I was convinced that test case 01(newest is placed at lowest offset. reversed order) was worst case, so I tested with "reversed order" first.
But it seems to be wrong. Test case 01 looks to be best/lucky case.
Test case 02(newest is placed at highest offset, normal order) was worst case.
This can explain why users experienced "long time to delete" even when delete of not-so-big-number-of-mails.

Comment 5

[Dan Mosedale (:dmosedale, :dmose)]

There's a patch for this in bug 296453, which I'd like to start dealing with here.  Reassigning to asuth and marking appropriately.

Comment 6

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

Attachment: de-rotted topological sort from 296453

My topo-sort patch from bug 296453.  This is my un-bitrotted version, but I think it turns out to be the same as Ben's de-rotting as well.

Comment 7

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

Attachment: test for the topo-sort delete logic

Unit test for the topological sort.  Note that messageGenerator.js currently also lives in my gloda repository (and is used by gldoa), but this patch would give it its permanent home.

Comment 8

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

Comment on attachment 337275 [details] [diff] [review]
test for the topo-sort delete logic

(It is quite clear that bugzilla just gives up if it can't fight a matching requestee rather than prompting...)

Comment 9

[David :Bienvenu]

Comment on attachment 337273 [details] [diff] [review]
de-rotted topological sort from 296453

I think I should review this...

Comment 10

[Mark Banner (:standard8)]

Comment on attachment 337275 [details] [diff] [review]
test for the topo-sort delete logic

+const NS_ERROR_NOT_INITIALIZED = 0xc1f30001;

Rather than doing this you can use:

Components.results.NS_ERROR_NOT_INITIALIZED

wherever you need it.

+function random_permute_array (aItems) {

I'm a bit concerned about the randomness here. If we start getting random results it will be hard to debug.

Comment 11

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

(In reply to comment #10)
> +const NS_ERROR_NOT_INITIALIZED = 0xc1f30001;
> 
> Rather than doing this you can use:
> 
> Components.results.NS_ERROR_NOT_INITIALIZED
> 
> wherever you need it.

Thank goodness!

> +function random_permute_array (aItems) {
> 
> I'm a bit concerned about the randomness here. If we start getting random
> results it will be hard to debug.

So, in some gloda testing I have a function that deterministically permutes an array based on a single parameter.  Would it be okay to use something like that if we print out the random parameter for reproducibility?

What I was actually going for was a fairly shuffled arrangement of the messages with the minimal amount of required coding.  Bit of a cop-out, really.  Random seemed acceptable as we should indeed handle any permutation of the input stream, even if we can't test them all at once (ever).

Comment 12

[Dan Mosedale (:dmosedale, :dmose)]

It seems like we have to make a trade-off between "test coverages" and "matches our workflow".  If the test is completely deterministic (uses the same initializing parameter on every run), it has the advantage of playing well with Tinderboxen: ie a Tinderbox turns orange and stays orange until this is fixed.  Having it be random seems like a recipe for often-unlikely-to-get-debugged Tinderbox orangeness.  Maybe a reasonable compromise would be to run it some small number of times (3 or 4) with a known, static set of initializers?

Comment 13

[Mark Banner (:standard8)]

Since this is already blocking TB 3, and it has a patch, we should drive it forward and beta 1 seems like a good target.

Comment 14

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

(In reply to comment #12)
> our workflow".  If the test is completely deterministic (uses the same
> initializing parameter on every run), it has the advantage of playing well with
> Tinderboxen: ie a Tinderbox turns orange and stays orange until this is fixed. 

Oh, right, tinderboxen.  I'll make the test deterministic.  But since that's a trivial fix, I'm going to just treat that as a review action item.  It will go in the next patch.  Reviewers should not consider it blocking them (unless they want to, in which case just r- and you get a new patch.)

Comment 15

[Mark Banner (:standard8)]

Comment on attachment 337275 [details] [diff] [review]
test for the topo-sort delete logic

I think we need some overall documentation for messageGenerator.js. It seems like it could be useful for various tests, however, I can't see how I easily use it.

So I'd like to see some documentation at the start of the file, maybe even expanding it on https://wiki.mozilla.org/MailNews:Home_Page#Automatic_Testing

For example:
- MessageScenarioFactory is at the bottom of the file (I'm fine with this) but is actually the main driver from what I can tell and there is writeMessagesToMbox that also looks to be a useful function, but could easily be missed.

Does writeMessagesToMbox need to be called with a folder where the db is closed? and then somehow carefully re-opened after that? If so, would be worth documenting as well.

Comment 16

[Dan Mosedale (:dmosedale, :dmose)]

We wouldn't actually block b1 on this; moving out.

Comment 17

[Dan Mosedale (:dmosedale, :dmose)]

Comment on attachment 337275 [details] [diff] [review]
test for the topo-sort delete logic

This patch is already review minus; please re-request review once the new test is ready.

Comment 18

[Dan Mosedale (:dmosedale, :dmose)]

Comment on attachment 337273 [details] [diff] [review]
de-rotted topological sort from 296453

My understanding from a discussion last week is that we think it will be possible to get this bug landed more quickly with a patch that uses a different strategy than this one.  Andrew, is that correct?  If so, what's your preferred strategy.  If not, please re-request the reviews that I just removed.  I also suspect this doesn't really block beta 2, though it would be nice to get it.

Comment 19

[Dan Mosedale (:dmosedale, :dmose)]

And, hey, somebody already moved it to not block beta2 and I just didn't notice.  :-)

Comment 20

[Zach Forsyth]

If you have folders with large amounts of e-mail with the same subject (i.e. from an automated alert system), this bug makes Thunderbird nearly unusable.  Currently I have no other choice but to go to a Windows machine to empty out these folders in Outlook which is very unpalatable.

Comment 21

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

(In reply to comment #18)
> My understanding from a discussion last week is that we think it will be
> possible to get this bug landed more quickly with a patch that uses a different
> strategy than this one.  Andrew, is that correct?  If so, what's your preferred
> strategy.  If not, please re-request the reviews that I just removed.  I also
> suspect this doesn't really block beta 2, though it would be nice to get it.

(responding to out-of-band poke by Wayne)

I think my comment in the discussion was that reviewing an implementation of a topological sort was probably not going to happen for that beta and that simply changing the order of deletion would generally make the problems go away.  I think the right solution continues to be a topological sort because only a topological sort is guaranteed to avoid worst-case behavior.

Unless someone else beats me to it, I will de-rot the patch in the beta4 or rc1 timeline and fix up its unit test.

nb: This problem has been largely mitigated by changes to the (default) threading logic in thunderbird, so the probability of encountering this problem has been greatly reduced, which is why this keeps slipping out.

Comment 22

[Wayne Mery (:wsmwk)]

thanks Andrew.
updating whiteboard (remove needs reviews)
can be as bad as hang, so updating severity and keyword.
 (memory jumped from 70meg to 350meg and we're at 100% cpu)

tested on a local folder "mess" of 37k messages all same subject - for testing some bug I am sure, but don't recall which one.

Comment 24

[WADA:World Anti-bad-Duping Agency]

FYI.
Bug 218075 is found for slowness/UI freeze in "Mark as deleted model" + "EXPUNGE of many mails" of IMAP. Tb can't control order of EXPUNGE responses, so solution proposed by this bug can't be applicable to that bug. But, if Bug 218075 will be resolved, I think this bug will be probably resolved or impact of slowness in this bug will be reduced very much.

Comment 25

[David Ascher (:davida)]

The threading logic now doesn't trigger this bug nearly as often, so we can take this off blocking.

Comment 26

[WADA:World Anti-bad-Duping Agency]

(In addiion to comment #0)
>   (Prob-1) O(mail_count**2) of time to execute Shift+Delete.
>            CPU 100%(50% when Dual Core) continues until end of Shift+Delete.
>   (Prob-2) Unresponsiveness(UI lock) while long "Shift+Delete" execution. 
> I think (Prob-1) is similar issue to (a) Rebuild Index takes long when long
> thread, (b) View/Thread takes long when long thread.
>(snip)

Bug 226730 was found for (a).

Comment 27

[WADA:World Anti-bad-Duping Agency]

Woops. Bug 226730 was found for (a) and (b).

Comment 28

[Wayne Mery (:wsmwk)]

The attached two test files do not work for me, they do not display or index.

I'm not sure this is still an issue.