aspose file tools*
The moose likes JBoss/WildFly and the fly likes Server boot time issue Big Moose Saloon
  Search | Java FAQ | Recent Topics | Flagged Topics | Hot Topics | Zero Replies
Register / Login


Win a copy of Soft Skills this week in the Jobs Discussion forum!
JavaRanch » Java Forums » Products » JBoss/WildFly
Bookmark "Server boot time issue" Watch "Server boot time issue" New topic
Author

Server boot time issue

Dan Seaver
Greenhorn

Joined: Mar 02, 2010
Posts: 8
I've just upgraded from JBoss AS 4.2 to 5.1 and have encountered a boot time issue that did not exist with 4.2. If I start the server while connected to my company's VPN, it takes 5:32 mins. With 4.2, it took about 1 min. If I start the server disconnected from the VPN, but still connected to internet (high speed cable), it takes about 1:40 mins. If I disable my network card, it takes 1:10 mins. I have not made any modifications to the server configuration that ships in the jboss-5.1.0.GA-jdk6.zip (also tried the jboss-5.1.0.GA.zip with the same results).

Any ideas on why the server startup would be network sensitive?

After turning on debug level logging for everything, I found these performance killers:
2010-02-25 12:56:31,003 DEBUG [org.jboss.management.j2ee.deployers.LocalJBossServerDomain] (main) handleNotification: javax.management.Notification[source=jboss.system:service=ServiceController][type=org.jboss.system.ServiceMBean.start][message=]
2010-02-25 12:56:43,466 FINE [sun.rmi.transport.tcp] (RMI Scheduler(0)) RMI Scheduler(0): close connection
2010-02-25 12:56:43,481 FINE [sun.rmi.transport.tcp] (RMI TCP Connection(2)-3.7.149.84) RMI TCP Connection(2)-3.7.149.84: (port 1851) connection closed
2010-02-25 12:56:43,481 FINE [sun.rmi.transport.tcp] (RMI TCP Connection(2)-3.7.149.84) RMI TCP Connection(2)-3.7.149.84: close connection
2010-02-25 12:56:43,481 FINE [sun.rmi.transport.tcp] (RMI Scheduler(0)) RMI Scheduler(0): close connection
2010-02-25 12:56:43,481 FINE [sun.rmi.transport.tcp] (RMI TCP Connection(1)-3.7.149.84) RMI TCP Connection(1)-3.7.149.84: (port 1090) connection closed
2010-02-25 12:56:43,481 FINE [sun.rmi.transport.tcp] (RMI TCP Connection(1)-3.7.149.84) RMI TCP Connection(1)-3.7.149.84: close connection
2010-02-25 12:57:56,347 DEBUG [org.jboss.remoting.ServerInvoker] (main) SocketServerInvoker[HCU-C1WYGC1:4446] added org.jboss.profileservice.management.upload.remoting.DeployHandler@18309b0 for subsystem 'DeploymentManager'

As you can see, SocketServerInvoker takes over a minute.

2010-02-25 12:57:56,347 DEBUG [org.jboss.profileservice.management.ManagementViewImpl] (main) addTemplate: org.jboss.resource.deployers.management.DsDataSourceTemplate@98843
2010-02-25 12:57:56,347 DEBUG [org.jboss.profileservice.management.ManagementViewImpl] (main) addTemplate: org.jboss.resource.deployers.management.DsDataSourceTemplate@1d11c11
2010-02-25 12:59:21,346 DEBUG [org.jboss.profileservice.remoting.ProxyFactory] (main) Bound ProfileService proxy under: ProfileService
2010-02-25 12:59:21,424 DEBUG [org.jboss.profileservice.remoting.ProxyFactory] (main) Created ManagementView proxy

Here, ProxyFactory takes over a minute

2010-02-25 12:59:28,508 DEBUG [org.jboss.aop.microcontainer.beans.GenericBeanAspectFactory] (main) Creating advice InvocationContextInterceptor with loader null
2010-02-25 12:59:32,573 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-14) Periodic recovery - second pass <Thu, 25 Feb 2010 12:59:32>
2010-02-25 12:59:32,589 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] (Thread-14) AtomicActionRecoveryModule: Second pass
2010-02-25 13:00:24,142 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Start expire sessions StandardManager at 1267131624142 sessioncount 0

Here, ManagerBase takes nearly a minute.

Thanks for any / all help you can throw my way.
Dan
Peter Johnson
author
Bartender

Joined: May 14, 2008
Posts: 5845
    
    7

Dan, welcome to Java Ranch!

Looks like it is waiting on a network request and either that request is taking a long time or is timing out. A scan through the forums will probably yield several posts asking out similar networking issues, though yours is the first to mention VPN (I haven't noticed the delay when connected to my VPN). The thing we usually recommend is to take a thread dump during that 1-minute wait to verify that it is indeed waiting on the network (it usually is, but at least going through the motions eliminates other possibilities). And there is usually nothing that can be done about it (though I vaguely recall that fixing the /etc/hosts file helped in one case) other than locating and correcting the network issue.


JBoss In Action
Mark E Hansen
Ranch Hand

Joined: Apr 01, 2009
Posts: 650
Also, as the log file is not written asynchronously, won't writing more information to it cause the performance to drop? Perhaps turning the log level up to DEBUG for the entire site just made things worse?

I know that I've gone to great lengths to reduce the amount of information written to the log file, and found it improved the start-up time somewhat.

I don't expect this to resolve the issue at hand, just that I think it may be contributing to it.

Peter Johnson
author
Bartender

Joined: May 14, 2008
Posts: 5845
    
    7

Yes, reducing the logging level usually helps speed things up, but when there is a 1 minute time span between log entries, changing the level does not help (at least, not for reducing that 1 minute).
Dan Seaver
Greenhorn

Joined: Mar 02, 2010
Posts: 8
Thanks for the warm welcome, Peter.
I don't understand why JBoss would be doing anything over the network. I'm running it locally and haven't configured anything to look elsewhere. Maybe the thread dump will help?
I turned on the debug level logging for the console and did a <ctrl><break> when the logging paused to get the following dump:


I don't see anything that points to the network, but maybe I'm not wearing the right glasses.

Thanks for any help you may have.

Dan
Jaikiran Pai
Marshal

Joined: Jul 20, 2005
Posts: 10288
    
169



Those are bugs which have been fixed:

https://jira.jboss.org/jira/browse/JBCL-117

https://jira.jboss.org/jira/browse/JBCL-118

Later versions of JBoss AS have this fix.

[My Blog] [JavaRanch Journal]
Dan Seaver
Greenhorn

Joined: Mar 02, 2010
Posts: 8
Thanks much Jaikiran.
I haven't applied patches to JBoss in the past. Can you point me to a doc for doing this?
Looks like JBCL-118 has some other files that need to be applied as well. How do I get those applied?

Or...Do I need to upgrade to JBoss 6.0.M2 to get the fix. I'd rather do dev work against a GA version if possible.
Do you know if there are other point releases scheduled for 5.1.0 that will include the fix?

Thanks again,
Dan
Jaikiran Pai
Marshal

Joined: Jul 20, 2005
Posts: 10288
    
169

Dan Seaver wrote:
I haven't applied patches to JBoss in the past. Can you point me to a doc for doing this?

Actually, that patch is spread across various projects outside the AS. So the easiest way to *build* an AS to get those patches is to update the AS' component-matrix/pom.xml (which dictates the version of other projects being pulled in) to use the 2.1.3.GA version of jboss-vfs project.

So:
1) Checkout AS 5.1.0 from tag http://anonsvn.jboss.org/repos/jbossas/tags/JBoss_5_1_0_GA/
2) Build the AS as per the instructions here (section JBossAS 5.x and Earlier versions)
3) Once the AS is built, just run it once to make sure everything is fine.
4) Edit the AS_CHECKOUT/component-matrix/pom.xml to change the jboss vfs version to:


(currently it contains 2.1.2.GA)

and rebuild the AS again. That should get you the fix.

Dan Seaver wrote:

Do you know if there are other point releases scheduled for 5.1.0 that will include the fix?


There are no more 5.1.0 community AS releases.
Dan Seaver
Greenhorn

Joined: Mar 02, 2010
Posts: 8
Thanks much! That solved the performance problem. Now the server starts up in 0:46 instead of 5:07!
 
I agree. Here's the link: http://aspose.com/file-tools
 
subject: Server boot time issue