Closed Bug 168732 Opened 24 years ago Closed 24 years ago

nsBrowserStatusFilter too weak for OnStateChange (3.5% of pageload)

Categories

(Core :: Networking, defect, P1)

Product:
Core
Component:
Networking
Platform:
x86
Linux
Type:
defect

Tracking

()

Status:
VERIFIED FIXED
Milestone:
mozilla1.2beta

People

(Reporter: dbaron, Assigned: dbaron)

Details

(Keywords: perf, Whiteboard: [patch])

Attachments

(3 files)

jprof of time in OnStateChange
283.18 KB, text/html
Details
patch, v. 1 (diff -u)
8.49 KB, patch
caillon
: review+
jag+mozilla
: superreview+
Details | Diff | Splinter Review
patch, v. 1 (diff -uw)
3.58 KB, patch
Details | Diff | Splinter Review
I wrote in bug 144533 comment 74: Poking at this in the debugger and in profiles, it looks like some of the notifications are going through the filter, but some are going directly from the docloader to the nsBrowserStatusHandler. The problem seems particularly bad for OnStateChange, although it also looks like it's present for OnStatus. Could this patch not be hooking something up to the filter? (Would it be cleaner to hide the filter inside of browser.xml and it's addProgressListener method?) I'm still seeing this. The OnStateChange issue may be as much as 3.5% of page load time on a list of live URLs very similar to jrgm's test URLs (assuming nothing really complicated is actually done from that code, so that the filter could essentially filter it all out).
So how do I see this? Start with a clean profile, and then?
So, with a clean tree and a clean profile (except for a one-line change to nsBrowserInstance.cpp to cause the page cycler to be built in a non-debug build), I took a jprof profile using the methods in attachment 88207 [details]. If you then look at the time spent not within (-e) DocumentViewerImpl::LoadComplete(unsigned int) and within (-i) nsDocLoaderImpl::FireOnStateChange(nsIWebProgress *, nsIRequest *, int, unsigned int), you'll see that the time spent within FireOnStateChange looks like this: 70171 2 471 nsDocLoaderImpl::FireOnStateChange(nsIWebProgress*, ... 347 SharedStub 80 nsDocLoaderImpl::FireOnStateChange(nsIWebProgress*, ... 79 nsSecureBrowserUIImpl::OnStateChange(nsIWebProgress*, ... 16 nsBrowserStatusFilter::OnStateChange(nsIWebProgress*, ... 7 nsCOMPtr_base::assign_from_helper(nsCOMPtr_helper const&,. 6 nsWalletlibService::OnStateChange(nsIWebProgress*, ... 6 nsCookieService::OnStateChange(nsIWebProgress*, ... 4 nsDocShell::OnStateChange(nsIWebProgress*, ... 1 non-virtual thunk to nsBrowserStatusFilter::Release() 1 nsPrefetchService::OnStateChange(nsIWebProgress*, ... 1 nsWebShellWindow::OnStateChange(nsIWebProgress*, ... 1 nsStandardURL::SchemeIs(char const*, int*) which shows way too much time in SharedStub. I managed to verify something similar in the debugger at one point.
(Note that depending on your version of something, you might need to change "unsigned int" in the above to "unsigned".)
Output of: ./jprof -e"DocumentViewerImpl::LoadComplete(unsigned)" -i"nsDocLoaderImpl::FireOnStateChange(nsIWebProgress*, nsIRequest*, int, unsigned)" mozilla-bin jprof-log
On second thoughts, after some printf debugging, I think this is just an artefact of jprof skipping stack frames. Thus, retitling bug -- the filtering for OnStateChange is probably letting too much through, I'd think.
Summary: nsBrowserStatusFilter not always hooked up right (3.5% of pageload) → nsBrowserStatusFilter too weak for OnStateChange (3.5% of pageload)
This does a bit of filtering for OnStateChange. The patch seems to save about 2.5% of pageload time based on profiles. The new profile for OnStateChange looks like this: 70171 4 202 nsDocLoaderImpl::FireOnStateChange(nsIWebProgress*, ... 76 SharedStub 72 nsSecureBrowserUIImpl::OnStateChange(nsIWebProgress*, ... 63 nsDocLoaderImpl::FireOnStateChange(nsIWebProgress*, ... 16 nsBrowserStatusFilter::OnStateChange(nsIWebProgress*, ... 14 nsCOMPtr_base::assign_from_helper(nsCOMPtr_helper const&,. 6 nsCookieService::OnStateChange(nsIWebProgress*, ... 5 nsWalletlibService::OnStateChange(nsIWebProgress*, ... 5 nsDocShell::OnStateChange(nsIWebProgress*, nsIRequest*, ... 1 nsBrowserStatusFilter::ProcessTimeout() 1 non-virtual thunk to nsSecureBrowserUIImpl::Release() 1 nsWebShellWindow::OnStateChange(nsIWebProgress*, ... 1 nsXPIDLCString::GetSharedEmptyBufferHandle()
Comment on attachment 99270 [details] [diff] [review] patch, v. 1 (diff -u) >+ NS_NOTREACHED("unexpected state"); I actually just saw this fire while loading http://www.nytimes.com/ , and my inclination is that it's wrong anyway, so I'm inclined to just removed the NS_NOTREACHED and leave the early return.
Taking bug.
Assignee: jaggernaut → dbaron
Priority: -- → P1
Whiteboard: [patch]
Target Milestone: --- → mozilla1.2beta
Hmmm, I'm curious why nytimes caused us to enter that |else|. And yeah, it's safe to just change that to an early return, nsBrowserStatusHandler will not do anything with the call anyway.
Comment on attachment 99270 [details] [diff] [review] patch, v. 1 (diff -u) r=/sr=jag, nice use of the comma operator there :-)
Attachment #99270 - Flags: superreview+
I get a pageload speed-up of between 2.7% and 3.0%. Nice work :-)
Comment on attachment 99270 [details] [diff] [review] patch, v. 1 (diff -u) >Index: resources/content/nsBrowserStatusHandler.js >=================================================================== ... >- // Turn the throbber on. >- this.throbberElement.setAttribute("busy", true); >+ // Turn the throbber on. >+ this.throbberElement.setAttribute("busy", true); Minor nit: I know you're moving this around, but while you're touching this, please add quotes around true to prevent us from doing the bool to string conversion at runtime. Looks great otherwise! Very nice! r=caillon.
Attachment #99270 - Flags: review+
Comment on attachment 99270 [details] [diff] [review] patch, v. 1 (diff -u) r/sr=darin (nice!)
Fix checked in to trunk, 2002-09-16 07:13 PDT.
Status: NEW → RESOLVED
Closed: 24 years ago
Resolution: --- → FIXED
WWhat do you guys want in the way of verification? Is this something perf qa or the necko test lab should be looking at?
well, tinderbox could be used to verify that the bug is fixed. after this patch went in, iirc, we saw the expected improvement in Tp on tinderbox. you or perf qa should be able to reproduce the numbers by testing before and after builds against cowtools.
-> jrgm, per kerz
QA Contact: benc → jrgm
I remember when this landed, and we saw the gain. verified.
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: