Tomcat 7 taking ages to start up after upgrade
- by Lawrence
I recently updated my server installation from Tomcat 6 to Tomcat 7, in order to take advantage of better connection pooling. My project uses Hibernate, for object persistance, a Mysql 5.5.20 database, and memcached for caching. When I was using Tomcat 6, Tomcat would start in about 8 seconds. After moving to Tomcat 7, it now takes between 75 - 80 seconds to start (this is on a Macbook pro 15", core i7 2Ghz, 8Gb of RAM).
The only thing that has really changed between during the move from Tomcat 6 to 7 has been my context.xml file, which controls the connection pooling information:
<Context antiJARLocking="true" reloadable="true" path="">
<Resource name="jdbc/test-db"
auth="Container"
type="javax.sql.DataSource"
factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
testOnBorrow="true"
testOnReturn="false"
testWhileIdle="true"
validationQuery="SELECT 1"
validationQueryTimeout="20000"
validationInterval="30000"
timeBetweenEvictionRunsMillis="60000"
logValidationErrors="true"
autoReconnect="true"
username="webuser"
password="xxxxxxx"
driverClassName="com.mysql.jdbc.Driver"
url="jdbc:mysql://databasename.us-east-1.rds.amazonaws.com:3306/test-db"
maxActive="15"
minIdle="2"
maxIdle="10"
maxWait="10000"
maxAge="7200000"/>
</Context>
Now, as you can see, the database is running on Amazon RDS (where our live servers are), and thus is about 200ms round trip time away from my machine. I have already checked that I have security permissions to that database from my machine, (and anyway, it connects after 75 secs, so it cant be that).
My initial thought was that Tomcat 7 and hibernate are doing something weird (like pre-instantiating a bunch of connections or something), and the latency to the database is amplifying the effects.
While trying to diagnose the problem, I used jstack to get a stack trace of the Tomcat 7 server while its doing its startup thing.
Here is the stack trace...
Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.12-b01-434 mixed mode):
"Attach Listener" daemon prio=9 tid=7fa4c0038800 nid=0x10c39a000 waiting on condition [00000000]
java.lang.Thread.State: RUNNABLE
"Abandoned connection cleanup thread" daemon prio=5 tid=7fa4bb810000 nid=0x10f3ba000 in Object.wait() [10f3b9000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <7f40a0070> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <7f40a0070> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at com.mysql.jdbc.NonRegisteringDriver$1.run(NonRegisteringDriver.java:93)
"PoolCleaner[545768040:1352724902327]" daemon prio=5 tid=7fa4be852800 nid=0x10e772000 in Object.wait() [10e771000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <7f40c7c90> (a java.util.TaskQueue)
at java.util.TimerThread.mainLoop(Timer.java:509)
- locked <7f40c7c90> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:462)
"localhost-startStop-1" daemon prio=5 tid=7fa4bd034800 nid=0x10d66b000 runnable [10d668000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
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 <7f3673be0> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3014)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3467)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3456)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3997)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2713)
- locked <7f366a1c0> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.ConnectionImpl.configureClientCharacterSet(ConnectionImpl.java:1930)
at com.mysql.jdbc.ConnectionImpl.initializePropsFromServer(ConnectionImpl.java:3571)
at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2445)
at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2215)
- locked <7f366a1c0> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:813)
at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
at sun.reflect.GeneratedConstructorAccessor10.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:399)
at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:334)
at org.apache.tomcat.jdbc.pool.PooledConnection.connectUsingDriver(PooledConnection.java:278)
at org.apache.tomcat.jdbc.pool.PooledConnection.connect(PooledConnection.java:182)
at org.apache.tomcat.jdbc.pool.ConnectionPool.createConnection(ConnectionPool.java:699)
at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:631)
at org.apache.tomcat.jdbc.pool.ConnectionPool.init(ConnectionPool.java:485)
at org.apache.tomcat.jdbc.pool.ConnectionPool.<init>(ConnectionPool.java:143)
at org.apache.tomcat.jdbc.pool.DataSourceProxy.pCreatePool(DataSourceProxy.java:116)
- locked <7f34f0dc8> (a org.apache.tomcat.jdbc.pool.DataSource)
at org.apache.tomcat.jdbc.pool.DataSourceProxy.createPool(DataSourceProxy.java:103)
at org.apache.tomcat.jdbc.pool.DataSourceFactory.createDataSource(DataSourceFactory.java:539)
at org.apache.tomcat.jdbc.pool.DataSourceFactory.getObjectInstance(DataSourceFactory.java:237)
at org.apache.naming.factory.ResourceFactory.getObjectInstance(ResourceFactory.java:143)
at javax.naming.spi.NamingManager.getObjectInstance(NamingManager.java:304)
at org.apache.naming.NamingContext.lookup(NamingContext.java:843)
at org.apache.naming.NamingContext.lookup(NamingContext.java:154)
at org.apache.naming.NamingContext.lookup(NamingContext.java:831)
at org.apache.naming.NamingContext.lookup(NamingContext.java:168)
at org.apache.catalina.core.NamingContextListener.addResource(NamingContextListener.java:1061)
at org.apache.catalina.core.NamingContextListener.createNamingContext(NamingContextListener.java:671)
at org.apache.catalina.core.NamingContextListener.lifecycleEvent(NamingContextListener.java:270)
at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:90)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5173)
- locked <7f46b07f0> (a org.apache.catalina.core.StandardContext)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
- locked <7f46b07f0> (a org.apache.catalina.core.StandardContext)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1559)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1549)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:680)
"Catalina-startStop-1" daemon prio=5 tid=7fa4b7a5e800 nid=0x10d568000 waiting on condition [10d567000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <7f480e970> (a java.util.concurrent.FutureTask$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:218)
at java.util.concurrent.FutureTask.get(FutureTask.java:83)
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:1123)
- locked <7f453c630> (a org.apache.catalina.core.StandardHost)
at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:800)
- locked <7f453c630> (a org.apache.catalina.core.StandardHost)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
- locked <7f453c630> (a org.apache.catalina.core.StandardHost)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1559)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1549)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:680)
"GC Daemon" daemon prio=2 tid=7fa4b9912800 nid=0x10d465000 in Object.wait() [10d464000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <7f4506d28> (a sun.misc.GC$LatencyLock)
at sun.misc.GC$Daemon.run(GC.java:100)
- locked <7f4506d28> (a sun.misc.GC$LatencyLock)
"Low Memory Detector" daemon prio=5 tid=7fa4b480b800 nid=0x10c8ae000 runnable [00000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" daemon prio=9 tid=7fa4b480b000 nid=0x10c7ab000 waiting on condition [00000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" daemon prio=9 tid=7fa4b480a000 nid=0x10c6a8000 waiting on condition [00000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=9 tid=7fa4b4809800 nid=0x10c5a5000 runnable [00000000]
java.lang.Thread.State: RUNNABLE
"Surrogate Locker Thread (Concurrent GC)" daemon prio=5 tid=7fa4b4808800 nid=0x10c4a2000 waiting on condition [00000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=8 tid=7fa4b793f000 nid=0x10c297000 in Object.wait() [10c296000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <7f451c8f0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <7f451c8f0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=10 tid=7fa4b793e000 nid=0x10c194000 in Object.wait() [10c193000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <7f452e168> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <7f452e168> (a java.lang.ref.Reference$Lock)
"main" prio=5 tid=7fa4b7800800 nid=0x104329000 waiting on condition [104327000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <7f480e9a0> (a java.util.concurrent.FutureTask$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:218)
at java.util.concurrent.FutureTask.get(FutureTask.java:83)
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:1123)
- locked <7f451fd90> (a org.apache.catalina.core.StandardEngine)
at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:302)
- locked <7f451fd90> (a org.apache.catalina.core.StandardEngine)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
- locked <7f451fd90> (a org.apache.catalina.core.StandardEngine)
at org.apache.catalina.core.StandardService.startInternal(StandardService.java:443)
- locked <7f451fd90> (a org.apache.catalina.core.StandardEngine)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
- locked <7f453e810> (a org.apache.catalina.core.StandardService)
at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:732)
- locked <7f4506d58> (a [Lorg.apache.catalina.Service;)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
- locked <7f44f7ba0> (a org.apache.catalina.core.StandardServer)
at org.apache.catalina.startup.Catalina.start(Catalina.java:684)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:322)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:451)
"VM Thread" prio=9 tid=7fa4b7939800 nid=0x10c091000 runnable
"Gang worker#0 (Parallel GC Threads)" prio=9 tid=7fa4b7802000 nid=0x10772b000 runnable
"Gang worker#1 (Parallel GC Threads)" prio=9 tid=7fa4b7802800 nid=0x10782e000 runnable
"Gang worker#2 (Parallel GC Threads)" prio=9 tid=7fa4b7803000 nid=0x107931000 runnable
"Gang worker#3 (Parallel GC Threads)" prio=9 tid=7fa4b7804000 nid=0x107a34000 runnable
"Gang worker#4 (Parallel GC Threads)" prio=9 tid=7fa4b7804800 nid=0x107b37000 runnable
"Gang worker#5 (Parallel GC Threads)" prio=9 tid=7fa4b7805000 nid=0x107c3a000 runnable
"Gang worker#6 (Parallel GC Threads)" prio=9 tid=7fa4b7805800 nid=0x107d3d000 runnable
"Gang worker#7 (Parallel GC Threads)" prio=9 tid=7fa4b7806800 nid=0x107e40000 runnable
"Concurrent Mark-Sweep GC Thread" prio=9 tid=7fa4b78e3800 nid=0x10bd0b000 runnable
"Gang worker#0 (Parallel CMS Threads)" prio=9 tid=7fa4b78e2800 nid=0x10b305000 runnable
"Gang worker#1 (Parallel CMS Threads)" prio=9 tid=7fa4b78e3000 nid=0x10b408000 runnable
"VM Periodic Task Thread" prio=10 tid=7fa4b4815800 nid=0x10c9b1000 waiting on condition
"Exception Catcher Thread" prio=10 tid=7fa4b7801800 nid=0x104554000 runnable
JNI global references: 919
The only thing I can figure out from this is that it looks like the mysql jdbc drivers might have something to do with the long start up (the various stack traces I took during the start up process all pretty much look the same as this).
Could anyone shed some light on what might be causing this? Have I done something dense in my context.xml? Is hibernate perhaps to blame?
