How to avoid minutes delay during Tomcat startup

Question

We're experiencing a significant delay during server startup of minutes on a number of production servers but cannot reproduce this in a test environment. Does anyone have any suggestions on how to debug or fix this? It happens on both Tomcat 6 and Tomcat 7

Our setup is Tomcat 7 Spring 3.1.2 Hibernate 4.1.7 BoneCP 0.7.1 Mysql connection 5.1.23 New Relic

It seems related to Bone CP

[MSA] DEBUG [2013-02-18 14:58:34,903] DefaultListableBeanFactory.invokeInitMethods(1498) | Invoking afterPropertiesSet() on bean with name 'dataSource'
[MSA] DEBUG [2013-02-18 14:58:34,919] BoneCPDataSource.maybeInit(148) | JDBC URL = jdbc:mysql://1.1.1.1:3306/db_prod?createDatabaseIfNotExist=true&amp;useUnicode=true&amp;characterEncoding=utf-8&amp;sessionVariables=FOREIGN_KEY_CHECKS=0, Username = xyz, partitions = 3, max (per partition) = 30, min (per partition) = 10, helper threads = 3, idle max age = 3 min, idle test period = 2 min
[MSA] DEBUG [2013-02-18 15:01:11,474] DefaultListableBeanFactory.doGetBean(245) | Returning cached instance of singleton bean 'managerTx'

Our Bone CP setup is as follows

<bean id="dataSource"
   class="org.springframework.jdbc.datasource.LazyConnectionDataSourceProxy">
   <property name="targetDataSource">
       <ref local="mainDataSource" />
   </property>
</bean>

<bean id="mainDataSource" class="com.jolbox.bonecp.BoneCPDataSource" destroy-method="close">
    <property name="driverClass" value="${jdbc.driverClassName}"/>
    <property name="jdbcUrl" value="${jdbc.url}"/>
    <property name="username" value="${jdbc.username}"/>
    <property name="password" value="${jdbc.password}"/>
    <property name="idleMaxAgeInMinutes" value="3"/>
    <property name="idleConnectionTestPeriodInMinutes" value="2"/>
    <property name="maxConnectionsPerPartition" value="30"/>
  <property name="minConnectionsPerPartition" value="10"/>
  <property name="partitionCount" value="3"/>
  <property name="acquireIncrement" value="2"/>
  <property name="statementsCacheSize" value="100"/>
  <property name="releaseHelperThreads" value="3"/>
</bean>

Based on Mindas suggestion. Here's a stacktrace of what's happening during the wait

"pool-3-thread-1" prio=10 tid=0x00007fd26c004000 nid=0x5c7e runnable   [0x00007fd2c4722000]
java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:150)
    at java.net.SocketInputStream.read(SocketInputStream.java:121)
    at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
    at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
    at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
    - locked <0x00000000ccf12490> (a com.mysql.jdbc.util.ReadAheadInputStream)
    at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3049)
    at com.mysql.jdbc.MysqlIO.readPacket(MysqlIO.java:597)
    at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1084)
    at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2465)
    at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2498)
    at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2283)
    - locked <0x00000000ccf04310> (a com.mysql.jdbc.JDBC4Connection)
    at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:822)
    at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:525)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
    at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:404)
    at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:317)
    at java.sql.DriverManager.getConnection(DriverManager.java:579)
    at java.sql.DriverManager.getConnection(DriverManager.java:221)
    at com.jolbox.bonecp.BoneCP.obtainRawInternalConnection(BoneCP.java:256)
    at com.jolbox.bonecp.ConnectionHandle.obtainInternalConnection(ConnectionHandle.java:211)
    at com.jolbox.bonecp.ConnectionHandle.<init>(ConnectionHandle.java:170)
    at com.jolbox.bonecp.BoneCP.<init>(BoneCP.java:371)
    at com.jolbox.bonecp.BoneCPDataSource.maybeInit(BoneCPDataSource.java:150)
    at com.jolbox.bonecp.BoneCPDataSource.getConnection(BoneCPDataSource.java:112)
    at org.springframework.jdbc.datasource.LazyConnectionDataSourceProxy.afterPropertiesSet(LazyConnectionDataSourceProxy.java:163)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1514)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1452)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:294)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:225)
    - locked <0x00000000dc56d780> (a java.util.concurrent.ConcurrentHashMap)
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:291)
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:193)
    at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:322)
    at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:106)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1360)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1118)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:517)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:294)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:225)
    - locked <0x00000000dc56d780> (a java.util.concurrent.ConcurrentHashMap)
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:291)

See http://wiki.apache.org/tomcat/HowTo/FasterStartUp, especially the Entropy Source section, if you are running production in a Unix environment. — Larry Shatzer, Mar 01 '13 at 15:27
I never saw any entropy related warnings appear in the logs. — Marc, Mar 04 '13 at 18:21
But JDBC connections do not log that like the Tomcat container. I gave that as an example of another area where entropy matters. — Larry Shatzer, Mar 04 '13 at 18:54
installed haveget on the server. Doesn't seem to make a difference — Marc, Mar 04 '13 at 19:52
I would look at the answer @mindas provided, in his edit. Or try writing a simple class that connects to the database outside of tomcat so you can time it, and remove various things like boncp from the equation. — Larry Shatzer, Mar 04 '13 at 20:01

score 2 · Answer 1 · edited May 23 '17 at 11:49

2

Send kill -3 (if on Unix, or corresponding signal if on Windows) to your Tomcat process id while it's stuck. You will see all the threads with complete stack traces in catalina.out.

EDIT: stacktrace snapshot appears to be in the middle of initiating a connection. Can you verify (using local mysql client) that you can connect without any delays (hint: DNS problems) and execute commands quickly -- using exactly the same configuration as JDBC?

edited May 23 '17 at 11:49

Community

1
1

answered Mar 01 '13 at 12:06

mindas

26,463
15
97
154

Yes, responds quite quickly – Marc May 09 '13 at 17:33

How to avoid minutes delay during Tomcat startup

1 Answers1