Closed Bug 512846 Opened 15 years ago Closed 15 years ago

Serious performance issue with Firebug on gmail.com

Categories

(Core :: General, defect)

Product:
Core
Component:
General
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED INVALID

People

(Reporter: johnjbarton, Unassigned)

Details

(Whiteboard: [firebug-p1])

Attachments

(1 file)

HTML file with 100 erroneous CSS rules
2.28 KB, text/html
Details 
While I was investigating Firebug:
Issue 2253:  	 Http Resources are loading slowly when net panel is visible
I found a very serious performance problem.  Gmail.com loads take about 15 times longer.

http://code.google.com/p/fbug/issues/detail?id=2253

On the firebug side the problem has been isolate to code in errors.js, the nsIConsoleService listener.
http://code.google.com/p/fbug/source/browse/branches/firebug1.5/content/firebug/errors.js

I tried the Chromebug profiler but it failed. I will work on that, but maybe there are other ways to go at this. 

My current guess is that this problem is behind most of the performance reports for Firebug 1.5
Whiteboard: [firebug-p1]
> On the firebug side the problem has been isolate to code in errors.js, the
> nsIConsoleService listener.

Any specific code in that file?  Or just that if you don't set up the listener the load is fast and if you do it's slow?
Just add or not add for now. Mostly the code is a lot of different paths for different kinds of errors/warning/exceptions.  Might be able to triage by creating a synthetic case with lots of errors. It's got to be about object creation, not loops.
Can you make the various listener methods there no-ops one by one until you narrow down more closely which particular method is the problem?
Hmm.  Is this just all the objects that logScriptError creates?  I wouldn't have thought you'd hit that code that much for gmail.  Do you get that many of them?

The other option, if we're hitting a codepath that sets thrownStackTrace or some such is that the construction of the stack trace has that issue with serializing functions to strings, etc.  That could be biting here too...
On 3.5.2 I only see the CPU not the memory. That's weird too, because the memory rise on 3.7 was impressive to watch. (This compare is messed up because 3.5.2 is on a different machine from 3.7 runs).

On 3.5.2, if I comment out like this:
 getErrorContext: function(object)
    {
        var url = object.sourceName;
        //if(!url)
            return FirebugContext; 
then the load is fast. So I think this part of the mystery is close at hand.

I'll try 3.7 nightly on this machine as well.
Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.3a1pre) Gecko/20090826 Minefield/3.7a1pre
Shows the CPU effect but not a rise in memory on this machine. So something else must be different, maybe other config setting. I'll have to investigate that on Friday.
Is the issue in getErrorContext itself, or in what callers do with those contexts?  If you change all callers to immediately set the context to FirebugContext after calling getErrorContext but leave getErrorContext as-is, are things fast or slow?
For one context, and Firebug active on the active tab (as is the case for these test runs), then getErrorContext == FirebugContext.

The CPU problem is in this function:
this.getStyleSheetByHref = function(url, context)
{
    function addSheet(sheet)
    {
        if (FBL.getURLForStyleSheet(sheet) == url)
            return sheet;

        for (var i = 0; i < sheet.cssRules.length; ++i)
        {
            var rule = sheet.cssRules[i];
            if (rule instanceof CSSImportRule)
            {
                var found = addSheet(rule.styleSheet);
                if (found)
                    return found;
            }
        }
    }

    var sheetIfFound = null;
    this.iterateWindows(context.window, function(subwin)
    {
        var rootSheets = context.window.document.styleSheets;
        for (var i = 0; i < rootSheets.length; ++i)
        {
            sheetIfFound = addSheet(rootSheets[i]);
            if (sheetIfFound)
                return sheetIfFound;
        }
    });

    return sheetIfFound;
};

So if I estimate ~100 errors, we can get a 100x speed up by figuring out how to cache this. Or maybe there something dumb in this code.
Well the recursion on style sheet only hits bottom about 10 times per error, so maybe one of the platform api calls is expensive?

I don't see an easy way to cache the style sheets. We are in the middle of parsing them, which is why we are getting CSS errors. Between any two errors a successful CSSImportRule could be added. 

Is there a notify event for CSSImportRule addition?

I guess we could assume that any sheet that has the same number of rules as last time has the same import list.

I also learned that all JS errors flow to FirebugContext, my test on context.sourceFileMap is bogus: the compile time JS error in foo.js occurs before foo.js is added to the sourceFileMap. (A small contribution to the performance from that, as all JS compile errors flow through the style sheet code.)
> Well the recursion on style sheet only hits bottom about 10 times per error

"hits bottom"?

> so maybe one of the platform api calls is expensive?

Nothing in there looks particularly expensive, but how many rules do these sheets have?  Do they have any @import rules?

> We are in the middle of parsing them, which is why we are getting CSS errors.

Uh... is that why we're calling into this code?

> Between any two errors a successful CSSImportRule could be added. 

Trying to get the .cssRules of a sheet that's not done parsing yet will throw, for what it's worth.  Does that affect your code at all?

> Is there a notify event for CSSImportRule addition?

No.
(In reply to comment #10)
> > Well the recursion on style sheet only hits bottom about 10 times per error
> 
> "hits bottom"?
> 
> > so maybe one of the platform api calls is expensive?
> 
> Nothing in there looks particularly expensive, but how many rules do these
> sheets have?  Do they have any @import rules?

I mean that the total number of style-sheet items is < 10.

> 
> > We are in the middle of parsing them, which is why we are getting CSS errors.
> 
> Uh... is that why we're calling into this code?

Yes, the nsIConsoleService calls us as errors occur. We don't know which window or what state that window is in.

> 
> > Between any two errors a successful CSSImportRule could be added. 
> 
> Trying to get the .cssRules of a sheet that's not done parsing yet will throw,
> for what it's worth.  Does that affect your code at all?

Evidently not.

> 
> > Is there a notify event for CSSImportRule addition?
> 
> No.

I'm discouraged. I think we should abandoned efforts to provide error messages by window in Firebug.
Oh, hmm.  I guess the reason the exceptions thing doesn't bite you is that the console service notifies listeners asynchronously, so that the sheet is done parsing by the time you get the warnings.  And then you're walking the whole sheet over and over.

So yes, caching might be the way to go.

As far as per-window error messages, the right approach is to fix the longstanding bugs about having a window context attached directly to console service errors, not to grovel through every single user window in an O(N^2) way as above, no?
Actually, how about this trivial optimization?  When walking the cssRules array, once you're past the point where you might see an @import rule, you stop walking.  That ought to help things a lot here.
(In reply to comment #12)
> Oh, hmm.  I guess the reason the exceptions thing doesn't bite you is that the
> console service notifies listeners asynchronously, so that the sheet is done
> parsing by the time you get the warnings.  And then you're walking the whole
> sheet over and over.

If you say so. The relationship between console service and parsing is unknown
to me.

> 
> So yes, caching might be the way to go.

But how? We get an error message and build the file list. Then we get another
error message. Is the file list still correct? We can't tell.

> 
> As far as per-window error messages, the right approach is to fix the
> longstanding bugs about having a window context attached directly to console
> service errors, not to grovel through every single user window in an O(N^2) way
> as above, no?

If by 'right' you mean this would make the above problem go away and the entire
solution more accurate and faster, then yes! If you mean I should stop working
on Firebug to take a chance that I could patch nsIConsoleService and get the
patch accepted, I'm dubious.
(In reply to comment #13)
> Actually, how about this trivial optimization?  When walking the cssRules
> array, once you're past the point where you might see an @import rule, you stop
> walking.  That ought to help things a lot here.

What defines that point?
> Is the file list still correct?

Hmm.  We might be able to do some heuristics here, but maybe it's not worth it in favor of something generally saner.

> to take a chance that I could patch nsIConsoleService and get the patch
> accepted

I think if someone created a patch it'd certainly be accepted.  ;)  That said, posting in the newsgroup as you did is probably the right way to go here.

> What defines that point?

Most simply and reliably, once you see a style rule of type STYLE_RULE (implementing nsIDOMCSSStyleRule, instance of CSSStyleRule).  That's guaranteed to not change and should catch most cases.

That said, I do have one question: how many rules do these stylesheets have exactly?  If we hit this code ~100 times and it's taking us 80-some seconds, that's about 1 second to walk through the stylesheets.  That's a huge amount of time.  Or do we hit this code a lot more than 100 times?

As far as exceptions go, I was wondering....  What happens on this testcase?

<html>
  <style>
    @import url("data:text/css, foo { bar: baz; }");
    @import url("data:text/css, foo { color: red; }");
  </style>
</html>

I'd expect you to end up with an exception in that case when handling the warning about "foo: baz"...
(In reply to comment #16)
...
> > What defines that point?
> 
> Most simply and reliably, once you see a style rule of type STYLE_RULE
> (implementing nsIDOMCSSStyleRule, instance of CSSStyleRule).  That's guaranteed
> to not change and should catch most cases.

So to be sure,         
    for (var i = 0; i < sheet.cssRules.length; ++i)
        {
            var rule = sheet.cssRules[i];
-------- Once I get a rule STYLE_RULE then:
   1) No more imports can happen in this sheet, and
   2) The list of imports for this sheet cannot change until the page is unloaded.

> 
> That said, I do have one question: how many rules do these stylesheets have
> exactly?  If we hit this code ~100 times and it's taking us 80-some seconds,
> that's about 1 second to walk through the stylesheets.  That's a huge amount of
> time.  Or do we hit this code a lot more than 100 times?

Seems to be about 100 times.  I'll try to narrow it down.

> 
> As far as exceptions go, I was wondering....  What happens on this testcase?
> 
> <html>
>   <style>
>     @import url("data:text/css, foo { bar: baz; }");
>     @import url("data:text/css, foo { color: red; }");
>   </style>
> </html>
> 
> I'd expect you to end up with an exception in that case when handling the
> warning about "foo: baz"...

In this case we get the message:

Unknown property 'bar'.  Declaration dropped.
data:text/css,%20foo%20{%20bar:%20baz;%20}
Line 1

in the console for the window containing the html.
>   1) No more imports can happen in this sheet, and

Correct.

>   2) The list of imports for this sheet cannot change until the page is
>      unloaded.

Sadly, no.  New rules can be added to stylesheets using the CSSOM, including @import rules.  I bet no one does that in practice, though.  ;)

> In this case we get the message:

Right; that's expected.  But are you walking the cssRules of the document.styleSheets[0] in this case?  If you are, I would have expected you to get an exception while walking....
This file takes about 60 seconds to load with Firebug, Chromebug and the OS console all monitoring errors. It has 100 CSS statements, all erroneous.
(In reply to comment #19) 
> This file takes about 60 seconds to load with Firebug, Chromebug and the OS
> console all monitoring errors. It has 100 CSS statements, all erroneous.

I guess it is not so dramatic on Firebug alone. Chromebug uses the same code, but it has a lot more contexts/windows to scan, so I guess that is where the multiplier is.
Does chromebug also scan UA stylesheets?  Or is it just walking the various chrome document sheets?

If you have a file with just a single CSS error and you time the function execution in firebug/chromebug, how long does it take?  Does the time taken scale linearly with number of CSS errors?
(In reply to comment #21)
> Does chromebug also scan UA stylesheets?  Or is it just walking the various
> chrome document sheets?

Firebug avoids UA sheets by avoiding chrome URLs. How should chromebug avoid UA stylesheets?

> 
> If you have a file with just a single CSS error and you time the function
> execution in firebug/chromebug, how long does it take?  Does the time taken
> scale linearly with number of CSS errors?

Actually I think the CSS error is a red-herring.

The gmail errors are JS errors about style changes made during ajax processing. The URLs are Ajax urls. My error-routing logic has no provision for these, so we fall through to the style sheet code. Or at least that is what I believe now.
> How should chromebug avoid UA stylesheets?

If it's just walking document.styleSheets it won't see them to start with.

> so we fall through to the style sheet code

Ah, so they're changing inline style or something?  In any case, I'd like to know how many calls to the "find the thing with this url" function there are in the case when it takes 80-some ms...
(In reply to comment #23) 
>  In any case, I'd like to
> know how many calls to the "find the thing with this url" function there are in
> the case when it takes 80-some ms...

Ok with my caching disabled I counted the number of stylesheets processed and the number of style rules processed, for each error message, and the time required, as well as the total for the page load:

13848 rules in 12 sheets required 1082 ms
errors.getErrorContext sheets: 996 rules: 1149384 time: 114263

So I think we have our answer right away: 13k rules. So we are processing 13 rules per millisecond, which seems ok. But we have lots of them, so we take a one second hit if we walk them all. Times 100 errors and there we are at a minute and a half.

With just the STYLE_RULE optimization we get
12 rules in 12 sheets required 5 ms
errors.getErrorContext sheets: 996 rules: 996 time: 13303

With also caching the style sheet URLs we get
0 rules in 0 sheets required 0 ms
errors.getErrorContext sheets: 12 rules: 12 time: 7255
(This optimization will make a bigger delta when we have multiple pages being debugged).

So all of this makes sense, except for the 13k rules seems like a lot.
Boris thanks once again for your help.
Status: NEW → RESOLVED
Closed: 15 years ago
Resolution: --- → FIXED
(In reply to comment #23)
> > How should chromebug avoid UA stylesheets?
> 
> If it's just walking document.styleSheets it won't see them to start with.

Ok, so how would chromebug find the UA stylesheets?
> except for the 13k rules seems like a lot.

Let's see...  gmail seems to have a dynamically generated inline sheet on the main page that has 2314 rules in it.  At least for me.  There are 2 other rules in another inline sheet on the main page, and 2 more in a sheet in one of the subframes.

That's 3 sheets, 2318 rules.  I don't know why you see 12 sheets and 13303 rules offhand; I assume you had only the one gmail tab open and no other windows open, right?

With the caching, I'm confused.  Now we're talking 12 sheets, 12 rules, still 7 seconds spent under getErrorContext?  That's still doubling the pageload time, isn't it?

Also not clear why this is FIXED (as a core gecko bug it's closer to INVALID)...

> Ok, so how would chromebug find the UA stylesheets?

See bug 503007.
(In reply to comment #27)
> > except for the 13k rules seems like a lot.
> 
> Let's see...  gmail seems to have a dynamically generated inline sheet on the
> main page that has 2314 rules in it.  At least for me.  There are 2 other rules
> in another inline sheet on the main page, and 2 more in a sheet in one of the
> subframes.
> 
> That's 3 sheets, 2318 rules.  I don't know why you see 12 sheets and 13303
> rules offhand; I assume you had only the one gmail tab open and no other
> windows open, right?

Now that was a plain ordinary bug: our loop over frames was running but instead of visiting the frames each pass we re-visited the main page. So now I see two unique style sheets with 2298 + 120 = 2318 rules. 

This explains why one I was missing on routing the errors: the errors reported to the frame did not hit the cache because the frame URL was not in there.

> 
> With the caching, I'm confused.  Now we're talking 12 sheets, 12 rules, still 7
> seconds spent under getErrorContext?  That's still doubling the pageload time,
> isn't it?

Sorry I was not clear: that value was the total time for the page load. 

> 
> Also not clear why this is FIXED (as a core gecko bug it's closer to
> INVALID)...

Whatever you like to set it to is fine.

> 
> > Ok, so how would chromebug find the UA stylesheets?
> 
> See bug 503007.
> Now that was a plain ordinary bug

Ah, ok.  Lots of progress here, then.  ;)

> Sorry I was not clear: that value was the total time for the page load. 

Aha.  That makes a lot more sense.

Thanks for filing this!
Resolution: FIXED → INVALID
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: