"Add Bookmark" performance poor with many bookmarks

RESOLVED FIXED in mozilla0.9.6

Status

()

Core
XUL
P3
normal
RESOLVED FIXED
17 years ago
10 years ago

People

(Reporter: Chase Tingley, Assigned: Chris Waterson)

Tracking

({perf})

Trunk
mozilla0.9.6
x86
Linux
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

(URL)

Attachments

(1 attachment, 2 obsolete attachments)

(Reporter)

Comment 1

17 years ago
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.
Keywords: perf
(Assignee)

Comment 2

17 years ago
rdf sucks.
Assignee: hyatt → waterson
(Reporter)

Comment 3

17 years ago
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.
(Reporter)

Comment 4

17 years ago
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))

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.
(Reporter)

Comment 6

17 years ago
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.

Updated

17 years ago
Blocks: 74634
(Reporter)

Comment 7

17 years ago
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.
(Reporter)

Comment 8

17 years ago
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.  
(Reporter)

Comment 9

17 years ago
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.
(Reporter)

Comment 10

17 years ago
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.
(Reporter)

Comment 11

17 years ago
Created attachment 53345 [details] [diff] [review]
so much for waiting for the weekend
(Reporter)

Comment 12

17 years ago
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.
Keywords: patch, review
(Reporter)

Comment 13

17 years ago
Created attachment 53346 [details] [diff] [review]
diff -u
(Reporter)

Updated

17 years ago
Attachment #53345 - Attachment is obsolete: true
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).
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.
(Assignee)

Comment 16

17 years ago
tingley, you rock so hard. r= or sr= waterson, whichever helps.
Status: NEW → ASSIGNED
Priority: -- → P3
Target Milestone: --- → mozilla0.9.6
Comment on attachment 53346 [details] [diff] [review]
diff -u

I weep with joy at this patch. r/sr=shaver (also marking waterson's complement).
Attachment #53346 - Flags: superreview+
Attachment #53346 - Flags: review+
Chris, this is assigned to you - who's going to commit it: Tingley or you?
(Reporter)

Comment 19

17 years ago
Waterson is checking it in -- I don't have commit access.
(Assignee)

Comment 20

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

Updated

17 years ago
No longer blocks: 87864
(Reporter)

Comment 21

17 years ago
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.
Blocks: 87864
(Reporter)

Comment 22

17 years ago
Created attachment 53773 [details] [diff] [review]
v3 - w/ hang fix
(Reporter)

Updated

17 years ago
Attachment #53346 - Attachment is obsolete: true
(Assignee)

Comment 23

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

r/sr=waterson
(Assignee)

Comment 24

17 years ago
Fix checked in. Thanks a ton, tingley!
Status: ASSIGNED → RESOLVED
Last Resolved: 17 years ago
Resolution: --- → FIXED
This change cut about 10% off of window close (bug 104127).  Great!

Updated

10 years ago
Component: XP Toolkit/Widgets: XUL → XUL
QA Contact: jrgmorrison → xptoolkit.widgets
You need to log in before you can comment on or make changes to this bug.