|<< Back to previous view|
[GLASSFISH-15393] [PERF] Admin Console - slow load time Created: 30/Dec/10 Updated: 18/Jan/12
|Remaining Estimate:||Not Specified|
|Time Spent:||Not Specified|
|Original Estimate:||Not Specified|
DAS/Instances on: Solaris 10, Sparc, JDK6u23
|File Attachments:||dasonly-server.log dasonly-trace.log multinode-cluster-hudson-console.txt perf-logging.zip server-logs-take2.jar server.log singlenode-two-instance-server-trace.log singlenode-twoinstance-cluster-creation-log.txt singlenode-twoinstance-server.log twonode-threeinstance-server-trace.log twonode-twoinstance-server-trace.log|
|Tags:||3_1-exclude 3_1-need_more_info 3_1-next|
|Participants:||Anissa Lam, Chris Kasso, Harshad Vilekar, Hong Zhang, Jason Lee, Joe Di Pol, Nazrul, Scott Fordin and sirajg|
The numbers below show the time taken by Admin Console main screen to show up in the Browser - for the first time after fresh install.
For http, the time is counted after entering the URL in the browser, and pressing return. In case of https, the time is counted after confirming security exception prompt.
1. DAS only (secure admin enabled): 30+ sec
2. Single node, two instance cluster (secure admin not enabled): 100+ sec
3. Two node, two instance cluster (secure admin enabled): 200+ sec
This is by no means any methodical performance test, but simply shows "perceived load time" on Solaris 10 Sparc machines (Niagara, T1000), that are used for day to day testing.
|Comment by Anissa Lam [ 03/Jan/11 08:28 AM ]|
Several developer is trying to look into this. The latest finding from Jason:
On 1/3/11 8:14 AM, Jason Lee wrote:
|Comment by Hong Zhang [ 03/Jan/11 06:11 PM ]|
Harshad, can you please attach the DAS server.log for all the three scenarios? Want to see how the loading time of the admin gui application compare in the test environment. Thanks.
|Comment by Harshad Vilekar [ 04/Jan/11 09:22 AM ]|
Attached the server logs for the two scenarios
|Comment by Jason Lee [ 04/Jan/11 09:43 AM ]|
This archive contains the jars I updated to add logging to the console. Extract this in your GlassFish install root and restart your server.
|Comment by Hong Zhang [ 04/Jan/11 06:15 PM ]|
|Comment by Harshad Vilekar [ 05/Jan/11 12:01 PM ]|
Attaching logs for scenario #1 and #2 with following option enabled in DAS domain.xml.
Logs for #3 are not yet available (the hosts are running other tests - so latest nightly build is not yet installed).
|Comment by Hong Zhang [ 05/Jan/11 01:58 PM ]|
Harshad: thanks for attaching the server.log with the tracing turned on. From your numbers, there is still significant difference between DAS-only and cluster scenarios.
1. The DAS only scenario:
M1.[#|2011-01-05T09:53:55.857-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=92;_ThreadName=Thread-1;|Container : com.sun.enterprise.web.WebContainer Mark BEFORE_CONTAINER_SETUP at 652|#]
M2.[#|2011-01-05T09:53:55.859-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=92;_ThreadName=Thread-1;|Mark CONTAINERS_SETUP_DONE at 3526|#]
M3.[#|2011-01-05T09:53:55.864-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=92;_ThreadName=Thread-1;|Container : web Mark START at 3613|#]
M4.[#|2011-01-05T09:53:55.864-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=92;_ThreadName=Thread-1;|Container : web Mark STARTED at 7106|#]
2. The single node, two cluster instance scenario:
The admin console application loading took 41.302 s. And the main time was also spent in the container initialization and loading components in web container: the container initialization took 14.341s (the time difference for mark 1 and mark 2) and the loading components in web container took 21.720s (the time difference for mark 3 and mark 4).
M1.[#|2011-01-05T11:22:58.378-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=120;_ThreadName=Thread-1;|Container : com.sun.enterprise.web.WebContainer Mark BEFORE_CONTAINER_SETUP at 4057|#]
M2.[#|2011-01-05T11:22:58.386-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=120;_ThreadName=Thread-1;|Mark CONTAINERS_SETUP_DONE at 18398|#
M3.[#|2011-01-05T11:22:58.412-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=120;_ThreadName=Thread-1;|Container : web Mark START at 19515|#]
M4.[#|2011-01-05T11:22:58.413-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=120;_ThreadName=Thread-1;|Container : web Mark STARTED at 41235|#]
Your DAS-only scenario seems to be consistent with what we observed, but your cluster scenario just seems taking much longer for every step, especially in container initialization and component loading. Can you share the exact steps of your cluster scenario, how did you create the cluster etc? And were there any other things running at the same time on the system when you tested? Tom did a testing on Niagra system today too (see issue 15412 for more details), but his numbers on DAS-only and cluster scenario (where 30 local instances were created) were more consistent with what we observed on other systems. We need to figure out what is different on your testing system. Thanks.
|Comment by Harshad Vilekar [ 05/Jan/11 02:30 PM ]|
Attaching Cluster Creation Steps: singlenode-twoinstance-cluster-creation-log.txt
Multi Node Two Instance Cluster Creation Steps are already attached: multinode-cluster-hudson-console.txt
|Comment by Hong Zhang [ 05/Jan/11 06:17 PM ]|
Harshad: I don't see anything unusual in the cluster creation steps. Tom was suggesting one possible cause is short of memory on the system, quoting his comments on issue 15412:
Can you share the test system configuration, how much memory it has etc? Thanks.
|Comment by Chris Kasso [ 06/Jan/11 04:14 PM ]|
I wanted to add a data point.
I created a two node, four instance cluster:
./asadmin list-instances -l
The DAS is running on a S10/Sparc box (aha.us.oracle.com). The nodes are on S11 Express/x86 system. The firefox (3.6.10) browser was on the S11/x86 box.
I saw no difference in the Admin Console startup time with three different scenarios:
1) Secure Admin enabled: 67 seconds
Given the age of the Solaris 10 Sparc box (SunBlade 1500), about a minute to start the Console is expected.
|Comment by Harshad Vilekar [ 06/Jan/11 05:44 PM ]|
Hong, I'm attaching server log - with trace enabled - for multi node cluster (scenario #3).
File name:twonode-threeinstance-server-trace.log. The relevant startup log entries begin at line 457.
asadmin list-instances --long
With latest nightly build - Admin Console took about 140+ seconds to load on above config (this was tested after running some other test).
|Comment by Hong Zhang [ 06/Jan/11 06:03 PM ]|
Looking at the server.log, the gui application loading took 36.067s, out of the 140s of the total console accessing time.
And for the application loading part, the container initialization (8.394s) and component loading (24.442s) still took most of the time especially the component loading part.
M1.[#|2011-01-06T17:19:26.048-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=134;_ThreadName=Thread-1;|Container : com.sun.enterprise.web.WebContainer Mark BEFORE_CONTAINER_SETUP at 2481|#
M2.[#|2011-01-06T17:19:26.057-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=134;_ThreadName=Thread-1;|Mark CONTAINERS_SETUP_DONE at 10875|#]
M3.[#|2011-01-06T17:19:26.090-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=134;_ThreadName=Thread-1;|Container : web Mark START at 11558|#]
M4[#|2011-01-06T17:19:26.091-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=134;_ThreadName=Thread-1;|Container : web Mark STARTED at 36000|#]
|Comment by Harshad Vilekar [ 06/Jan/11 06:36 PM ]|
Notes about numbers reported in twonode-threeinstance-server-trace.log:
1. Hardware config of the machine used to get these numbers:
========================= CPUs ===============================================
========================= IO Configuration =========================
2. One EJB App was deployed on the cluster when these log entries are generated.
|Comment by Harshad Vilekar [ 06/Jan/11 07:29 PM ]|
One more data point: twonode-twoinstance-server-trace.log
for following configuration:
asadmin list-instances --long
No apps are deployed.
|Comment by Hong Zhang [ 07/Jan/11 07:17 AM ]|
M1. [#|2011-01-06T19:03:01.872-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=130;_ThreadName=Thread-1;|Container : com.sun.enterprise.web.WebContainer Mark BEFORE_CONTAINER_SETUP at 3972|#]
M2. [#|2011-01-06T19:03:01.882-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=130;_ThreadName=Thread-1;|Mark CONTAINERS_SETUP_DONE at 15038|#]
M3. [#|2011-01-06T19:03:01.913-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=130;_ThreadName=Thread-1;|Container : web Mark START at 15705|#]
M4. [#|2011-01-06T19:03:01.914-0800|INFO|oracle-glassfish3.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=130;_ThreadName=Thread-1;|Container : web Mark STARTED at 37291|#]
|Comment by Harshad Vilekar [ 07/Jan/11 04:45 PM ]|
Here are the updated results (take 2) showing Admin Console load time, with clean environment:
1. all test machines now use locally installed jdk (earlier, JDK was installed in remote NFS mounted directory)
Time taken: 105 secs
Time taken: 125 seconds
Config 2.5: Cluster on two hosts (host1: DAS + in1, host2: in2), secure admin enabled:
Time taken: 130 seconds
Server logs for config 2.1 to 2.5 attached: server-logs-take2.jar
|Comment by Hong Zhang [ 07/Jan/11 06:42 PM ]|
Harshad: thanks for re-running the tests!
The console accessing time do seem pretty long in the tests (105s-130s), but maybe this is expected with the machine configuration (resource constraint)?
|Comment by Nazrul [ 10/Jan/11 05:44 PM ]|
This issue happens on a specific hardware. Should we exclude this from 3.1?
We should spend time on this and fix it during 3.2.
|Comment by Nazrul [ 11/Jan/11 01:20 AM ]|
Excluding from 3.1 count.
|Comment by Chris Kasso [ 26/Jan/11 04:17 PM ]|
After discussing this with the submitter we decided to clear the "blocker" status.
|Comment by Scott Fordin [ 23/Mar/11 06:57 PM ]|
Need more info to add issue to 3.1 Release Notes. Note at all clear what wants to be said here, either in terms of description or workaround. Is it really necessary to include in the Release Notes?
|Comment by Harshad Vilekar [ 23/Mar/11 09:00 PM ]|
No need to release note this issue. I'm Including part of the offline email thread:
— From: Chris Kasso -----------
|Comment by Anissa Lam [ 31/Oct/11 05:36 PM ]|
assign go Siraj as he is leading the GUI initial performance improvement effort.
|Comment by Joe Di Pol [ 14/Jan/12 12:18 AM ]|
We've done all the work in this area that is planned for 3.1.2. Removing the 3_1_2-review tag (see linked bugs for details).
|Comment by Anissa Lam [ 18/Jan/12 06:35 AM ]|
The issue is filed about the startup console time between DAS only and DAS with clusters.
I do not have a T1000 to run on, so i tried this on a Solaris 10 x86
DAS only, first launch - 20sec; console-preloaded - 10 sec.
Case 1: cluster with 2 instances (both using localhost-domain1)
Case 3: cluster with 2 instances ( one on localhost-domain1, one on another solaris host)