73295 - new cache load time is much slower in 3/23 than 3/21

Status: RESOLVED FIXED

(Core :: Networking: Cache, defect)

Description

[John Morrison]

As posted by me in n.p.m.performance, n.p.m.porkjockeys:

win32 performance when things are "in the cache" is not significantly better
than in builds of 3/21 or 3/19. But, it's "initial visit" times are ~30%
slower in 3/23 than in 3/21. Bug coming up.

Oddly, linux shows the opposite: when things are "in the cache", page load 
times are about 85% of the "initial visit" in the 3/23 build. Page load times 
for the "initial visit" are not significantly different in builds of 3/19, 3/21 
and 3/23.

Giving this to pav since he said he was going to take a look, but if anyone
else can investigate that would be good. 

Bea-yoo-tiful colored charts coming up ...

Comment 1

[John Morrison]

Attachment: win98 comparison: 3/19,3/21,3/23; "first visit" and subsequent visits

Comment 2

[John Morrison]

Attachment: linux comparison: 3/19,3/21,3/23; "first visit" and subsequent visits

Comment 3

[John Morrison]

On those graphs, for clarity, I did not show the times for a subsequent visit 
for the 3/19 and 3/21 since they were not significantly different than the 
first visit (i.e., the test forces the eviction of the content before a 
subsequent visit occurs, when using the old cache). 

Comment 4

[Brendan Eich [:brendan]]

Pav showed waterson, cathleen, and me some jrgm-style charts showing real
speedups just the other week.  Did things purely within libpr0n regress since
then, or is there some confounding change elsewhere?

/be

Comment 5

[Stuart Parmenter]

I may have fixed this.  Has anyone run these tests with today's build?

Comment 6

[John Morrison]

This is what I emailed last night when bugzilla was down (?). We should 
see the same thing from today's tests, which I haven't looked at yet.

I ran a test on my win2k box with the mar21 commercial build, and then 
built and ran the following: 

A) source pulled at Fri ~2pm, but with newcache and imglib2 disabled (in 
   config.mak). This source include the changes for new view manager, and 
   kmcclusk's frame and content.notify.interval, etc.

B) same source rebuilt enabling newcache but keeping imglib2 disabled

C) same source plus pavlov's patches for the "hugeass" leak, enabling 
   both newcache and imglib2, but now without the leak.

Comparing mar21 to (A), I get about the same performance. (However, I don't
_really_ know how a hand-rolled build should compare to the verification build.
It should be (all things equal) the same, but ...)

Comparing mar21 to (B), I get about the same performance on the first visit
and then about a 20% lift on the second and subsequent visits due to cache. 

Comparing mar21 to (C), I get about the same performance as with just the 
new cache (first visit times equivalent to mar21, subsequent visits about 
20% faster on overall average). Should this have been yet better than (B)?

At any rate, it looks like Friday's build was doomed by the leaks, and things
should be alright Monday.

Comment 7

[Stuart Parmenter]

reassigning to beard, owner of 73498.

Comment 8

[gordon]

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

Comment 9

[Patrick C. Beard]

Let's generate new numbers as soon as possible, especially after we land fix for 
bug #73917. We have optimized cache misses a bit.

Comment 10

[John Morrison]

There are mac verification builds for today, but not linux and win32 (at this 
time) that include the fix for bug #73917 (checked in ~11:50am today).

Comment 11

[John Morrison]

Attachment: updated chart, adding 3/29 win98 times

Comment 12

[John Morrison]

(You might need to trigger a reflow to view that chart in mozilla). 

So, its come back a chunk of the way on win98 with the 03/29 a.m. build. That
build does _not_ have the additional fix from bug #73917; I'll check again
tomorrow. 

Comment 13

[gordon]

DISKCACHE1_BRANCH has landed with some slight performance enhancements (which we 
can't verify yet because of the onLoad bugs).  We're starting work on Disk Cache 
Level 2, which will store cache entry info (key + metadata) in a single flat 
file.  This should have a larger impact on performance.

Disk Cache Level 3 will use flat files for storing the data portion of cache 
entries.

Comment 14

[gordon]

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

Comment 15

[gordon]

We've made improvements, but we'll continue working on this in 0.9.1.  Disk Cache 
Level 2 is nearly finished, and Level 3 should be a small incremental effort.

Comment 16

[gordon]

The recent builds show first load has improved for the iBench test (Win98):

Build      Interations   First Iteration  Subsequent (Cached)
IE 5.5        222.94          32.02           27.27
Comm 4.7      351.17          51.06           42.87
ns 6.01      1213.86         168.33          158.37 
2001-04-27    584.71         101.91           68.97
2001-04-30    576.45         101.56           67.76

John, how do your numbers look?  Can we close this now?

Comment 17

[John Morrison]

Attachment: comparison: first load times, win98, Mar 19,20,21 vs. Apr. 26,27,30

Comment 18

[John Morrison]

Hmm. I had thought that this difference had been largely closed. However, 
it turns out to be a mixed story: while we are approx. the same for most
of the pages in the test series, we are decidedly slower for the slowest
pages in the series. 

Among those are our old friends (most of whom went missing [not loading]
for a while after libpr0n landed):
  
                                   Mar     Apr     +
  www.spinner.com                 2929    3734    27%
  www.zdnet.com                   3206    4210    31%
  www.zdnet.com_Gamespot.com      3139    4626    47%
  www.time.com                    2967    4916    66%
  www.cnn.com                     3644    5171    42%
  www.voodooextreme.com           4053    5273    30%
  www.tomshardware.com            3434    6071    77%

These pages (among other things) are some of the biggest users of images.
I expect gordon's changes for cache storage will help to reduce the gap.
Wondering though if there is some other factor involved in how we pull
the content off the wire and feed it into layout.

Comment 19

[David Hyatt]

Those pages load CSS, which blocks the parser, resulting in a single huge uber-
event that blasts and builds the entire page at once, preventing images from 
even getting kicked off until after layout is completely finished.

Comment 20

[gordon]

How do the subsequent page load time compare for those seven pages?  Is there
only a discrepancy on the first load time (which might indicate problems with
the cache) or do they also exist on subsequent loads as well (which would
indicate some other problem)?

Comment 21

[John Morrison]

Attachment: comparison: "second" load times, win98, Mar 19,20,21 vs. Apr. 26,27,30

Comment 22

[John Morrison]

So there are the values for the second load of each page for these tests for 
the days 19-21 Mar, and 26,27,30 Apr; the URL's are sorted in the same order
as the previous chart (to ease comparibility).

So, once things are in the cache, we are much better off than we were in March
(when, due to 512 item limits, we would evict the entire cache in the course of 
loading these 40 documents). 

Of note on the right hand side of the graph: lxr.mozilla.org and 
www.w3.org_DOML2Core show about the same times for either a first or second
load of that page, but that is to be expected since these both have only a 
single image, and the nature of my test script is that the top level document 
is never cached (again a bug|feature).

Also, we are slower with voodooextreme.com since March on second loads as well.
I'll note that the one unusual aspect of that page is that it has dozens of 
small 'document.write("short string")' sprinkled in the page (search bugzilla 
for the history of that page).

Comment 23

[John Morrison]

Attachment: comparison: default profile vs. disable disk cache, win98/500Mhz/128MB, Apr30 build

Comment 24

[John Morrison]

Attachment: comparison: default profile vs. disable disk cache vs. 64MB mem. cache, win98/500Mhz/128MB, Apr30 build

Comment 25

[Gagan]

will get fixed when 72507 marking transitively to 0.9.2

Comment 26

[gordon]

John, I'm going to assert that this was fixed with the landing of the Disk Cache
Level 2 branch.  Marking FIXED, but please reopen if you find the latest builds
still have that anomolous slow down for time, cnn, gamespot, and tomshardware.

Comment 27

[Ronald van Kuijk]

Please check bug 83721. Could this be related? I do not see a comparison dated
end of may so probably not realy fixed?

Comment 28

[gordon]

No, this bug is unrelated to bug 83721, which is concerned with the number of 
requests generated by shift-reload.  I expect John Morrison (jrgm - the bug 
reporter) to verify this bug has been fixed or reopen it.