104328 - "Add Bookmark" performance poor with many bookmarks

Status: RESOLVED FIXED

(Core :: XUL, defect, P3)

Description

[Chase Tingley]

see
 news://news.mozilla.org:119/9q5pti$[e-mail]

Comment 1

[Chase Tingley]

bug 69009 is a good place to get a huge bookmark file if people want to test
along at home.

Hyatt, I can take this from you (for investigation at least, hopefully all the
way) unless it is readily apparent to you what's going on here.

Comment 2

[Chris Waterson]

rdf sucks.

Comment 3

[Chase Tingley]

Well, sure, but there's definitely a particular bottleneck.  Inside
|nsXULTemplateBuilder::Propagate()|, there are only a few (4 or 7, in my case)
test nodes that can propagate the assertion.  Of these, one (always the first,
whatever that means) takes up all the time, splitting it evenly between
|nsRDFTestNode::Constrain()| and |nsRDFTestNode::Propagate()|.  The others take
(in comparison) almost no time at all.

I would assume that the rule tree behind that first test node is growing >>
linearly with the size of the bookmarks datasource.... time to go look at the
code some more.

Comment 4

[Chase Tingley]

With XUL logging enabled, I'm noticing interesting things like this:

| 1024[806ae70]: nsRDFPropertyTestNode[85603e0]: FilterInstantiations()
|     source=[http://0.com]
|     target=[http://home.netscape.com/NC-rdf#BookmarkSeparator]
| 1024[806ae70]:     consistency check => failed
| ...
| 1024[806ae70]: nsRDFPropertyTestNode[85603e0]: FilterInstantiations()
|     source=[http://1071.com]
|     target=[http://home.netscape.com/NC-rdf#BookmarkSeparator]
| 1024[806ae70]:     consistency check => failed
| 
| 1024[806ae70]: nsRDFPropertyTestNode::FilterInstantiations (instCount=1079): 
|    took 124848 tics

Other tests are doing similar things.

So here's the O(n^2) -- InMemoryDataSource::HasAssertion() scales linearly (bug
35817), and when a new element is added, the rule code rechecks all of the
already existing elements just in case one has also become a BookmarkSeparator.

Obviously, HasAssertion() should be improved (I've got a bogus piece of code
lying around that sticks an nsAVLTree into nsInMemoryAssertion for just this
purpose -- the implementation turns out to be problematic, but it might be
interesting to see what it does here).  But that would probably improve this
operation to O(nlogn) at best -- a bigger win would be to figure out a way to
hint/cheat/short circuit/etc and not recheck every element every time.  This
would reduce the time to O(constant * (HasAssertion time))

Comment 5

[Randell Jesup [:jesup] (needinfo me)]

We also see O(n^2) issues with RDF in closing windows in these same functions
(bug 104127).  That one is probably the Tasks menu.

Comment 6

[Chase Tingley]

At least part of the time in this bug is probably the exact same problem -- the
XULTemplate log also shows 

1024[806ae70]: xultemplate[838fdc0] build-content-from-template rule 
               (template='') [NC:PersonalToolbarFolder]
1024[806ae70]: xultemplate[838fdc0]     building menupopup  [unique]
1024[806ae70]: xultemplate[838fdc0] build-content-from-template menupopup 
               (template='') [NC:PersonalToolbarFolder]
1024[806ae70]: xultemplate[838fdc0]     building menu [resource]
[... repeats may times ...]

Is this really rebuilding hidden menus from scratch?

Even without cleaning up the rule-processing code, there are ways we could be
lazy about this recomputation -- eg don't rebuild the tasks menu until the next
time it's opened.

Comment 7

[Chase Tingley]

Whew.  I can now say with some confidence that for adding bookmarks (via
keyboard shortcut), the bottleneck is the consistency checking block that begins at 

http://lxr.mozilla.org/mozilla/source/content/xul/templates/src/nsRDFConMemberTestNode.cpp#156

Looking at it, this is perhaps not surprising.  (And |IndexOf()| frequently
appears beneath |FilterInstantiations()| in Randell Jesup's jprof on bug 104127,
iirc.)  It seems like there ought to be a way to utilize fuller knowledge of the
situation to avoid some of these calls.

Comment 8

[Chase Tingley]

Waterson was right; RDF sucks.

All the time is in |RDFContainerImpl::IndexOf()|, which is innately very slow.  

Furthermore, the fact that the datasource is a composite makes it even worse
(IndexOf() uses GetTargets() rather than GetTarget() in order to avoid
degenerate cases where a composite ds could have colliding assertions).

You know what would be cool?  Making IndexOf() fast by storing it as an extra arc.  

Comment 9

[Chase Tingley]

Ugh, I am in quite a state today.  Obviously we don't need an extra arc, since
we can already walk them backwards.  I wonder why IndexOf doesn't do this already.

Comment 10

[Chase Tingley]

Ok, last time, I promise.

The RDFContainerUtilsImpl version of IndexOf() (slightly different -- also takes
a datasource) does things the "right" way -- get the arcs into the resource and
go backwards.  The RDFContainerImpl version is braindead.  If I swap the IndexOf
call at 
http://lxr.mozilla.org/mozilla/source/content/xul/templates/src/nsRDFConMemberTestNode.cpp#163
to the equivalent nsIRDFContainerUtils call, adding bookmarks becomes pretty speedy.

I'm planning on producing a patch to make RDFContainerImpl do this the fast way.
 This may not happen for a couple days, as I have to attend a wedding.

Comment 11

[Chase Tingley]

Attachment: so much for waiting for the weekend

Comment 12

[Chase Tingley]

It looks a little odd for the container to call out to the containerUtils, but
it needs to be this way -- the operations are done using container resource
rather than the nsIRDFContainer itself.

With this patch, I get roughly a 20x speedup (~900,000 tics -> ~40,000) when
using ^D to add bookmarks (using the 1100 bookmark file).  This is almost too
good to be true.

cc'ing shaver so he can tell me that it is.

Also, I've just noticed that my diff isn't -u.  I'll fix this.

Comment 13

[Chase Tingley]

Attachment: diff -u

Comment 14

[Randell Jesup [:jesup] (needinfo me)]

Ooooohhhhh.  I'm drooling.  :-)

I not up anywhere near enough on RDF to review the patch, but it looks nice. 
It's always nice to speed things up _and_ make them smaller.  I wondow how much
impact this will have on the window close test (and on window open).

Comment 15

[Randell Jesup [:jesup] (needinfo me)]

Window Close (bug 104127) spends about 15% of it's time in
RDFContainer::IndexOf, so I'd guess we'll get a nice boost there.

Comment 16

[Chris Waterson]

tingley, you rock so hard. r= or sr= waterson, whichever helps.

Comment 17

[Mike Shaver (:shaver -- probably not reading bugmail closely)]

Comment on attachment 53346 [details] [diff] [review]
diff -u

I weep with joy at this patch. r/sr=shaver (also marking waterson's complement).

Comment 18

[Randell Jesup [:jesup] (needinfo me)]

Chris, this is assigned to you - who's going to commit it: Tingley or you?

Comment 19

[Chase Tingley]

Waterson is checking it in -- I don't have commit access.

Comment 20

[Chris Waterson]

I am. But before I do so, I'd like some time to test it, thanks! (See comments
in bug 87864, e.g.)

Comment 21

[Chase Tingley]

Why am I cursed when it comes to accidental dependency removal?  
Here comes a new patch to also fix the hang discovered in bug 87864.

Comment 22

[Chase Tingley]

Attachment: v3 - w/ hang fix

Comment 23

[Chris Waterson]

Good lord! Who wrote this code in the first place? ;-)

r/sr=waterson

Comment 24

[Chris Waterson]

Fix checked in. Thanks a ton, tingley!

Comment 25

[Randell Jesup [:jesup] (needinfo me)]

This change cut about 10% off of window close (bug 104127).  Great!