Re: [Wrapper-user] JVM appears to be hung message.

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Tasso,
1) The first warning you get on startup is because you are running a
64-bit JVM with a 32-bit version of the Wrapper.  Please download a
64-bit version and request a trial license to run your tests:
http://wrapper.tanukisoftware.com/doc/english/requestTrial.jsp

---
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager: WARNING -
Unable to load the Wrapper's native library 'wrapper.dll'.
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
The file is located on the path at the following location but
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
could not be loaded:
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
C:\...\..\lib\wrapper.dll
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
Please verify that the file is readable by the current user
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
and that the file has not been corrupted in any way.
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
One common cause of this problem is running a 32-bit version
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           of
the Wrapper with a 64-bit version of Java, or vica versa.
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
This is a 64-bit JVM.
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
Reported cause:
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
C:\...\lib\wrapper.dll: Can't load IA 32-bit .dll on a AMD 64-bit
platform
INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
System signals will not be handled correctly.
---

2) The second problem is showing that the Wrapper is thinking that the
JVM is frozen and killing it.  When it restarts, the system is still
so heavily loaded that it fails again.   In both cases, the JVM
process is completely unresponsive for an extended amount of time.
This is most likely because another process on your system is
consuming all available CPU, or worse, memory.

Java (Not related to the Wrapper) is notoriously bad about performance
in cases where its memory being swapped.   It is common for a JVM to
run at 1/00th or 1/1000th the speed if even a small amount of its
memory is being swapped.

---
ERROR  | wrapper  | 2010/08/05 06:31:12 | JVM appears hung: Timed out
waiting for signal from JVM.
ERROR  | wrapper  | 2010/08/05 06:31:13 | JVM did not exit on request,
terminated
STATUS | wrapper  | 2010/08/05 06:31:18 | Launching a JVM...
INFO   | jvm 2    | 2010/08/05 06:31:21 | Profiler Agent: Waiting for
connection on port 5140 (Protocol version: 10)
ERROR  | wrapper  | 2010/08/05 06:31:50 | Startup failed: Timed out
waiting for a signal from the JVM.
ERROR  | wrapper  | 2010/08/05 06:31:50 | JVM did not exit on request,
terminated
STATUS | wrapper  | 2010/08/05 06:31:55 | Launching a JVM...
---

The Wrapper does a lot to automatically extend timeouts when the
system is under heavy load, but that is not foolproof under extreme
conditions.  We have to reach a balance to make sure the Wrapper is
responsive to actual JVM failures.   It is possible to completely
control all of these timeouts however.
The first one is the ping timeout which is hit when the JVM fails to
respond to pings for longer than this timeout.
http://wrapper.tanukisoftware.com/doc/english/prop-ping-interval.html
You can control the startup timeout with this:
http://wrapper.tanukisoftware.com/doc/english/prop-startup-timeout.html
And shutdown timeouts with the following two properties:
http://wrapper.tanukisoftware.com/doc/english/prop-shutdown-timeout.html
http://wrapper.tanukisoftware.com/doc/english/prop-jvm-exit-timeout.html

If you are sure that there is not any memory swapping going on, please
let me know as I would like to look into it further in that case.  If
so, please send me a full wrapper.log file with wrapper.debug=true
set, along with your wrapper.conf, directly to me.

BE SURE TO READ the above pages before changing their values however.
If you set the ping timeout to one hour for example then the Wrapper
will NEVER kill the JVM for a whole hour if it does indeed freeze at
some point.

We have been working on ways of detecting when the system is
undergoing heavy swapping in a reliable way.  Hopefully that will be
in a near future version.

Please let me know if you have any questions about the above.
Cheers,
Leif

On Fri, Aug 6, 2010 at 2:48 AM, Tasso Angelidis <ta...@rb...> wrote:
> Sorry for the repost but message got blocked because it was too big.
>
>
>
> This is General question…
>
>
>
> I started stress testing my application and after a couple of hours I got…
>
>
>
> ERROR  | wrapper  | 2010/08/05 06:31:12 | JVM appears hung: Timed out
> waiting for signal from JVM.
>
> ERROR  | wrapper  | 2010/08/05 06:31:13 | JVM did not exit on request,
> terminated
>
>
>
> My profiler showed that I had reached the maximum heap. But the app should
> have recorded an OutOfMemory exception. I would have seen it in the
> wrapper.log right? Or is it because I used 32 bit wrapper with 64bit vm?
>
>
>
>
>
> STATUS | wrapper  | 2010/08/04 17:02:36 | --> Wrapper Started as Service
>
> STATUS | wrapper  | 2010/08/04 17:02:36 | Java Service Wrapper Community
> Edition 32-bit 3.3.9
>
> STATUS | wrapper  | 2010/08/04 17:02:36 |   Copyright (C) 1999-2009 Tanuki
> Software, Ltd.  All Rights Reserved.
>
> STATUS | wrapper  | 2010/08/04 17:02:36 |
> http://wrapper.tanukisoftware.org
>
> STATUS | wrapper  | 2010/08/04 17:02:36 |
>
> STATUS | wrapper  | 2010/08/04 17:02:36 | Launching a JVM...
>
> INFO   | jvm 1    | 2010/08/04 17:02:36 | Profiler Agent: Waiting for
> connection on port 5140 (Protocol version: 10)
>
> INFO   | jvm 1    | 2010/08/04 17:02:53 | Profiler Agent: Established
> connection with the tool
>
> INFO   | jvm 1    | 2010/08/04 17:02:54 | Profiler Agent: Standard session
>
> INFO   | jvm 1    | 2010/08/04 17:02:55 | WrapperManager: Initializing...
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager: WARNING - Unable
> to load the Wrapper's native library 'wrapper.dll'.
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           The file
> is located on the path at the following location but
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           could
> not be loaded:
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
> C:\...\..\lib\wrapper.dll
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           Please
> verify that the file is readable by the current user
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           and that
> the file has not been corrupted in any way.
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           One
> common cause of this problem is running a 32-bit version
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           of the
> Wrapper with a 64-bit version of Java, or vica versa.
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           This is
> a 64-bit JVM.
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           Reported
> cause:
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
> C:\...\lib\wrapper.dll: Can't load IA 32-bit .dll on a AMD 64-bit platform
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:           System
> signals will not be handled correctly.
>
> INFO   | jvm 1    | 2010/08/04 17:02:56 | WrapperManager:
>
> INFO   | jvm 1    | 2010/08/04 17:03:01 | *** Profiler engine warning: class
> sun.reflect.GeneratedConstructorAccessor1 that should be instrumented is not
> loaded by target VM
>
> INFO   | jvm 1    | 2010/08/04 17:03:01 | *** Requested classloader:
> sun.reflect.DelegatingClassLoader@199155be, its class = class
> sun.reflect.DelegatingClassLoader, index = 7, hashcode = 428955070
>
> INFO   | jvm 1    | 2010/08/04 17:03:01 | *** Profiler engine warning:
> target VM cannot load class to instrument
> sun.reflect.GeneratedConstructorAccessor1
>
> INFO   | jvm 1    | 2010/08/04 17:03:01 | *** probably it has been unloaded
> recently
>
> INFO   | jvm 1    | 2010/08/04 17:03:06 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.Acquirer_$$_javassist_0 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:06 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.Currency_$$_javassist_1 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:06 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.Merchant_$$_javassist_2 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:06 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.Transaction_$$_javassist_3 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:06 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.DirectoryServer_$$_javassist_4 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:06 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.PayerAuthentication_$$_javassist_5 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:07 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.STNCryptURL_$$_javassist_6 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:07 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.Scheme_$$_javassist_7 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:07 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.Certificate_$$_javassist_8 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:07 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.VerifyEnrollment_$$_javassist_9 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:07 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.services.broker.dto.BrokerMessageLog_$$_javassist_10
> in ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:07 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.CertificateType_$$_javassist_11 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:07 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.MerchantAcquirer_$$_javassist_12 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:07 | ***Profiler agent warning: could
> not get .class file for a synthetic class
> com.rbs.threedsecure.mpi.domain.Configuration_$$_javassist_13 in
> ClassBytesLoader.getClassFileBytes
>
> INFO   | jvm 1    | 2010/08/04 17:03:08 | *** Profiler engine warning: class
> sun.reflect.GeneratedConstructorAccessor2 that should be instrumented is not
> loaded by target VM
>
> INFO   | jvm 1    | 2010/08/04 17:03:08 | *** Requested classloader:
> sun.reflect.DelegatingClassLoader@6b055af0, its class = class
> sun.reflect.DelegatingClassLoader, index = 11, hashcode = 1795513072
>
> INFO   | jvm 1    | 2010/08/04 17:03:08 | *** Profiler engine warning:
> target VM cannot load class to instrument
> sun.reflect.GeneratedConstructorAccessor2
>
> INFO   | jvm 1    | 2010/08/04 17:03:08 | *** probably it has been unloaded
> recently
>
> … Message repeats for 298 times
>
> INFO   | jvm 1    | 2010/08/05 01:34:40 | *** Profiler engine warning: class
> sun.reflect.GeneratedConstructorAccessor298 that should be instrumented is
> not loaded by target VM
>
> INFO   | jvm 1    | 2010/08/05 01:34:40 | *** Requested classloader:
> sun.reflect.DelegatingClassLoader@57dd79fe, its class = class
> sun.reflect.DelegatingClassLoader, index = 1621, hashcode = 1474132478
>
> INFO   | jvm 1    | 2010/08/05 01:34:40 | *** Profiler engine warning:
> target VM cannot load class to instrument
> sun.reflect.GeneratedConstructorAccessor298
>
> INFO   | jvm 1    | 2010/08/05 01:34:40 | *** probably it has been unloaded
> recently
>
> ERROR  | wrapper  | 2010/08/05 06:31:12 | JVM appears hung: Timed out
> waiting for signal from JVM.
>
> ERROR  | wrapper  | 2010/08/05 06:31:13 | JVM did not exit on request,
> terminated
>
> STATUS | wrapper  | 2010/08/05 06:31:18 | Launching a JVM...
>
> INFO   | jvm 2    | 2010/08/05 06:31:21 | Profiler Agent: Waiting for
> connection on port 5140 (Protocol version: 10)
>
> ERROR  | wrapper  | 2010/08/05 06:31:50 | Startup failed: Timed out waiting
> for a signal from the JVM.
>
> ERROR  | wrapper  | 2010/08/05 06:31:50 | JVM did not exit on request,
> terminated
>
> STATUS | wrapper  | 2010/08/05 06:31:55 | Launching a JVM...
>
> INFO   | jvm 3    | 2010/08/05 06:31:55 | Profiler Agent: Waiting for
> connection on port 5140 (Protocol version: 10)
>
> ERROR  | wrapper  | 2010/08/05 06:32:27 | Startup failed: Timed out waiting
> for a signal from the JVM.
>
> ERROR  | wrapper  | 2010/08/05 06:32:27 | JVM did not exit on request,
> terminated
>
> STATUS | wrapper  | 2010/08/05 06:32:32 | Launching a JVM...
>
> INFO   | jvm 4    | 2010/08/05 06:32:32 | Profiler Agent: Waiting for
> connection on port 5140 (Protocol version: 10)
>
> ERROR  | wrapper  | 2010/08/05 06:33:04 | Startup failed: Timed out waiting
> for a signal from the JVM.
>
> ERROR  | wrapper  | 2010/08/05 06:33:04 | JVM did not exit on request,
> terminated
>
> STATUS | wrapper  | 2010/08/05 06:33:09 | Launching a JVM...
>
> INFO   | jvm 5    | 2010/08/05 06:33:10 | Profiler Agent: Waiting for
> connection on port 5140 (Protocol version: 10)
>
> ERROR  | wrapper  | 2010/08/05 06:33:41 | Startup failed: Timed out waiting
> for a signal from the JVM.
>
> ERROR  | wrapper  | 2010/08/05 06:33:41 | JVM did not exit on request,
> terminated
>
> STATUS | wrapper  | 2010/08/05 06:33:46 | Launching a JVM...
>
> INFO   | jvm 6    | 2010/08/05 06:33:46 | Profiler Agent: Waiting for
> connection on port 5140 (Protocol version: 10)
>
> ERROR  | wrapper  | 2010/08/05 06:34:18 | Startup failed: Timed out waiting
> for a signal from the JVM.
>
> ERROR  | wrapper  | 2010/08/05 06:34:18 | JVM did not exit on request,
> terminated
>
> FATAL  | wrapper  | 2010/08/05 06:34:19 | There were 5 failed launches in a
> row, each lasting less than 300 seconds.  Giving up.
>
> FATAL  | wrapper  | 2010/08/05 06:34:19 |   There may be a configuration
> problem: please check the logs.
>
> STATUS | wrapper  | 2010/08/05 06:34:19 | <-- Wrapper Stopped

-- 
Leif Mortenson
Tanuki Software, Ltd.
6-16-7-1001 Nishi-Kasai, Edogawa-ku
Tokyo 134-0088 Japan
Tel/Fax: +81-3-3878-3211
http://www.tanukisoftware.com
lei...@ta...