520172 - gloda indexer stringifies MessagesByMessageIdCallback results for debug even when not in debug mode

Status: RESOLVED FIXED

(MailNews Core :: Database, defect)

Description

[Olli Pettay [:smaug][[e-mail]]]

Shark profile shows that 50% of time is spent under CompletionNotifier::Run()
which then calls some JS. That leads to *very* deep MarkSharpObjects recursion.

Just a guess, something wrong with datastore.js' handleCompletion implementations?
http://mxr.mozilla.org/comm-central/source/mailnews/db/gloda/modules/datastore.js#72
http://mxr.mozilla.org/comm-central/source/mailnews/db/gloda/modules/datastore.js#275
http://mxr.mozilla.org/comm-central/source/mailnews/db/gloda/modules/datastore.js#1229

Comment 1

[Wayne Mery (:wsmwk)]

(leaving [faceted search] in summary for search purposes)

Comment 2

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

Could you elaborate on the depth of the MarkSharpObjects recursion and provide some analysis as to why it is a bad thing?  If we are not blowing the stack and there's no reason to presume we are creating pathological algorithmic behavior (O(n^2) or worse), I'm not sure this is a bad thing.

We do all kinds of work in handleCompletion because much of our code is asynchronous and dependent on those database notifications for the data it needs to do its work.

Comment 3

[Olli Pettay [:smaug][[e-mail]]]

(In reply to comment #2)
> Could you elaborate on the depth of the MarkSharpObjects recursion and provide
> some analysis as to why it is a bad thing?
I was just profiling using Shark and noticed that lots of time is spent in
very deep MarkSharpObjects recursion. I don't exactly know why, and what does 
that mean.
But perhaps there is some recursive algorithm which could be changed to iterative. (just guessing...). If iteration is possible, it is quite often
faster than recursion - especially with 1.9.1.x Tracemonkey, which doesn't, IIRC, trace recursion.

> We do all kinds of work in handleCompletion because much of our code is
> asynchronous and dependent on those database notifications for the data it
> needs to do its work.
Right. I understand that, but I was hoping the algorithms could be tweaked a bit.

The new search is awesome, but when I updated my TB build to one which has the
new search, indexing emails took ~8h. That is quite a lot.

Comment 4

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

smaug found me on IRC and reminded me that MarkSharpObjects is the pretty-printer helper thing and not something related to GC.

There is over-zealous debug in MessagesByMessageIdCallback.  We are trying to stringify the results structure regardless of our debug setting.

Thank you very much for logging this bug, smaug!

Comment 5

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

I ran this with my indexing benchmark.  The debug appears to have trivial performance ramifications; the difference basically gets lost in the noise.  I was really hoping that was it.  This makes sense considering the code still should have shown up as a hot-spot last time I killed off over-zealous debug.

Olli, if you can post your shark dump in text form, that could be useful.  It's possible there's some form of edge case happening and that might be useful.  Of course, without the JS stack, it'll be mainly guesswork.

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

Attachment: profile, rooted @ CompletionNotifier::Run()

Comment 7

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

Attachment: v1 only build the string if it will be used for debug logging

There certainly is no benefit to wastefully doing the stringification, so let's stop doing it when not needed.  Since we're not absolutely sure if the shark trace is pointing out this as a problem or something else, let's see if this makes it go away.

Comment 8

[David :Bienvenu]

Comment on attachment 404640 [details] [diff] [review]
v1 only build the string if it will be used for debug logging

shouldn't this be

if (MBM_LOG.level >= Log4Moz.Level.Debug)

?

Comment 9

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

(In reply to comment #8)
> (From update of attachment 404640 [details] [diff] [review])
> shouldn't this be
> 
> if (MBM_LOG.level >= Log4Moz.Level.Debug)

No, although that's what I wrote the first time I was fixing the indexer verbose debug :)

From:
http://mxr.mozilla.org/comm-central/source/mailnews/db/gloda/modules/log4moz.js#69

  Level: {
    Fatal:  70,
    Error:  60,
    Warn:   50,
    Info:   40,
    Config: 30,
    Debug:  20,
    Trace:  10,
    All:    0,

Comment 10

[David :Bienvenu]

Comment on attachment 404640 [details] [diff] [review]
v1 only build the string if it will be used for debug logging

ah, ok...that's going to take some getting used to :-)

Comment 11

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

pushed attachment 404640 [details] [diff] [review]:
http://hg.mozilla.org/comm-central/rev/1a5f029b9d51

Olli, if you can try again and post the shark trace when this shows up in a new nightly or when you get time to spin your own new build, that would be great.

Comment 12

[Olli Pettay [:smaug][[e-mail]]]

Now I can't see MarkSharpObjects in the profile anymore.

74.9% of time under CompletionNotifier::Run() is now spent somewhere
in generator_op.
In the earlier profile that was 38.8%, so seems like there is a significant 
improvement.

Comment 13

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

Since we landed a patch and I don't think there is anything actionable left on the bug (although there is lots of performance work we could do in general), let's mark this fixed.