PDA

View Full Version : Resin takes 60 seconds to start


hff135
06-18-2010, 04:47 AM
My Resin server starts up pretty quickly as you can see below. However, it does not serve pages right after it's started up. Instead, there's another 60 second delay before it will serve any pages.


[2010/06/17 22:20:24.803] Host[] active
[2010/06/17 22:20:24.816] hmux listening to 192.168.1.114:6800
[2010/06/17 22:20:24.831] http listening to *:56
[2010/06/17 22:20:24.839] Server[id=,cluster=app-tier] active
[2010/06/17 22:20:24.841] Resin started in 4529ms

2010/06/17 22:21:25: ***** Page requested=/test.html
2010/06/17 22:21:25: ***** Request params={}


I have turned on logging to 'finest', but there are no log messages from Resin between "Resin started" and "***** Page requested" (which is output from my servlet).

Can anyone help?

emil
06-18-2010, 05:42 PM
Hi,

Can you do a thread dump during the startup? That should show us what's going on.

Thanks,
Emil

hff135
06-19-2010, 04:58 AM
Starting Resin on Fri, 18 Jun 2010 22:27:45 -0600 (CST)

[2010/06/18 22:27:47.361] 'select-manager' requires Resin Professional. See http://www.caucho.com for information and licensing.
[2010/06/18 22:27:47.362]
[2010/06/18 22:27:47.362] Mac OS X 10.6.3 x86_64
[2010/06/18 22:27:47.362] Java(TM) SE Runtime Environment 1.6.0_20-b02-279-10M3065, MacRoman, en
[2010/06/18 22:27:47.362] Java HotSpot(TM) 64-Bit Server VM 16.3-b01-279, 64, mixed mode, Apple Inc.
[2010/06/18 22:27:47.362] user.name: root
[2010/06/18 22:27:47.362] resin.home = /Users/henry/usinternet/development/resin-3.1.9/
[2010/06/18 22:27:47.362] resin.root = /Users/henry/usinternet/development/resin-3.1.9/
[2010/06/18 22:27:47.362] resin.conf = /Users/henry/usinternet/development/resin-3.1.9/conf/Dogstar.conf
[2010/06/18 22:27:47.363]
[2010/06/18 22:27:47.921] WebApp[http://localhost:56] active
[2010/06/18 22:27:47.925] WebApp[http://localhost:56/charts] active
[2010/06/18 22:27:47.940] WebApp[http://localhost:56/audio-files] active
[2010/06/18 22:27:47.973] WebApp[http://localhost:56/music-files] active
[2010/06/18 22:27:48.028] WebApp[http://localhost:56/temp] active
[2010/06/18 22:27:48.034] WebApp[http://localhost:56/WEB-INF] active
[2010/06/18 22:27:48.034] Host[] active
[2010/06/18 22:27:48.073] hmux listening to localhost:6800
[2010/06/18 22:27:48.077] http listening to *:56
[2010/06/18 22:27:48.089] Server[id=,cluster=app-tier] active
[2010/06/18 22:27:48.090] Resin started in 3921ms
2010-06-18 22:28:05
Full thread dump Java HotSpot(TM) 64-Bit Server VM (16.3-b01-279 mixed mode):

"process reaper" daemon prio=5 tid=103289000 nid=0x1184ab000 runnable [1184aa000]
java.lang.Thread.State: RUNNABLE
at java.lang.UNIXProcess.waitForProcessExit(Native Method)
at java.lang.UNIXProcess.access$900(UNIXProcess.java: 17)
at java.lang.UNIXProcess$2$1.run(UNIXProcess.java:86)

"watchdog-" prio=5 tid=10327c000 nid=0x118395000 in Object.wait() [118394000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106fcc828> (a com.caucho.lifecycle.Lifecycle)
at com.caucho.boot.WatchdogProcess.runInstance(Watchd ogProcess.java:370)
- locked <106fcc828> (a com.caucho.lifecycle.Lifecycle)
at com.caucho.boot.WatchdogProcess.runInstance(Watchd ogProcess.java:173)
at com.caucho.boot.WatchdogProcess.run(WatchdogProces s.java:99)
at com.caucho.boot.WatchdogTask.run(WatchdogTask.java :108)
at java.lang.Thread.run(Thread.java:637)

"resin-10" daemon prio=5 tid=101a61000 nid=0x118292000 in Object.wait() [118291000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6c628> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6c628> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-9" daemon prio=5 tid=101a60800 nid=0x11818f000 in Object.wait() [11818e000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6c300> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6c300> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-8" daemon prio=5 tid=101a5f800 nid=0x11808c000 in Object.wait() [11808b000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6bfd8> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6bfd8> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-7" daemon prio=5 tid=101a5f000 nid=0x117f89000 in Object.wait() [117f88000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6bcb0> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6bcb0> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-6" daemon prio=5 tid=101a5e000 nid=0x117e86000 in Object.wait() [117e85000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6b988> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6b988> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-5" daemon prio=5 tid=101bcf000 nid=0x117d83000 in Object.wait() [117d82000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6b660> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6b660> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-4" daemon prio=5 tid=101bce000 nid=0x117c80000 in Object.wait() [117c7f000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6b2a0> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6b2a0> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-3" daemon prio=5 tid=101bcd800 nid=0x117b7d000 in Object.wait() [117b7c000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6af78> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6af78> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-2" daemon prio=5 tid=101bcc800 nid=0x117a7a000 in Object.wait() [117a79000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6ac50> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6ac50> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)



continued ...

hff135
06-19-2010, 04:58 AM
...

"resin-1" daemon prio=5 tid=101bcc000 nid=0x117977000 in Object.wait() [117976000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6a928> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6a928> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-0" daemon prio=5 tid=101b4e800 nid=0x117874000 in Object.wait() [117873000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106d6a5a8> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.runTasks(ThreadPoo l.java:727)
- locked <106d6a5a8> (a com.caucho.util.ThreadPool$Item)
at com.caucho.util.ThreadPool$Item.run(ThreadPool.jav a:662)
at java.lang.Thread.run(Thread.java:637)

"resin-alarm" daemon prio=5 tid=101b4d800 nid=0x117771000 waiting on condition [117770000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.caucho.util.Alarm$AlarmThread.run(Alarm.java:5 86)

"resin-thread-scheduler" daemon prio=5 tid=10320d000 nid=0x11766e000 in Object.wait() [11766d000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106ab2258> (a java.util.ArrayList)
at com.caucho.util.ThreadPool$ScheduleThread.run(Thre adPool.java:925)
- locked <106ab2258> (a java.util.ArrayList)
at java.lang.Thread.run(Thread.java:637)

"resin-thread-launcher" daemon prio=5 tid=10320c000 nid=0x11756b000 in Object.wait() [11756a000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <106abb160> (a com.caucho.util.ThreadPool$ThreadLauncher)
at com.caucho.util.ThreadPool$ThreadLauncher.startCon nection(ThreadPool.java:858)
- locked <106abb160> (a com.caucho.util.ThreadPool$ThreadLauncher)
at com.caucho.util.ThreadPool$ThreadLauncher.run(Thre adPool.java:881)
at java.lang.Thread.run(Thread.java:637)

"Low Memory Detector" daemon prio=5 tid=101809800 nid=0x116f1e000 runnable [00000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=9 tid=101808800 nid=0x116e1b000 waiting on condition [00000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=9 tid=101808000 nid=0x116d18000 waiting on condition [00000000]
java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=9 tid=101807000 nid=0x116c15000 waiting on condition [00000000]
java.lang.Thread.State: RUNNABLE

"Surrogate Locker Thread (CMS)" daemon prio=5 tid=101806800 nid=0x116b12000 waiting on condition [00000000]
java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=101801800 nid=0x116a0f000 in Object.wait() [116a0e000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <107fff108> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue .java:118)
- locked <107fff108> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue .java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finali zer.java:159)

"Reference Handler" daemon prio=10 tid=101801000 nid=0x11690c000 in Object.wait() [11690b000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <107fff120> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Refer ence.java:116)
- locked <107fff120> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=103000800 nid=0x100501000 in Object.wait() [100500000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <107f2d920> (a com.caucho.boot.ResinBoot)
at com.caucho.boot.ResinBoot.main(ResinBoot.java:298)
- locked <107f2d920> (a com.caucho.boot.ResinBoot)

"VM Thread" prio=9 tid=103089800 nid=0x116809000 runnable

"Gang worker#0 (Parallel GC Threads)" prio=9 tid=103002000 nid=0x102201000 runnable

"Gang worker#1 (Parallel GC Threads)" prio=9 tid=103002800 nid=0x102304000 runnable

"Concurrent Mark-Sweep GC Thread" prio=9 tid=103042000 nid=0x116511000 runnable
"VM Periodic Task Thread" prio=10 tid=10180b000 nid=0x117021000 waiting on condition

"Exception Catcher Thread" prio=10 tid=103001800 nid=0x10171b000 runnable
JNI global references: 930

Heap
par new generation total 19136K, used 10598K [106810000, 107cd0000, 107cd0000)
eden space 17024K, 52% used [106810000, 1070bf300, 1078b0000)
from space 2112K, 80% used [1078b0000, 107a5a880, 107ac0000)
to space 2112K, 0% used [107ac0000, 107ac0000, 107cd0000)
concurrent mark-sweep generation total 63872K, used 4773K [107cd0000, 10bb30000, 10e610000)
concurrent-mark-sweep perm gen total 21248K, used 14249K [10e610000, 10fad0000, 113a10000)

emil
06-21-2010, 05:03 PM
Hi,

Could be the watchdog is taking a long time starting the Resin instance. The watchdog code changed a bit in Resin 4 - it might address the problem. Can you try Resin 4.0.7 to make sure?

Thanks,
Emil

skippopotamus
06-24-2010, 06:19 PM
Similar problem here but Resin can sometimes take 30 minutes or more to start. This Resin 4.0.7 on Solaris 10.

Resin Professional 4.0.7 (built Fri, 21 May 2010 12:31:47 PDT)
Copyright(c) 1998-2010 Caucho Technology. All rights reserved.

1010259.license -- 1 Resin server Motorola

Starting Resin Professional on Thu, 24 Jun 2010 10:21:32 -0700 (PDT)

2010-06-24 11:07:04
Full thread dump Java HotSpot(TM) 64-Bit Server VM (16.0-b13 mixed mode):

"resin-37" daemon prio=3 tid=0x00000001022b2800 nid=0x60 waiting on condition [0xfffffffe4bcfe000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSu pport.java:283)
at com.caucho.util.ThreadPool$PoolThread.nextTask(Thr eadPool.java:962)
at com.caucho.util.ThreadPool$PoolThread.runTasks(Thr eadPool.java:887)
at com.caucho.util.ThreadPool$PoolThread.run(ThreadPo ol.java:866)

"RMI Scheduler(0)" daemon prio=3 tid=0x000000010227f800 nid=0x51 waiting on condition [0xfffffffe4b8fe000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0xfffffffe70a6b3e0> (a java.util.concurrent.locks.AbstractQueuedSynchroni zer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(L ockSupport.java:198)
at java.util.concurrent.locks.AbstractQueuedSynchroni zer$ConditionObject.awaitNanos(AbstractQueuedSynch ronizer.java:1963)
at java.util.concurrent.DelayQueue.take(DelayQueue.ja va:164)
at java.util.concurrent.ScheduledThreadPoolExecutor$D elayedWorkQueue.take(ScheduledThreadPoolExecutor.j ava:583)
at java.util.concurrent.ScheduledThreadPoolExecutor$D elayedWorkQueue.take(ScheduledThreadPoolExecutor.j ava:576)
at java.util.concurrent.ThreadPoolExecutor.getTask(Th readPoolExecutor.java:947)
at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)

"BlockWriter-1" daemon prio=3 tid=0x000000010223a000 nid=0x4f runnable [0xfffffffe4befe000]
java.lang.Thread.State: RUNNABLE
at com.caucho.vfs.JniRandomAccessFile.nativeWrite(Nat ive Method)
at com.caucho.vfs.JniRandomAccessFile.write(JniRandom AccessFile.java:96)
at com.caucho.db.block.BlockReadWrite.writeBlock(Bloc kReadWrite.java:212)
at com.caucho.db.block.Block.writeImpl(Block.java:358 )
at com.caucho.db.block.Block.writeImpl(Block.java:342 )
at com.caucho.db.block.BlockWriter.runTask(BlockWrite r.java:125)
at com.caucho.util.TaskWorker.run(TaskWorker.java:112 )
at com.caucho.util.ThreadPool$PoolThread.runTasks(Thr eadPool.java:901)
at com.caucho.util.ThreadPool$PoolThread.run(ThreadPo ol.java:866)

"resin-35" daemon prio=3 tid=0x0000000102301800 nid=0x4e waiting on condition [0xfffffffe4c0ff000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSu pport.java:283)
at com.caucho.util.ThreadPool$PoolThread.nextTask(Thr eadPool.java:962)
at com.caucho.util.ThreadPool$PoolThread.runTasks(Thr eadPool.java:887)
at com.caucho.util.ThreadPool$PoolThread.run(ThreadPo ol.java:866)

"resin-34" daemon prio=3 tid=0x0000000102255800 nid=0x4d waiting on condition [0xfffffffe4c2ff000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSu pport.java:283)
at com.caucho.util.ThreadPool$PoolThread.nextTask(Thr eadPool.java:962)
at com.caucho.util.ThreadPool$PoolThread.runTasks(Thr eadPool.java:887)
at com.caucho.util.ThreadPool$PoolThread.run(ThreadPo ol.java:866)

"resin-shutdown" daemon prio=3 tid=0x0000000102244000 nid=0x4c waiting on condition [0xfffffffe4c4ff000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSu pport.java:283)
at com.caucho.server.resin.Resin$ShutdownThread.run(R esin.java:2308)

"resin-fail-safe-halt" daemon prio=3 tid=0x000000010222f800 nid=0x4b waiting on condition [0xfffffffe4c6ff000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSu pport.java:283)
at com.caucho.server.resin.Resin$FailSafeHaltThread.r un(Resin.java:2339)
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSu pport.java:283)
at com.caucho.util.ThreadPool$PoolThread.nextTask(Thr eadPool.java:962)
at com.caucho.util.ThreadPool$PoolThread.runTasks(Thr eadPool.java:887)
at com.caucho.util.ThreadPool$PoolThread.run(ThreadPo ol.java:866)

"resin-6" daemon prio=3 tid=0x0000000101f21800 nid=0x2f waiting on condition [0xfffffffe4fefe000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSu pport.java:283)
at com.caucho.util.ThreadPool$PoolThread.nextTask(Thr eadPool.java:962)
at com.caucho.util.ThreadPool$PoolThread.runTasks(Thr eadPool.java:887)
at com.caucho.util.ThreadPool$PoolThread.run(ThreadPo ol.java:866)

"resin-5" daemon prio=3 tid=0x0000000101f03000 nid=0x2e waiting on condition [0xffffffff706ff000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSu pport.java:283)
at com.caucho.util.ThreadPool$PoolThread.nextTask(Thr eadPool.java:962)
at com.caucho.util.ThreadPool$PoolThread.runTasks(Thr eadPool.java:887)
at com.caucho.util.ThreadPool$PoolThread.run(ThreadPo ol.java:866)

ferg
06-24-2010, 06:33 PM
is that the full thread dump? there are several expected threads missing from that trace.

skippopotamus
06-24-2010, 07:23 PM
Hi Ferg, its not. I posted that and then the phone rang twice, then someone came by. Now I'm back on this. I see I can post it as an attachment. I think I'll do that because its pretty long.

skippopotamus
06-28-2010, 07:57 PM
Does anything in the attachment stand out?

skippopotamus
06-28-2010, 08:53 PM
There were some very large files in resin_data and watchdog_data. I backed them up, deleted the directories, then recreated the directories and now Resin starts up fast. I'm looking in documentation for what's in those .db files inside those directories.