1055077 - JSMime header parsing makes quick filter slow

Status: NEW

(MailNews Core :: MIME, defect)

Description

[Wayne Mery (:wsmwk)]

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

This has bothered me for a few weeks and I tracked the regression range to probably bug 858337 (build 20140604 is good, 20140605 is slow). 

My Inbox is ~4,000 messages. type "test" brings 244 hits.
On my fairly beefy work desktop:
20140604 instantaneous response and CPU usage <1sec
20140605 3-5 sec response and 3-5 sec CPU usage, and an annoying choppiness to the display of results

Comment 1

[Wayne Mery (:wsmwk)]

Profiled with 2014-08-22 nightly build.  This has been an excruciating exercise because I can't get upload the full profile run of 10 seconds to mozilla for the 4k message Inbox folder because the profile is >9mb.  Too much data, for 10 seconds!

So I profiled the last few seconds of quick search - with profiler off I pasted the "phpmyadmin" in quicksearch, waited a few seconds, and then enabled profiler for the last few seconds - http://people.mozilla.org/~bgirard/cleopatra/?1408741199883#report=04abac43e1c513ebc324d7a7e3b8c1e8ee3bdc84

20% of time is in getHeaderTokens() jsmime.js:317

Smaller folders do not seem to have quite the same profile:
* 2k messages - http://people.mozilla.org/~bgirard/cleopatra/?1408740691944#report=9096cbfffca464dd353b1c6913e5b1705147e5cc
* 1k messages - http://people.mozilla.org/~bgirard/cleopatra/?1408738063795#report=40c47833d3f9b0b727780047f652d0fbca12279b

Now, 20% of 10 seconds in getHeaderTokens by itself doesn't explain why quick search time increased 5-fold (10 seconds in profiler, about 5 seconds when not profiling)

Comment 2

[Kent James (:rkent)]

Great work, Wayne!

The fear I have had with the move to javascript everywhere is that we would see serious performance regressions.

Comment 3

[Wayne Mery (:wsmwk)]

I have more info to come along those lines.

Comment 4

[Joshua Cranmer [:jcranmer]]

(In reply to Wayne Mery (:wsmwk) from comment #1)
> 20% of time is in getHeaderTokens() jsmime.js:317

I was somewhat expecting this--I've been told that generators are not great performance-wise, and it looks like this is a performance bottleneck. I'll talk with JS people to see what their plans are for optimizing generators.

Comment 5

[Wayne Mery (:wsmwk)]

Attachment: bug 1055077 bailouts.png

This shows one of my profiles, which I could not save, with a very high percentage is "bailout".

Comment 6

[Joshua Cranmer [:jcranmer]]

Converting headerparser.getTokenHeaders to return an array instead of a generator improves speed from ~6K headers/sec to ~14K headers/sec on my machine, according to a prototype microbenchmark I wrote. That alone is something like a 10-20% overall speedup on your profiles.

[I used 12-13K headers extracted from some email list archives I have. The headers were anonymized by by randomly rotating letters and numbers. RFC 2047 is very rare in this set (only a few hundred), and I have no non-ASCII 8-bit headers.]

Comment 7

[Philipp Kewisch [:Fallen][☁️📆]]

This is really annoying btw. For years I have been able to hold thousands of emails in my folders and searching was instant. Now even for 1000 emails it takes a noticable time. I've worked around by setting up archiving for at least my inbox and going down to only showing mails of the last 2-3 months, but this isn't ideal.

Comment 8

[Joshua Cranmer [:jcranmer]]

I have a patch for this on bug 1005413.

Comment 9

[alta88]

No lesson at all was learned from Bug 418551.  Back then, though, we had adult supervision (product management) and the change was not allowed and no users were harmed.

And no lesson has been learned from mconley's well documented description of the extreme attention to perf and rework required before Australis was allowed to continue.  It's clear if someone had skipped up gloating of a 20% giveback as the solution to an Australis regression, it would have been laughable.

(In reply to Joshua Cranmer [:jcranmer] from comment #8)
> I have a patch for this on bug 1005413.

HAHAHA, that's wholly inadequate, nor anything but alleged.  Clearly, no perf testing was done here at all.  This pattern of post fact analysis isn't the way to go.  Plus, Bug 858337 seems to have landed despite standard8's issue and non r+, what's going on here?

Anyone thinking jsmime is going to acceptably perf compete with compiled code (on other that single mail parsing) will be disappointed.  It can't handle a few thousand records and is unlikely to have been tested on 100k.  Add to that the apparent need to reindex gloda - this was an enourmous user issue last time it was done.

IMO jsmime should be backed out until it's proven near perf equivalent.  Why are we allowing such crapification of Thunderbird?

Comment 10

[Joshua Cranmer [:jcranmer]]

(In reply to alta88 from comment #9)
> (In reply to Joshua Cranmer [:jcranmer] from comment #8)
> > I have a patch for this on bug 1005413.
> 
> HAHAHA, that's wholly inadequate, nor anything but alleged.  Clearly, no
> perf testing was done here at all.

Please stop spreading lies. I in fact took the time out of my schedule to extract a corpus of headers to use for testing, build a millibenchmark to estimate parsing time, attempt to build a reliable performance testing suite (with the help of people in #jsapi), and even try to get Ion dumps of assembly code for proper microoptimization. I'm not going to claim that the patch does not fix everything, but it is a substantial improvement by itself.

> Plus, Bug 858337 seems to have landed despite standard8's
> issue and non r+, what's going on here?

There were discussions over IRC that are not reflected in the bug.

If you want to be productive, then by all means, I would welcome your help in building a performance test suite to catch performance regressions. It would be a load off of my back to have one less thing I have to juggle. But if all you're going to do is snipe, then please leave. It would let me do more productive work in actually fixing the problems.

Comment 11

[rsx11m]

Quite likely related, we also see this issue in current SeaMonkey releases (given that JSMime is MailNews Core code, that wouldn't be surprising and matches the regression window reported here, although the QFB design itself differs between TB and SM).

Bug 1067972 - slow "Search Subject or Adress" process after upgrade to SM 2.29 (Gecko 32).

Comment 12

[alta88]

(In reply to Joshua Cranmer [:jcranmer] from comment #10)
> (In reply to alta88 from comment #9)
> > (In reply to Joshua Cranmer [:jcranmer] from comment #8)
> > > I have a patch for this on bug 1005413.
> > 
> > HAHAHA, that's wholly inadequate, nor anything but alleged.  Clearly, no
> > perf testing was done here at all.
> 
> Please stop spreading lies. I in fact took the time out of my schedule to
> extract a corpus of headers to use for testing, build a millibenchmark to
> estimate parsing time, attempt to build a reliable performance testing suite
> (with the help of people in #jsapi), and even try to get Ion dumps of
> assembly code for proper microoptimization. I'm not going to claim that the
> patch does not fix everything, but it is a substantial improvement by itself.

Your own evidence disputes this, regardless of whether you want to call someone's pointing it out a lie.  20% is not substantial, but, as I said, wholly inadequate.  Post facto tests, etc.  Maybe you can post some profiler results.

Oh, and you're the master of all caps guffaws, shall I footnote the numerous places?

> 
> > Plus, Bug 858337 seems to have landed despite standard8's
> > issue and non r+, what's going on here?
> 
> There were discussions over IRC that are not reflected in the bug.
> 
> If you want to be productive, then by all means, I would welcome your help
> in building a performance test suite to catch performance regressions. It
> would be a load off of my back to have one less thing I have to juggle. But
> if all you're going to do is snipe, then please leave. It would let me do
> more productive work in actually fixing the problems.

I'm going to neither leave nor accept your defacto loading of nonperformant code
just because you want to.  Your entire premise is flawed.  Have you or have you not tested with 100k records?

(In reply to Joshua Cranmer [:jcranmer] from comment #4)
> (In reply to Wayne Mery (:wsmwk) from comment #1)
> > 20% of time is in getHeaderTokens() jsmime.js:317
> 
> I was somewhat expecting this--I've been told that generators are not great
> performance-wise, and it looks like this is a performance bottleneck. I'll
> talk with JS people to see what their plans are for optimizing generators.

This reads like comedy.  Perhaps you can get smedberg and dolske to up the prio for you, eh?

Comment 13

[Joshua Cranmer [:jcranmer]]

I landed the change from generators last night, so it should be in the nightly. It missed the Aurora uplift, though. If you try the latest nightly, how bad is it still?

Comment 14

[Joshua Cranmer [:jcranmer]]

(ni'ing wsmwk to remind him to upload a profile that has the recent changes).

Comment 15

[Wayne Mery (:wsmwk)]

2014-10-23 daily build, Inbox, 4k message, warm folder (not first time entering folder), laptop, ~25% CPu in use by music player, not in safe mode, filter on "test", times NOT via stopwatch:

- recipient+sender+subject  (<5sec, 225 hits) http://people.mozilla.org/~bgirard/cleopatra/?1414243934911#report=e1dca35ebe3369ff209382fa959f1f96336be903
- subject only (<2sec, 216 hits) http://people.mozilla.org/~bgirard/cleopatra/?1414244158168#report=3539a2fd8d9cf12113b86faf1e984c3311e53a3c
- recipient+sender (<4sec, 17 hits) http://people.mozilla.org/~bgirard/cleopatra/?1414244402251#report=3cee87481dbfb9364ea0cf202c20f85d3194a326

Comment 16

[Joshua Cranmer [:jcranmer]]

(In reply to Wayne Mery (:wsmwk) from comment #15)
> - subject only (<2sec, 216 hits)
> http://people.mozilla.org/~bgirard/cleopatra/
> ?1414244158168#report=3539a2fd8d9cf12113b86faf1e984c3311e53a3c

So the jsmime portion of this profile is rather slim, at most 10-20%. The profile is rather flat (PR_Now is at the top of the inverted callstack!). There are some easy wins, it looks like, from avoiding UTF-8-to-UTF-16 conversions: we convert the UTF-16 result to UTF-8 and then right back into UTF-16. If I make the search terms convert to UTF-16 and match on that, that should be a worthwhile gain.

Another possible improvement would be finding ways to avoid doing the conversion altogether, or somehow caching the result. The fact that we're doing a .sort() does suggest we could be doing some caching, but we're not accessing the methods in an easy way to implement caching (and I don't want to encourage using Mime2Decoded* methods--they're all sorts of levels of subtly wrong). Structured headers for the message database could effectively cache this sort of stuff, but... there's a lot of details to work out about eager/lazy parsing of stuff.

We could avoid going through nsIMimeConverter (and xpconnect) if we detect that said method would do nothing. For an en-US build, this is the common case, but it would hurt performance in the situation for non-ASCII headers. However, for the subject header, we could probably get around that by rejiggling the code to do RFC 2047 decoding on header creation instead on every damn time we're using the header. This wouldn't improve existing headers, but as people reindex their folders or get new headers, it would improve the situation.

> - recipient+sender+subject  (<5sec, 225 hits)
> http://people.mozilla.org/~bgirard/cleopatra/
> ?1414243934911#report=e1dca35ebe3369ff209382fa959f1f96336be903

Over here, I see fixArray is fairly expensive. Considering that I expect toString is rather little called (which is the main point of fixArray), I suspect I can probably make this much cheaper by using proxies for toString instead of resetting prototypes. It's a bit nasty to code, but it should improve performance.

The jsmime header parsing logic is still hot code though, and it's less amenable to avoid-doing-it-at-all tricks like the subject header. Although we might be able to cheat and make the search code work by just doing a mime decoding and search for the string in the header instead of parsing the header. This doesn't apply for IsInAB searches, though.

I'll ask Benoit for help in disecting the actual JS code here when I get the time. But first, I'll file bugs on the other, easier wins.

Comment 18

[Wayne Mery (:wsmwk)]

Would you say bug 1089298 is the easiest significant win?
And what might be the next best one to attack?

Comment 19

[Joshua Cranmer [:jcranmer]]

(In reply to Wayne Mery (:wsmwk) from comment #18)
> Would you say bug 1089298 is the easiest significant win?
> And what might be the next best one to attack?

Bug 1089298 turned out to not be a terribly significant win. Bug 1089301 was a phenomenal one.

Comment 20

[Wayne Mery (:wsmwk)]

recently described for 100k message folder in https://support.mozilla.org/en-US/questions/1119695 quick filter used to be quick few years ago, but now it is really slow

Comment 21

[Ben Slade]

An old dev-apps-thunderbird mailing list discussion at http://mozilla.6506.n7.nabble.com/Removing-libmime-functionality-td270251.html (about migrating from libmime to jsmime) talks about whether JS performance will be adequate for jsmime.  It also says:

"all JS is executed in mainthread, and there is already too much problems with it (infamous TB
"pauses"...)"

Is that still true?  Could that be magnifying the slowness of jsmime?

Comment 22

[Ben Slade]

I'm sorry, please ignore the previous thread question in the previous comment.  It's answered in the discussion.  I would delete the previous comment, but that doesn't seem to be allowed.

Comment 23

[DeeP]

A little curious if Wayne's assertion above (8 years ago), that "quick filter used to be quick few years ago, but now it is really slow", was ever confirmed to be true. Was there a time when it was quick, and if so, what changed? Parsing JSMime headers... has that been done the whole time (before & after quick turned slow), or only after?

It seems to me that even recently searches were quicker before latest versions of TB were released, but that could be only a "perceived" quickness (and subsequent slowdown) due to other functionality changing that could be making the usual slowness more manifest. For instance, if QF used to show results immediately (and user could find looked-for email quick), but now waits until entire search is finished before showing results.. that could definitely create a perhaps false perception that QF is slower, when really it's just that user cannot see accumulating results immediately.

I've documented my ideas for addressing such concerns -- even if the overall search can't be sped up, specifically -- in the bug listed just above this msg (https://bugzilla.mozilla.org/show_bug.cgi?id=1849650), which involve things like: 1) a "Halt (or Cancel) Search" button, 2) showing usable results immediately, 3) maybe a "finished" indicator, or a active/inactive light, 4) allowing just another second or so during user input before spawning a search, etc. .. but since it looks like that now-aging bug needed to get resolved, it appears a new ticket is needed? Is this still considered a bug, or an enhancement request (which likely will never get fulfilled)?