630480 - hang loading about:cache?device=disk because nth-child is expensive

Status: RESOLVED WORKSFORME

(Core :: CSS Parsing and Computation, defect)

Description

[Alice0775 White]

Build Identifier:
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:2.0b11pre) Gecko/20110131 Firefox/4.0b11pre ID:20110131064745

Minefield Hang up  when click "List Cache Entries" in about:cache.


Reproducible: Always

Steps to Reproduce:
1. Start Minefield with new profile
2. Navigate web pages For a long time
3. Open about:cache
4. Click "List Cache Entries"

Actual Results:
  Minefield Hang up

Expected Results:
  Should not.

Comment 1

[Alice0775 White]

Attachment: WinDbg log

Comment 2

[Bjarne (:bjarne)]

Which cache-device do you list items for (disk/memory)? Do you have the cache around, and are you be willing to send it to me? Oh, and if you create a new profile and browse around with it ref step (2) above, do you get into the same situation?

Comment 3

[Alice0775 White]

cache-device is  disk.
What is the cache around?
I tested on new profile and no-addons and I reported.

Comment 4

[Bjarne (:bjarne)]

Sorry - I meant to say: Do you have the cache which makes ff crash, and would you be willing to zip it up and send it to me so that I can try to reproduce.

Comment 5

[Alice0775 White]

Not crash.Browser become not response, hang-up. 180MB zip , Where should I put it?

Comment 6

[Alice0775 White]

Disk cache device
Number of entries: 	32212
Maximum storage size: 	1048576 KiB
Storage in use: 	350450 KiB
Cache Directory: 	C:\Users\___\AppData\Local\Mozilla\Firefox\Profiles\m3ak3r2q.7777\Cache
List Cache Entries

I think that
 It takes time to layout link elements of cache entries more than 30,000.
 And Minefield become "not response".
 
 I think that for example,this problem dissolves if Minefield makes paging
 every 1000 entries.


*After click the link, I leave( never touch) PC, then Browser become work normally. It takes about 5-10 min.
*If I touch UI of Browser or Windows taskbar while processing, then browser will hang(white-out) and become impossible to task switching by Windows taskbar. CPU usage  of Firefox process is 25%(a core), HDD is very  quiet and I think HDD did not happen any thrashing.

PC spec:
Core2Quad @2.5GHz, 4GBmem, 160GB free space.

Comment 7

[Bjarne (:bjarne)]

Copying Boris: Is this a known issue? I cannot find it by simple searching. 

It looks like nsAboutCache visits each entry in the disk cache (using EntryInfoVisitor in nsDiskCacheDevice.cpp) on the main thread. The visitor calls nsDiskCacheMap::ReadDiskCacheEntry() for each entry, which access the file.

Comment 8

[timeless]

alice: the log seems to claim that your time is spent dealing w/ the web page content and not the underlying disk data.

could you try loading the page, and then using save-as-webpage-complete, and then loading that saved page. i believe it should trigger the same hang. it might require loading the page from a "slow server", i think there's a way to get our httpd test script to provide that if necessary.

Comment 9

[Alice0775 White]

Attachment: WinDbg log

(In reply to comment #8)
> alice: the log seems to claim that your time is spent dealing w/ the web page
> content and not the underlying disk data.
I do not understand.
I never accessed newly web page when I opened about:cache.


Anyway, I attached new WinDbg log.
Start Minefield with cache file of comment#6.
Open only about:cache tab (no other tab exist).
Click "List Cache Entries" of disk.

Comment 10

[timeless]

alice, from my perspective (and from gecko's), about:cache is a web page, as is about:cache?device=disk which is in fact the "web page" you're visiting when you click "list cache entries".

It takes me 15s or so to load about:cache?device=disk, and i have 3845. You have ~10x as many entries as I have, so assuming things scale simply, it should take you ~3mins. Since it only took me 15s to load about:cache?device=disk, I was able to use file>save page as, the file i generated is 1.7mb, your file should be around 20mb. -- you could try this with a new profile just to get an understanding of it.

i assumed that it would eventually finish, perhaps that was foolish of me. I currently have a task running at work over the weekend (I hope), you could try leaving your browser loading about:cache?device=disk over the weekend and see if it finishes when you get back to it on Monday -- hopefully it'll be done.

Actually, to make this better, let's try this:

Alice! Instead of *clicking* "List Cache Entries", please *right* click it and select "Save Link As". It might hang Firefox (it probably will in fact), but it's a better simpler test.

--- technical stuff follows, you can skip it for now ---
the fun part of this code is here:

515 nsDiskCacheMap::VisitEachRecord(PRUint32                    bucketIndex,
516                                 nsDiskCacheRecordVisitor *  visitor,
517                                 PRUint32                    evictionRank)
518 {
519     PRInt32             rv = kVisitNextRecord;
520     PRUint32            count = mHeader.mBucketUsage[bucketIndex];
521     nsDiskCacheRecord * records = GetFirstRecordInBucket(bucketIndex);
522 
523     // call visitor for each entry (matching any eviction rank)
524     for (int i = count-1; i >= 0; i--) {

--- if someone wants to get a subset of the file we're trying to save above, they can ---
6. switch to windbg
7. debug>break
8. ".reload /f"
9. "kp nsDiskCacheMap::VisitEachRecord; g"
11. switch back to windbg
12. windbg should say BUSY for a bit, and then be ready for commands
13. you should be able to execute "t; t; t; t"
14. that should take you to roughly somewhere in:


523     // call visitor for each entry (matching any eviction rank)
524     for (int i = count-1; i >= 0; i--) {
525         if (evictionRank > records[i].EvictionRank()) continue;
526 
527         rv = visitor->VisitRecord(&records[i]);
528         if (rv == kStopVisitingRecords) 

15. "dv"
16. "?? i = 5; g"

you should only have to repeat steps 11..16 thirty-two times (we could reduce this, but i'm somewhat lazy).

[the step numbers here are random because i've removed steps from a different starting point]

if you talk to someone on irc, you should be able to find someone who can help you step out of that block faster.

the problem is that iiuc the disk cache is single thread only. and the iterator is sync requiring one to consume all data before continuing. it would be possible to restructure the visitor to merely store all of the visited elements and then schedule events to do the actual work which is currently in nsAboutCache::VisitEntry().

Comment 11

[Alice0775 White]

Priour landing Bug 175600 and Bug 569709, the maximum number of entry 8192.
Now it is depend on size of memory and disk space.

In my case Maximum number of entry is more than 32212 and maybe more which is depend on my PC spec.

I think that it is a mistake to have increased the maximum number without doing the consideration of processing time.

Comment 12

[Boris Zbarsky [:bzbarsky]]

I'd really appreciate someone creating a copy of the HTML (and css?) in question.  See comment 8...

Alic0775e, the normal things one does with a cache don't include listing all its contents, so aren't O(N).  Increasing the cache size was definitely the right thing to do.  We should figure out why this HTML is being so slow and fix it, though.  It shouldn't take multiple minutes to render an HTML page, typically.

Comment 13

[Boris Zbarsky [:bzbarsky]]

In fact, even 15s sounds too long.  So timeless' file would work for me too.

Comment 14

[Alice0775 White]

Attachment: Information about the Cache Service zip

Comment 15

[Alice0775 White]

(In reply to comment #12)
> I'd really appreciate someone creating a copy of the HTML (and css?) in
> question.  See comment 8...

Here  attachment 509747 [details] .

Comment 16

[Boris Zbarsky [:bzbarsky]]

Thanks!

So the resulting DOM there has about 612000 nodes.  On my machine it takes 20 seconds or so to render, but the browser is frozen during that time.  Probably because we move the data through to layout very quickly, not interrupting the parser much....  If I turn off the HTML5 parser, I get a much more incremental pageload, but it takes 40s.

Henri, would it make sense to interrupt more often once we've seen, say, a meg of HTML?

In any case, actual time spent is 30% layout and 67% frame construction.  The rest is minor.  The vast majority of the frame construction time (56% of the total pageload time, so 85% of frame construction) is in (not under) SelectorMatches.

Looking at the attached stylesheets, the "problem" is these rules:

  #entries > tbody > tr:nth-child(odd) {
    background-color: rgba(0, 0, 0, .03);
  }

  #entries > tbody > tr:nth-child(even) {
    background-color: rgba(0, 0, 0, .06);
  }

which actually make the pageload O(N^2).  If I comment those out, pageload goes from 20s to 9s for me.

We really need to figure out a better way to handle caching/computing the :nth-child stuff.  In particular, shark claims that most of the SelectorMatches time is in one place: the |test al,byte1| that nsINode::GetFlags does when called from IsElement().  I haven't done an L2 miss profile, but I'll bet that's all that happens there...  a lot.

Comment 17

[Bjarne (:bjarne)]

Phew...  finally a case where the cache is not the culprit... :)  Move to appropriate component?

Comment 18

[Boris Zbarsky [:bzbarsky]]

Yeah.  Over to style system, but we should probably file a bug about my parser question too....

Comment 19

[Bjarne (:bjarne)]

Do you think it's worth following up the issue in comment #7 about the visitor reading files as well?

Comment 20

[Boris Zbarsky [:bzbarsky]]

I don't know. I only profiled CPU time, not wall-clock time....  but my CPU seemed pretty well pegged for the duration.

Comment 21

[Bjarne (:bjarne)]

Ok - I'll drop that issue then. :)

Comment 22

[timeless]

oh, of note, afaict this only affects windows because only windows has aboutCache.css which in turn has this rule.

bz: not that we should work around this, but would it be bad for the AboutCache page to replace nth-child with a pair of odd/even classes and two rules?

Comment 23

[timeless]

Attachment: untested hack

Comment 24

[Boris Zbarsky [:bzbarsky]]

Not particularly bad, I wouldn't think.

Comment 25

[Steffen Wilberg]

(In reply to comment #22)
> oh, of note, afaict this only affects windows because only windows has
> aboutCache.css which in turn has this rule.
No, that file is used by all platforms.
Gnomestripe (Linux) is just an override over Winstripe (Windows).
Pinstripe (Mac) packages the Winstripe file.
http://mxr.mozilla.org/mozilla-central/search?string=aboutCache.css&find=jar.mn&findi=&filter=^[^\0]*%24&hitlimit=&tree=mozilla-central

Comment 26

[Boris Zbarsky [:bzbarsky]]

The fixes in bug 598832 should have cut the time here significantly.  Alice0775 White, could you retest please?

Comment 27

[Alice0775 White]

Improved.
http://hg.mozilla.org/mozilla-central/rev/b909ecef2c15
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:7.0a1) Gecko/20110525 Firefox/7.0a1 ID:20110525010732

It takes about 15sec.

Disk cache device
Number of entries: 	26496
Maximum storage size: 	1048576 KiB
Storage in use: 	272155 KiB