182842 - major perf regression (O(N^2)) in bookmark writing (closing windows)

Status: VERIFIED FIXED

(SeaMonkey :: Bookmarks & History, defect)

Description

[Andrew Schultz]

there is a major perf regression on the trunk that is seen when closing windows.
 the regression occured between trunk builds 2002112121 and 2002112305.

to test this, I generated N bookmarks in a folder.  I timed just opening and
closing Mozilla with the following results:

5000 bookmarks
1.1, 1.2 and 2002112121: 8-9 seconds
2002112305 to 20021129: 22-24 seconds

10000 bookmarks
1.1, 1.2 and 2002112121: 11-13 seconds
2002112305 to 20021129: 89-92 seconds

20000 bookmarks
1.1, 1.2 and 2002112121: 15-18 seconds
2002112305 to 20021129: 466 seconds

I backed out bug 167335, but that didn't help.  Backing out 180423 proved to be
more troublesome, but appears to be the only relevant checkin.

Comment 1

[R.K.Aa.]

there's been some bugs on slow closing lately; bug 182619, bug 182472, bug 182435
i dup'ed them against bug 101319 but that might have been wrong?

Comment 2

[R.K.Aa.]

bug 182619, bug 182472, bug 182435 were all reported with 1.2 release.

Comment 3

[Peter Bergt]

I dunno if the dup'ing is wrong, but in fact the latest binary release of 1.2 is
unusable when you use a big bookmark file

IMHO lately reports concern awfully slow writing of rv1.2 and differ from
the inital intention of Matteo Portas report (at last my comment to bug 101319
was meant this way)

Comment 4

[Andrew Schultz]

I confirmed that bug 180423 is the cause of the regression here.

Comment 5

[Robert Accettura [:raccettura]]

I noticed this when I (very rare event) downloaded a nightly.  About 150
bookmarks.  Some nested in folders.  Most not.  

I have noticed that 1.2 (the build that was removed) seems to  be more awkward
with bookmarks than 1.1 was.... At least on my system it is.


So I see it here too

Comment 6

[R.K.Aa.]

Since the checkin for bug 180423 is not in 1.2, the bugs i mentioned in comment2
have nothing to do with this bug.

Comment 7

[Chris Lyon]

*** Bug 183021 has been marked as a duplicate of this bug. ***

Comment 8

[R.K.Aa.]

The cause for bug 182842 is said to be the checking for bug 180423. That fix was
checked in on the trunk on Nov. 21st. At a time when the tree was closed for 1.2.

The patch in bug 180423 has no approval for checkin to the branch. And I can't
see any indications it was checked in on the branch either? Or was it?

If it wasn't, bug 183021 is not a dup, or it wasn't bug 180423 causing the
regression.

Comment 9

[Andrew Schultz]

I discovered this bug while looking at bug 182373, which I left open to figure
out what went wrong with 1.1 => 1.2.
I obviously can't reproduce that bug (I see no differenc between 1.1 and 1.2)

Comment 10

[Stephane]

On my side, this bug appeared when I upgraded (uninstall and clean
re-installation) from 1.0 to 2.1. Today, I tried 1.2.1 and it's the same.

Mozilla is now simply unusable with my 710KB bookmark file. I downgraded to
1.0.1 and everything works fine again.  

Please, don't hesitate to email me if i could help by giving more details.

btw, i'm using Win2K pro w/sp3.

Comment 11

[Peter Bergt]

Concerning "Status Whiteboard: this bug does not exist in Mozilla 1.2(.1)"

I can't agree to this, as I mentioned in comment 25 on bug 101319 I upgraded to
1.2 (I used 1.1) and the troubles with closing started. Today I tried 1.2.1 and
the same lag on closing a window exists. I tried a new 1.1 installation and
closing a browser windows is possible within seconds whereas after a new 1.2.1
installation it needs to much time to close. (my bookmark file has a size of
1.8mb and the difference on closing a browser window between 1.1 and 1.2.(1) is
awfully) 
but if this bug doesn't exist in 1.2.(1)
I've 2 possibilities: I can use 1.1 with bookmarks or 1.2 without bookmarks.

BTW I'm using binary versions offered by mozilla.org

Comment 12

[Stephane]

Status Whiteboard has changed : << this bug does not exist in Mozilla 1.2(.1) >>    

It's not true. I had this problem with 1.2 and also with 1.2.1

Everything worked fine when emptied my bookmarks file.

Comment 13

[Andrew Schultz]

I'm not saying that bookmarks are fast in 1.2(.1).  I'm saying that "It's not
this bug!"  There is bug 101319 and/or bug 182373 for the slowness of 1.2.

I think you would find that if you upgraded to a current trunk build, that the
performance would be much worse than you're seeing with 1.2

Comment 14

[Boris Zbarsky [:bzbarsky]]

OK.  Well Ben's not going to be fixing this, almost certainly... so we need a
real assignee.  pch?  rjc?

Comment 15

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

The time spent writing bookmarks was mostly in HasMoreElements, called with the
stack:

 InMemoryAssertionEnumeratorImpl::HasMoreElements(int*)
 ContainerEnumeratorImpl::HasMoreElements(int*)
 nsBookmarksService::WriteBookmarksContainer(nsIRDFDataSource*, ...

FWIW, the bottleneck in reading bookmarks is the stack:

 <various functions where the time is spent>
 RDFContainerImpl::AppendElement(nsIRDFNode*)
 BookmarkParser::ParseBookmarkInfo(BookmarkParser::BookmarkField*, ...

Comment 16

[guanxi]

wfm in 1.3a (200212 1215) on Win2K

I did see the problem in 1.2.1, but it's gone in 1.3a

Comment 17

[Samir Gehani]

Nominating for nav triage consideration.  This is on Asa's 1.3 beta list as well.

Comment 18

[Samir Gehani]

Nav triage team: nsbeta1+/adt2

Comment 19

[Pierre Chanial]

Does anybody still see this bug?
If not -> dupe of bug 180516

Comment 20

[Andrew Schultz]

pch: it's bug bug 182373 that is probably a dupe of bug 180516.  this bug is not
related to disk access.

this bug still exists in linux trunk build 20030121.  starting a profile with
5000 bookmarks takes 35 seconds (significantly worse than originally reported in
comment 0)

Comment 21

[Pierre Chanial]

Andrew: mozilla write bookmarks on close.
What refer exactly the numbers you give in comment 0?

Comment 22

[Andrew Schultz]

> What refer exactly the numbers you give in comment 0?

While an otherwise clean profile was inactive, I created a bookmarks.html with N
bookmarks.  Then

> time mozilla -P bigbookmarks
(quit Mozilla as soon as it comes up)

the time in comment 0 is the user time in seconds (system time is <1s) reported
by the "time" utility.  CPU usage is ~80%, so wallclock time is higher.

Comment 23

[Jan Varga [:janv]]

accepting

Comment 24

[Jan Varga [:janv]]

Attachment: proposed fix

Comment 25

[Darin Fisher]

Comment on attachment 112835 [details] [diff] [review]
proposed fix

>Index: nsBookmarksService.cpp

>+    nsCOMPtr<nsIRDFLiteral> literal = do_QueryInterface(node);
>+    if (!literal)
>+        return NS_ERROR_FAILURE;

nit:
      nsCOMPtr<nsIRDFLiteral> literal = do_QueryInterface(node, &rv);
      if (NS_FAILED(rv)) return rv;

the nice thing about this is that if you see the error way downstream
you'll know that it was because a QI failed (NS_ERROR_NO_INTERFACE).
i can't tell you how many times this helped me quickly discover a
missing QI case while developing new code :-)


>+    if (! aURI)
>+        return NS_ERROR_NULL_POINTER;

nit:  NS_ENSURE_ARG_POINTER(aURI);

but does this really need a runtime check?  wouldn't a NS_ASSERTION
be sufficient here?


>+    nsCOMPtr<nsIFileURL> fileURL = do_QueryInterface(aURI);
>+    if (! fileURL)
>+        return NS_ERROR_FAILURE;

same QI nit.

otherwise, the patch looks fine.  granted i don't know much about RDF
or bookmarks.  r=darin

Comment 26

[Jan Varga [:janv]]

Attachment: new patch

addressing darin's comments

Comment 27

[jag (Peter Annema)]

Comment on attachment 112848 [details] [diff] [review]
new patch

sr=jag

Comment 28

[Jan Varga [:janv]]

Comment on attachment 112848 [details] [diff] [review]
new patch

requesting approval for 1.3b

Basically I changed bookmarks service back to using in-memory data source
instead of xml-ds.

Comment 29

[Jan Varga [:janv]]

fixed

Comment 30

[sairuh (rarely reading bugmail)]

rs vrfy.