8700 - nsJSContext::InitContext() takes 50% of the CPU time when loading test9

Status: VERIFIED FIXED

(Core :: JavaScript Engine, defect, P3)

Description

[Pierre Saslawsky]

Below is an excerpt from a message I posted on May 7th:

-------------
I profiled Viewer on a Mac while loading "test9.html" and found out that 49%
of the time is spent in nsJSContext::InitContext(nsIScriptGlobalObject*).

The table below shows that 61.8% of the time was spent inside just 8 calls to
DocumentViewerImpl::Init() and the main culprits are 4 calls to
nsJSContext::InitContext() that represent 25.1%, and 6 more calls that
represent another 24.2%.


Function                              #Calls              %Time
(...)
NET_NGLayoutConverter                     12                67.8
nsDocumentBindInfo::OnStartBinding        12                67.6
nsWebShell::Embed                          8                66.8
--DocumentViewerImpl::Init                 8                61.8
----GlobalWindowImpl::SetNewDocument       4                32.6
------nsJSContext::InitContext             4                25.1 <---
------nsJSContext::GC                      4                 6.7
----nsWebShell::GetScriptableObject        8                28.4
------nsWebShell::CreateScriptEnvironment  8                28.4
--------NS_CreateContext                   7                28.4
----------nsJSContext::InitContext         6                24.2 <---
----------nsServiceManager::GetService     6                 4.2
--DocumentViewerImpl::Release              1                 5.0


I did a similar test with "test0.html" which has only one webshell:
nsJSContext::InitContext() was called once and represented 11.9% of the CPU
time. With "test9b.html" which has 2 webshells, it was called twice for a
total of 33.1% (17.0 + 16.1).
-------------

These measurements have been done on Mac. It would be interesting to check
whether similar results are obtained on Windows and Unix.

Below is a response I got from Vidur:

-------------
I'm more than happy to work with someone to get more profiling information about
nsJSContext::InitContext itself.

The bulk of what happens in that methods is JavaScript core class initialization,
LiveConnect initialization and XPConnect initialization for the context. While
most of this is out of my control (i.e. there are other owners that need to be
pinged about them), it's not inconceivable that there's code being called by the
initializers that belongs to me and could contribute to the high numbers you see.
The code that I have in mind is nsJSUtils::nsLookupGlobalName() and
GlobalWindowImpl::GetProperty(). [As an experiment, try profiling with the code
for both commented out and see if it makes a substantial difference.]

Again, I think there's a lot of potential for improvement, but I don't want to
drive this right now. I am, however, willing to work with anyone who wants to
make nsJSContext::InitContext more efficient.
-------------

Comment 1

[Mike McCabe]

Accepting this bug.

I won't be looking at it for a while, but it could end up being relevant to
XPConnect.

cc'ing jband, brendan, mang.

Comment 2

[Pierre Saslawsky]

This bug may be related to #11421.

Comment 3

[Brendan Eich [:brendan]]

Adding sfraser and waterson, time team stalwarts.

/be

Comment 4

[leger]

Bulk add of "perf" to new keyword field.  This will replace the [PERF] we were
using in the Status Summary field.

Comment 5

[Peter Trudelle]

On behalf of PorkJockeys: putting on beta1 radar, per beta criteria priority #2 
- performance on Mac is not within beta metrics. removing extraneous tags

Comment 6

[leger]

tever, how does this look with latest build.  Performance is relative to type of 
page.  Let's get latest results in comparison with Mac 4.72.

Comment 7

[Mike McCabe]

John is setting up a Quantify environment.

Comment 8

[John Bandhauer]

I'm marking this fixed. I made two changes: I fixed bug 26879 such that we are 
no longer compiling and running some JS code upon each JSContext creation. And, 
I added code to the init of xpcom to force the .xpt files to be read upon xpcom 
startup rather than when first used when creating the first JSContext. The 
former speeds things up a bit, the later really just shifts the cost to a 
different place in the code - but does allow for better profiling.

I am not otherwise seeing anything in my Quatify runs on Win32 that shows 
context creation doing anything particularly slow or unreasonable. There may 
have been other slow things going on back in May 1999 that have since been 
fixed.

Comment 9

[Tom Everingham]

Not set up with a profiler so I'll take your word on this.
Marking verified.