Closed Bug 180109 Opened 22 years ago Closed 21 years ago

Global history performance poor with large (60 day) history size; delays on page load

Categories

(Camino Graveyard :: History, defect)

PowerPC
macOS
defect
Not set
critical

Tracking

(Not tracked)

RESOLVED FIXED
Camino0.8

People

(Reporter: iezibeij-bugzilla.mozilla.org, Assigned: mikepinkerton)

References

Details

(Keywords: perf)

Attachments

(4 files, 2 obsolete files)

User-Agent:       Mozilla/5.0 (Macintosh; U; PPC Mac OS X; en-US; rv:1.0.1) Gecko/20021113 Chimera/0.6+
Build Identifier: Mozilla/5.0 (Macintosh; U; PPC Mac OS X; en-US; rv:1.0.1) Gecko/20021113 Chimera/0.6+

With the history preferences set to "remember visited pages for 60 days",
performance when interacting with items in the global history sidebar is
extremely poor. Long periods (10-15 seconds or more) of spinning beach ball upon
trying to click on disclosure triangles; and even scrolling performance is poor
with the scrollbar "jumping" after several second lags. This is on a
Dual-1.25GHz Mac running 10.2.2 and the 2002-11-13 nightly.

My history.dat file is quite large (more than 1.5 meg); I don't know how many
entries it must have in it, but it is many... Other global-history-related
performance is good with this configuration (for example, auto-completion in the
location bar is very quick).

Reproducible: Always

Steps to Reproduce:
1. Set history prefernce to "remember visited pages for 60 days".
2. Make sure you've visited lots of pages so that the global history contains
many, many addresses.
3. Open the sidebar and try to scroll, or flip disclosure triangles on and off.

Actual Results:  
Laggy performance with long periods of blocking (spinning wait cursor).

Expected Results:  
Maintained responsive UI.
->pink
Assignee: sfraser → pinkerton
Confirmed with Build ID: 2002111604 on same date. Also, loading pages by typing
in the location bar is extremely slow and some (maccentral.macworld.com will not
load at all). There may be a popup interaction in that case. 
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Target Milestone: --- → Chimera0.7
*** Bug 184213 has been marked as a duplicate of this bug. ***
I can verify this activity. I have my history set to 9 days (even changed it to
2 days) and I can never pull up the history. Any attempts to click on a
disclosure triangle in the History sidebar yields a spinning cursor - for
several mins.... I have let it spin for up to 5 mins before force quitting.
Never have been able to access the disclosed history urls.

Using latest nightly build(s).
We're hindered by the interaction between outline view datasource methods, and
RDF here. Performance is poor because [outlineView:numberOfChildrenOfItem:] and
[outlineView:child:ofItem:] need to enumerate the children of a resource each
time, which is going to give O(n^2) performance. Opening large folders will be
much slower than opening small ones.

We'll have to solve this by either caching more data on the Cocoa side, or
removing RDF from the equation.
Keywords: perf
NormalizeTime() in the global history code calls 

  PR_ExplodeTime(aTime, PR_LocalTimeParameters, &explodedTime);

sets the hours/minutes/secs/usecs to 0, then calls 
  PR_ImplodeTime()

to round times down to the previous midnight, to be able to make day comparisons.
This involves two calls to localtime(), which are really slow on OS X. Also,
PR_ImplodeTime() implicitly uses GMT parameters, which seems to contradict the
PR_LocalTimeParameters usage in PR_ExplodeTime().

Another issue is that PR_Now() gets called a lot from the matchAgeInDaysCallback.
This patch reduces the number of PR_Now() calls, and removes a bogus
nsCString::Append call.
> PR_ImplodeTime() implicitly uses GMT parameters, which seems to contradict the
> PR_LocalTimeParameters usage in PR_ExplodeTime().

I discovered that these conversions are necessary to correctly determine which
day (in local time) an item was changed in.
Taking
Assignee: pinkerton → sfraser
Status: ASSIGNED → NEW
I checked in that pathc, and did some optimizations in the chimera code to cache
child lists of RDFOutlineViewItems, and make sure we rebuild the history sidebar
only once per page load.

It still sucks. Eliminating the localtime() calls in the history code will help,
but that requires solving local/GMT timezone issues. I'm leaving this bug open
for now.
Status: NEW → ASSIGNED
I don't know why localtime would be so slow, but it seems like this is the
0(n^2) code: (in /mozilla/source/chimera/src/extensions/RDFOutlineViewDataSource.mm)

233         while (NS_SUCCEEDED(childNodes->HasMoreElements(&hasMore)) && hasMore)
234         {
235             childNodes->GetNext(getter_AddRefs(supp));
236             if (count == aIndex)
237                 break;
238             count ++;
239         }

the same code in numberOfChildrenOfItem ... so the RDF source only iterates,
doesn't just give you a count eh? Thus, since NSOutlineView iterates, and you
iterate again each time. Icky.

Some thoughts 

... if NSOutlineView is predictable about how it calls child: ofItem: and
numberOfChildrenOfItem: then it might be possible to fake it out and do a lot
less caching by doing something more along the lines of some minimal "hopeful"
caching. In other words, if you know the next call to child: ofItem: is likely
to be the next one you can keep the iteration values around just for the last
call and in the usual case (your prediction correct) be O(1)

... you could build a "middleware" cache that sits between the real datasource
and the outlineView and passes uncached messages through (not too hard with
obj-c) (not sure about this being helpful)

... my impression is that the RDF datasource requires iterating, is there a way
to modify it to just give you the count in 0(1) instead of modifying the cocoa
side? (no idea about this, just a thought)
If you look at my new code, you'll see that i build a list of child nodes just
once, and use it in calls to get the number of children, and the child at index.
Attached file localtime speed test
I ran this speed test on localtime (hopefully useful) that ran a million
localtime(gettimeofday()) calls in 45s on my g4/400. This would seem to show
that it's pretty fast.
Based on the original comments, I'm not able to reproduce the history
performance issue in the sidebar. Tested with the 2002-12-18-08 NB under 10.2.2.
I'm not sure I understand, please don't bite.
If LocalTime function is slow, can you not compute the delta values between
Global and Local time once. The delta values are always the same.
Then use them instead of the function to obtain values that can be compared
correctly.
In response to Chris's comment 14, the performance for folders with a small
number of items is much improved here under 10.2.2 with the 2002-12-18-04
nightly. Performance is still not up to par with other apps that use outline
views (eg. Finder, Mail.app etc), but it is much better.

Folders with many items are still producing long periods of "spinning beach
ball". Originally, I couldn't even scroll without getting the ball, but now at
least scrolling seems responsive. It's the disclosure triangle performance that
is still very laggy.
This last patch improves history performance by eliminating lots of localtime()
calls from NormalizeTime(), by caching the difference between GTM and local time
(thanks Stephane). I think this is as fast as we're going to get for now;
remaining performance goes into a lot of string routines in
nsGlobalHistory::RowMatches().
Patch checked in. This bug is now fixed.
Status: ASSIGNED → RESOLVED
Closed: 22 years ago
Resolution: --- → FIXED
Testing with the 2002-12-24 build has revealed two things: this bug is mostly
resolved, but another has been revealed.

1. The performance does indeed seem better (running on a dual 1.25); the only
subfolder in the History draw that could produce the beachball cursor is the
"Older than 6 days" subfolder, which in my case contains a list of sites several
"screenfuls long" and locks up Chimera for about 15 seconds. All the other
folders only have a about 10-30 sites in them and these all disclose/collapse
with a short delay of about one second.

2. The new bug, however, becomes evident when the bookmarks sidedraw is open and
many subfolders are in the expanded state. In this case, whenever you visit a
new site (by clicking on a link, choosing a bookmark, or typing in a URL) there
will be a long, long delay (with beachball) while the history is scanned and the
site is added to the history. If the history draw is scrolled to an appropriate
point then you will see the site being added to the history and then the browser
becomes responsive again.

This one goes away as soon as you close the history draw, but comes back when
you re-open it.

You can reproduce it by going to an address that is not in your history: say...

http://www.nasa.gov/

This will produce the delay regardless of which folders in the history are
expanded. All that is necessary is that a sufficient number of subfolders be
visible, in ANY parent folder.

Visiting a sub-page of the same site will produce another delay, so for example,
the following producing another lengthy delay:

http://www.nasa.gov/hqpao/survey.html

Having visited these sites once, you can switch back and forth between them with
no delay.

Can anyone else repro this one? And if so, Simon, do you think I should file a
separate bug report for it?
This delay on page load is not new; in fact, it would have been much worse in
older builds (which could rebuild the entire history tree several times for each
page load). From what you're saying, it sounds like we're still not fast enough.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Summary: Global history performance poor when interacting in sidebar with large (60 day) history size → Global history performance poor with large (60 day) history size; delays on page load
Can we just not make a simpler history ?
>2002-12-25
>2002-12-24
etc

The only thing to check is if the date/time has changed to another day (12-26),
if it's the case make a new folder at the top.
Add the URL to the top of top folder (12-25).

Splitting items into host folders is quite annoying, eg. if you visit apple.com,
you'll get store.apple.com, www.apple.com, etc.

Not easy to track where you have been.
A simple list will be enough for anyone and will solve all those speed problems.
you forget that there are people who use 333mhz imacs, not dual 1.25ghz g4s. it
is interesting to note that history is considerably faster in mozilla (very
responsive) even on my 333mhz imac as compared to chimera.
I just got back from vacation and saw all the activity here.. is this stuff in
the trunk now too? If not, can we fix it there?
It's not in the trunk: I was told that GH perf on the trunk was OK. The last
nsGlobalHistory.cpp patch should be able to go onto the trunk as-is.
Simon, any way this can go onto the trunk soon?  Since merging with the trunk,
history performance sucks again.  This would definitely help with that.
alecf, want to take a stab at that?
Assignee: sfraser → alecf
Status: REOPENED → NEW
I tried to track this problem down on my own using Sampler and I confirmed that
localtime() really seems to be slow. I compared the implementation of
localtime() in the Darwin libc with the one in glibc, and I think the problem is
that Darwin's localtime() resets the time zone with tzset() every time it is
called whereas glibc's calls tzset() once and then caches the time zone for
subsequent calls. The calls to tzset() seem to access the file system, and I
found out through Sampler that Darwin's localtime() seems to spend most of its
time in lstat(). This seems to be a bug in Darwin's implementation of localtime().

One possible workaround is to use the old mac implementation of localtime() in
http://lxr.mozilla.org/mozilla/source/nsprpub/pr/src/md/mac/mactime.c. I tested
the attached localtime speed test on my 333MHz G3 with both the Darwin version
and the mactime.c version and found that the latter version is much faster:

Darwin version:     54s
mactime.c version:  6s
The patches in this bug are enough to fix the problem; they just need migrating
to the trunk.
Attached patch patch to trunk (obsolete) — Splinter Review
Okay then. This should be enough to merge your changes into the trunk.
Attachment #126773 - Flags: review?(alecf)
Comment on attachment 126773 [details] [diff] [review]
patch to trunk

this is really great stuff, but you rearranged some code so this patch is a lot
bigger than it needs to be (i.e. such as the moving of GetAgeInDays()) - can
you move them back where they were in the file so the diff is a little more
sane? 

(and yes I realize they went from static functions to nsGlobalHistory::
members)

also, please don't check in #if 0'ed code

overall this looks great but I just want to see a cleaner patch. thanks!
Attachment #126773 - Flags: review?(alecf) → review-
Attached patch cleaned-up patchSplinter Review
Attachment #126773 - Attachment is obsolete: true
Comment on attachment 127891 [details] [diff] [review]
cleaned-up patch

This is sfraser's patch so I neither deserve credit for its goodness nor
criticism for its messiness. I was just trying to merge a languishing patch
with the current trunk in order to move things along.

Anyway, how about this one?
Attachment #127891 - Flags: review?(alecf)
Comment on attachment 127891 [details] [diff] [review]
cleaned-up patch

hey, nothing personal, I just didn't want the patch landing until then.
r=alecf
Attachment #127891 - Flags: review?(alecf) → review+
I'm running on this latest patch now, seems to work. I don't notice any lag in
the history any more, but that may be my new machine ;-)
Comment on attachment 127891 [details] [diff] [review]
cleaned-up patch

Let's move this one into the build?
Attachment #127891 - Flags: superreview?(pinkerton)
The performance boost of this patch is huge compared to the speed it's right
now. Still I think it's slow.  For me (G4 533, 1Gb Ram) it take 2/3 secons to
open the today folder which has 30/40 entries. I can't emagine something as
simple as the history file takes so much cpu time to open?

Why isn't the history file loaded before opening it? Would changing the history
system so that it would save the file in a.plist file boost performance?
alecf, attachment 129075 [details] [diff] [review] to bug 91044 which is also in your review queue
addresses a PR_Now issue. The patch is much simpler...

i haven't looked in detail (and i'm on vacation) but does this ExpireNow/Cache
Now play nicely with timezone changes? I'm betting it doesn't.
Is this the same bug as bug 91044 then? It might be educational to study the
caching implementation in glibc of localtime() compared to the implementation in
Darwin. Perhaps the glibc implementation could be integrated into Camino? And
then, call a local library version of localtime derived from glibc instead of
the Darwin localtime. That would save maintaining our own caching system.

Separately we could try to fix Darwin's localtime and submit that back to apple
to go into the next version.
Comment on attachment 127891 [details] [diff] [review]
cleaned-up patch

smfr, can you sr this so we can move it to the trunk?
Attachment #127891 - Flags: superreview?(pinkerton) → superreview?(sfraser)
talking so i don't lose it. we just need sr and a= now for 0.8
Assignee: alecf → pinkerton
Severity: normal → critical
Target Milestone: Camino0.7 → Camino0.8
Attachment #127891 - Flags: superreview?(sfraser) → superreview+
bryner sr'd already, but sr=me if you need it. It's a fine patch!
Is there a reason this isn't checked in and marked fixed? Seems as though people
agree that the patch is good and it has all the needed approvals.
Mike
you can apply, it applies properly and build works. Camino.app launches and
works well.
landed.
Status: NEW → RESOLVED
Closed: 22 years ago21 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: