Re: [Wrapper-user] Wrapper Monopolizes CPU

[Ben L. <Ben...@As...>]

Hi Leif,

Thank you very much for your prompt reply. It turned out that, indeed,
the java application rather than the wrapper was mal-configured. Setting
wrapper.java.command.loglevel=INFO was very useful while tracking this
down. I really appreciate your help - thank you!

Cheers,
Ben
   

-----Original Message-----
From: wra...@li...
[mailto:wra...@li...] On Behalf Of
wra...@li...
Sent: Tuesday, February 19, 2008 10:52 PM
To: wra...@li...
Subject: Wrapper-user Digest, Vol 21, Issue 9

Send Wrapper-user mailing list submissions to
	wra...@li...

To subscribe or unsubscribe via the World Wide Web, visit
	https://lists.sourceforge.net/lists/listinfo/wrapper-user
or, via email, send a message with subject or body 'help' to
	wra...@li...

You can reach the person managing the list at
	wra...@li...

When replying, please edit your Subject line so it is more specific than
"Re: Contents of Wrapper-user digest..."


Today's Topics:

   1. Re: Wrapper Monopolizes CPU (Leif Mortenson)
   2. Re: Issue with wrapper (Leif Mortenson)
   3. Re: Issue with wrapper (Ramakrishna Bv Sanku)


----------------------------------------------------------------------

Message: 1
Date: Wed, 20 Feb 2008 14:20:53 +0900
From: Leif Mortenson <le...@ta...>
Subject: Re: [Wrapper-user] Wrapper Monopolizes CPU
To: wra...@li...
Message-ID: <47B...@ta...>
Content-Type: text/plain; charset=windows-1252; format=flowed

Ben,
I have never seen or heard of any examples of the Wrapper or its Java
component consuming lots of CPU due to the Wrapper.

To confirm, it is the java process and not the wrapper process that is
using up all the CPU.

You might want to try doing some profiling of your JVM to narrow down
the cause. From you classpath, and
configManager.VPNManagement.RegistrarDaemon
class, it is likely that more is going on in your application than the
loop below.

I have seen cases where the java application is not being configured as
expected when running under the wrapper. An incorrect path for example.
Something like that could cause some thrashing of an outer loop
depending on how the error handling code was written.

You can review the full command used to launch the JVM by adding the
following to your wrapper.conf wrapper.java.command.loglevel=INFO

Cheers,
Leif

Ben Leibert wrote:
>
> I?m using version 3.2.3 of the wrapper on SuSe Linux 10.1 alongside 
> version 1.5 of Java. The ?top? command shows the wrapper to 
> consistently monopolize the CPU, which I?d ~really~ appreciate help 
> resolving. The code I?m testing with looks as follows:
>
> while(true)
>
> {
>
> System.out.println("This just ran");
>
> Thread.currentThread().sleep(3000);
>
> }
>
> Only when run via the wrapper does this dominate the processor. 
> Neither changing the wrapper.ping.interval nor the priority (nice) 
> properties has had any noticeable affect. My configuration files are 
> included below. Thanks in advance for any help!
>
> Cheers,
>
> Ben
>
(snip)



------------------------------

Message: 2
Date: Wed, 20 Feb 2008 15:23:56 +0900
From: Leif Mortenson <le...@ta...>
Subject: Re: [Wrapper-user] Issue with wrapper
To: wra...@li...
Message-ID: <47B...@ta...>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed

Ram,
I am a bit of a loss as to what is happening here assuming that you sent
me the full logs.

DEBUG  | wrapperp | 2008/02/08 01:39:48 | send a packet PING : ping
INFO   | jvm 8    | 2008/02/08 01:39:49 | Received a packet PING : ping
INFO   | jvm 8    | 2008/02/08 01:39:49 | Send a packet PING : ok
DEBUG  | wrapperp | 2008/02/08 01:39:49 | read a packet PING : ok DEBUG
| wrapper  | 2008/02/08 01:39:49 | Got ping response from JVM DEBUG  |
wrapperp | 2008/02/08 01:39:53 | send a packet PING : ping DEBUG  |
wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4) DEBUG  |
wrapperp | 2008/02/08 01:40:42 | send a packet SERVICE_CONTROL_CODE : 4
DEBUG  | wrapperp | 2008/02/08 01:40:42 | socket send failed. (10053)
DEBUG  | wrapper  | 2008/02/08 01:40:42 |   SERVICE_CONTROL_INTERROGATE
DEBUG  | wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4) DEBUG
| wrapperp | 2008/02/08 01:40:42 | socket not open, so packet not sent
SERVICE_CONTROL_CODE : 4
DEBUG  | wrapper  | 2008/02/08 01:40:42 |   SERVICE_CONTROL_INTERROGATE

The Wrapper should be attempting to send a PING packet once
every 5 seconds as happens at 01:39:48 and 01:39:53.   But then
there is nothing.  The JVM does say that it received the ping and there
are no more attempts to send by the Wrapper.
The next bessage is 49 seconds later at 01:40:42 when the Service
Manager sends an interrogate control code.

Both of your logs show the same thing.   The wrapper sends a
ping which is never acknowledged by the Java side of the Wrapper then
about 50 seconds later an interrogate control code shows up which fails
to be sent to the JVM.

In addition to the wrapper.debug=TRUE property, can you also try setting
wrapper.state_output=TRUE  This will produce a LOT of output, but it
might also shed more light on what is happening to you.

Cheers,
Leif

Ramakrishna Bv Sanku wrote:
> Hi Leif Mortenson,
>
> Thank you for quick response. Please check my answers in Blue for the 
> questions.
>
> Please find the attachment for the log.
>
>
> I have checked the logs on other days as well , this issue is occuring

> but for the recovery time is less, please check the log below:
>
> INFO   | jvm 9    | 2008/02/10 01:28:46 | Send a packet PING : ok
> DEBUG  | wrapperp | 2008/02/10 01:28:46 | read a packet PING : ok 
> DEBUG  | wrapper  | 2008/02/10 01:28:46 | Got ping response from JVM 
> DEBUG  | wrapperp | 2008/02/10 01:28:50 | send a packet PING : ping
> INFO   | jvm 9    | 2008/02/10 01:28:50 | Received a packet PING :
ping
> INFO   | jvm 9    | 2008/02/10 01:28:50 | Send a packet PING : ok
> DEBUG  | wrapperp | 2008/02/10 01:28:50 | read a packet PING : ok 
> DEBUG  | wrapper  | 2008/02/10 01:28:50 | Got ping response from JVM 
> DEBUG  | wrapperp | 2008/02/10 01:28:54 | send a packet PING : ping 
> DEBUG  | wrapper  | 2008/02/10 01:29:25 | ServiceControlHandler(4) 
> DEBUG  | wrapperp | 2008/02/10 01:29:25 | send a packet 
> SERVICE_CONTROL_CODE : 4 DEBUG  | wrapperp | 2008/02/10 01:29:25 | 
> socket send failed. (10053)
> DEBUG  | wrapper  | 2008/02/10 01:29:25 |
SERVICE_CONTROL_INTERROGATE
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Read Timed out. (Last Ping 
> was 30300 milliseconds ago)
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Wrapper Manager: The Wrapper

> code did not ping the JVM for 30 seconds.  Quit and let the Wrapper 
> resynch.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Send a packet RESTART :
restart
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Thread, Wrapper-Connection, 
> handling the shutdown process.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | calling listener.stop()
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Waiting for 
> WrapperListener.stop runner thread to complete.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | WrapperListener.stop runner 
> thread started.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | WrapperSimpleApp: stop(1)
> INFO   | jvm 9    | 2008/02/10 01:29:25 | WrapperListener.stop runner 
> thread stopped.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | returned from 
> listener.stop() -> 1
> INFO   | jvm 9    | 2008/02/10 01:29:25 | shutdownJVM(1) 
> Thread:Wrapper-Connection
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Send a packet STOPPED : 1
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Closing socket.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | calling System.exit(1)
> INFO   | jvm 9    | 2008/02/10 01:29:25 | 2008-02-10 
> 01:29:23,188|INFO|SequencerTool|shutting down
> INFO   | jvm 9    | 2008/02/10 01:29:25 | 2008-02-10 
> 01:29:23,266|INFO|SequencerTool|ok.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | 2008-02-10 
> 01:29:23,266|INFO|SequencerTool|stopped.
> DEBUG  | wrapperp | 2008/02/10 01:29:25 | server listening on port
32002.
> INFO   | wrapper  | 2008/02/10 01:29:25 | Wrapper Process has not 
> received any CPU time for 30 seconds.  Extending timeouts.
> DEBUG  | wrapper  | 2008/02/10 01:29:25 | JVM process exited with a 
> code of 1, setting the wrapper exit code to 1.
> ERROR  | wrapper  | 2008/02/10 01:29:25 | JVM exited unexpectedly.
> DEBUG  | wrapper  | 2008/02/10 01:29:25 | ServiceControlHandler(4) 
> DEBUG  | wrapperp | 2008/02/10 01:29:25 | socket not open, so packet 
> not sent SERVICE_CONTROL_CODE : 4
> DEBUG  | wrapper  | 2008/02/10 01:29:25 |
SERVICE_CONTROL_INTERROGATE
> DEBUG  | wrapper  | 2008/02/10 01:29:25 | Waiting 5 seconds before 
> launching another JVM.
> DEBUG  | wrapper  | 2008/02/10 01:29:29 | Classpath element, 
> wrapper.java.classpath.10, does not exist: ../classes STATUS | wrapper

> | 2008/02/10 01:29:29 | Launching a JVM...
> ______________________________________________________________________
> ___________________________
>
> INFO   | jvm 7    | 2008/02/06 02:31:49 | Received a packet 
> SERVICE_CONTROL_CODE : 4
> INFO   | jvm 7    | 2008/02/06 02:31:49 | ServiceControlCode from 
> Wrapper with code 4
> DEBUG  | wrapperp | 2008/02/06 02:31:49 | send a packet PING : ping
> INFO   | jvm 7    | 2008/02/06 02:31:49 | Received a packet PING :
ping
> INFO   | jvm 7    | 2008/02/06 02:31:49 | Send a packet PING : ok
> DEBUG  | wrapperp | 2008/02/06 02:31:50 | read a packet PING : ok 
> DEBUG  | wrapper  | 2008/02/06 02:31:50 | Got ping response from JVM 
> DEBUG  | wrapperp | 2008/02/06 02:31:54 | send a packet PING : ping
> INFO   | jvm 7    | 2008/02/06 02:31:54 | Received a packet PING :
ping
> INFO   | jvm 7    | 2008/02/06 02:31:54 | Send a packet PING : ok
> DEBUG  | wrapperp | 2008/02/06 02:31:54 | read a packet PING : ok 
> DEBUG  | wrapper  | 2008/02/06 02:31:54 | Got ping response from JVM 
> DEBUG  | wrapperp | 2008/02/06 02:31:58 | send a packet PING : ping 
> DEBUG  | wrapper  | 2008/02/06 02:32:50 | ServiceControlHandler(4) 
> DEBUG  | wrapperp | 2008/02/06 02:32:50 | send a packet 
> SERVICE_CONTROL_CODE : 4 DEBUG  | wrapperp | 2008/02/06 02:32:50 | 
> socket send failed. (10053)
> DEBUG  | wrapper  | 2008/02/06 02:32:50 |
SERVICE_CONTROL_INTERROGATE
> DEBUG  | wrapper  | 2008/02/06 02:32:50 | ServiceControlHandler(4) 
> DEBUG  | wrapperp | 2008/02/06 02:32:50 | socket not open, so packet 
> not sent SERVICE_CONTROL_CODE : 4
> DEBUG  | wrapper  | 2008/02/06 02:32:50 |
SERVICE_CONTROL_INTERROGATE
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Read Timed out. (Last Ping 
> was 30400 milliseconds ago)
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Wrapper Manager: The Wrapper

> code did not ping the JVM for 30 seconds.  Quit and let the Wrapper 
> resynch.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Send a packet RESTART :
restart
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Thread, Wrapper-Connection, 
> handling the shutdown process.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | calling listener.stop()
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Waiting for 
> WrapperListener.stop runner thread to complete.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | WrapperListener.stop runner 
> thread started.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | WrapperSimpleApp: stop(1)
> INFO   | jvm 7    | 2008/02/06 02:32:50 | WrapperListener.stop runner 
> thread stopped.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | returned from 
> listener.stop() -> 1
> INFO   | jvm 7    | 2008/02/06 02:32:50 | shutdownJVM(1) 
> Thread:Wrapper-Connection
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Send a packet STOPPED : 1
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Closing socket.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | calling System.exit(1)
> INFO   | jvm 7    | 2008/02/06 02:32:50 | 2008-02-06 
> 02:32:26,750|INFO|SequencerTool|shutting down DEBUG  | wrapperp | 
> 2008/02/06 02:32:50 | server listening on port 32002.
> INFO   | wrapper  | 2008/02/06 02:32:50 | Wrapper Process has not 
> received any CPU time for 51 seconds.  Extending timeouts.
> DEBUG  | wrapper  | 2008/02/06 02:32:50 | JVM process exited with a 
> code of 1, setting the wrapper exit code to 1.
> ERROR  | wrapper  | 2008/02/06 02:32:50 | JVM exited unexpectedly.
> DEBUG  | wrapper  | 2008/02/06 02:32:50 | Waiting 5 seconds before 
> launching another JVM.
> DEBUG  | wrapper  | 2008/02/06 02:32:54 | Classpath element, 
> wrapper.java.classpath.10, does not exist: ../classes STATUS | wrapper

> | 2008/02/06 02:32:54 | Launching a JVM...
>
> Best Regards,
> Ram
> IBM Global Services India Pvt. Ltd.
> Mindspace, Survey No 64, APIIC Software Layout, Hi-tech City, 
> Hyderabad -500 081 INDIA
> Phone: +91-40-66956756
>
>
> *Leif Mortenson <le...@ta...>* Sent by: 
> wra...@li...
>
> 02/08/2008 01:17 PM
> Please respond to
> wra...@li...
>
>
> 	
> To
> 	wra...@li...
> cc
> 	
> Subject
> 	Re: [Wrapper-user] Issue with wrapper
>
>
>
> 	
>
>
>
>
>
> Ramakrishna,
> According to the log, the backend socket between the Wrapper and
> Java process was somehow closed.   The Wrapper is failing saying
> that it can no longer communicate with the JVM.  It keeps going though

> because the JVM process is still running.
>
> The JVM then gives up after around 30 seconds because it has not 
> received any communications from the Wrapper for that long.  This is a

> safety feature to shut the JVM process down just in case the Wrapper 
> process should ever crash.
>
> Once the Wrapper detects that the JVM is shutdown, it is correctly 
> restarting the JVM.
>
>
> The question is why is the backend socket being closed?  This is not a

> problem I have ever seen or heard of in the past.  Is anything else in

> the log file earlier than what you sent?
>
> How easy is this to reproduce?
> *A: We cannot reproduce.*
>
> Does it always happen at the same time?
> *A: No,it does not happen at the sametime.*
>
> Is it possible that some other application on your system is closing 
> the socket?
> *A:Can't say whether someother application on the system might be 
> trying to close the socket.Another two applications are running on the

> same machine with wrapper having same configuration.*
>
> Is your system under load at the time of this reset?
> *A: Yes, it was under load.*
>
> Does your Java application respond during the 30 seconds between the 
> socket being closed and the JVM shutting itself down?
> *A: Can't answer*
>
> Cheers,
> Leif
>
> Ramakrishna Bv Sanku wrote:
> >
> > Hi All,
> >
> > I came across a issue with wrapper, the Wrapper is getting degraded 
> > for sometime and getting into normal state after some time. Please 
> > check the wrapper log below.
> >
> > Can anyone help me and provide a solution, how can this be
rectified.
> >
> > *Information from the wrapper log*
> > WrapperManager class initialized by thread: main  Using classloader:
> > sun.misc.Launcher$AppClassLoader@27e3570f
> > ...............
> > Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org 
> > ...............
> >
> > Extract from wrapper log
> >
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4) 
> > DEBUG  | wrapperp | 2008/02/08 01:40:42 | send a packet 
> > SERVICE_CONTROL_CODE : 4 DEBUG  | wrapperp | 2008/02/08 01:40:42 | 
> > socket send failed. (10053)
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 |
SERVICE_CONTROL_INTERROGATE
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4) 
> > DEBUG  | wrapperp | 2008/02/08 01:40:42 | socket not open, so packet

> > not sent SERVICE_CONTROL_CODE : 4
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 |
SERVICE_CONTROL_INTERROGATE
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Read Timed out. (Last Ping
> > was 30600 milliseconds ago)
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Wrapper Manager: The
Wrapper
> > code did not ping the JVM for 30 seconds.  Quit and let the Wrapper 
> > resynch.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Send a packet RESTART : 
> restart
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Thread,
Wrapper-Connection,
> > handling the shutdown process.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | calling listener.stop()
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Waiting for
> > WrapperListener.stop runner thread to complete.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | WrapperListener.stop
runner
> > thread started.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | WrapperSimpleApp: stop(1)
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | WrapperListener.stop
runner
> > thread stopped.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | returned from
> > listener.stop() -> 1
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | shutdownJVM(1)
> > Thread:Wrapper-Connection
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Send a packet STOPPED : 1
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Closing socket.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | calling System.exit(1)
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | 2008-02-08
> > 01:40:22,031|INFO|SequencerTool|shutting down DEBUG  | wrapperp | 
> > 2008/02/08 01:40:42 | server listening on port
> 32002.
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4) 
> > DEBUG  | wrapperp | 2008/02/08 01:40:42 | socket not open, so packet

> > not sent SERVICE_CONTROL_CODE : 4
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 |
SERVICE_CONTROL_INTERROGATE
> > INFO   | wrapper  | 2008/02/08 01:40:42 | Wrapper Process has not
> > received any CPU time for 48 seconds.  Extending timeouts.
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | JVM process exited with a 
> > code of 1, setting the wrapper exit code to 1.
> > ERROR  | wrapper  | 2008/02/08 01:40:42 | JVM exited unexpectedly.
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | Waiting 5 seconds before 
> > launching another JVM.
> > DEBUG  | wrapper  | 2008/02/08 01:40:46 | Classpath element, 
> > wrapper.java.classpath.10, does not exist: ../classes STATUS | 
> > wrapper  | 2008/02/08 01:40:46 | Launching a JVM...
> > NONE   | wrapper  | 2008/02/08 01:40:46 | command:
> > "D:\IBM\WBIServer\jre\bin\java.exe"
> > -Dsequencer.context=AU04QWS130DCA32
> > -Dsequencer.logs=d:\wppaup\runtime\var\sequencer\logs
> > -Drepository.directory=D:\IBM\Sequencer -Djava.library.path="./lib"
> > -classpath
> > 
>
"./lib/wrapper.jar;./lib/commons-collections-3.1.jar;./lib/commons-lang-
2.1.jar;./lib/commons-logging-1.0.4.jar;./lib/commons-net-1.4.1.jar;./li
b/jakarta-oro.jar;./lib/log4j-1.2.7.jar;./lib/spring.jar;./lib/velocity-
1.4.jar;../classes;./lib/sequencer.jar" 
>
> > -Dwrapper.key="2ZXzPWYAZ6Ry7obW" -Dwrapper.port=32002 
> > -Dwrapper.jvm.port.min=31000 -Dwrapper.jvm.port.max=31999 
> > -Dwrapper.debug="TRUE" -Dwrapper.pid=2508 -Dwrapper.version="3.2.3"
> > -Dwrapper.native_library="wrapper" -Dwrapper.service="TRUE"
> > -Dwrapper.cpu.timeout="10" -Dwrapper.jvmid=9 
> > org.tanukisoftware.wrapper.WrapperSimpleApp SequencerTool LOOP DEBUG

> > | wrapper  | 2008/02/08 01:40:46 | JVM started (PID=9500)
>
>
> ----------------------------------------------------------------------
> --- This SF.net email is sponsored by: Microsoft Defy all challenges. 
> Microsoft(R) Visual Studio 2008.
> http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
> _______________________________________________
> Wrapper-user mailing list
> Wra...@li...
> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>
>
> ----------------------------------------------------------------------
> --
>
> ----------------------------------------------------------------------
> --- This SF.net email is sponsored by: Microsoft Defy all challenges. 
> Microsoft(R) Visual Studio 2008.
> http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
> ----------------------------------------------------------------------
> --
>
> _______________________________________________
> Wrapper-user mailing list
> Wra...@li...
> https://lists.sourceforge.net/lists/listinfo/wrapper-user




------------------------------

Message: 3
Date: Wed, 20 Feb 2008 12:21:47 +0530
From: Ramakrishna Bv Sanku <ram...@in...>
Subject: Re: [Wrapper-user] Issue with wrapper
To: Leif Mortenson <le...@ta...>
Cc: wra...@li...
Message-ID:
	
<OF5...@in...>
Content-Type: text/plain; charset="us-ascii"

Hi Leif  Mortenson,

Thank you i will set the property and check what is happening.

Best Regards,
Ram
IBM Global Services India Pvt. Ltd.
Mindspace, Survey No 64, APIIC Software Layout, Hi-tech City, Hyderabad
-500 081
Phone: +91-40-66956756
INDIA



Leif Mortenson <le...@ta...> 
20/02/2008 11:53

To
wra...@li...
cc
Ramakrishna Bv Sanku/India/IBM@IBMIN
Subject
Re: [Wrapper-user] Issue with wrapper






Ram,
I am a bit of a loss as to what is happening here assuming that you
sent me the full logs.

DEBUG  | wrapperp | 2008/02/08 01:39:48 | send a packet PING : ping
INFO   | jvm 8    | 2008/02/08 01:39:49 | Received a packet PING : ping
INFO   | jvm 8    | 2008/02/08 01:39:49 | Send a packet PING : ok
DEBUG  | wrapperp | 2008/02/08 01:39:49 | read a packet PING : ok
DEBUG  | wrapper  | 2008/02/08 01:39:49 | Got ping response from JVM
DEBUG  | wrapperp | 2008/02/08 01:39:53 | send a packet PING : ping
DEBUG  | wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4)
DEBUG  | wrapperp | 2008/02/08 01:40:42 | send a packet 
SERVICE_CONTROL_CODE : 4
DEBUG  | wrapperp | 2008/02/08 01:40:42 | socket send failed. (10053)
DEBUG  | wrapper  | 2008/02/08 01:40:42 |   SERVICE_CONTROL_INTERROGATE
DEBUG  | wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4)
DEBUG  | wrapperp | 2008/02/08 01:40:42 | socket not open, so packet not

sent SERVICE_CONTROL_CODE : 4
DEBUG  | wrapper  | 2008/02/08 01:40:42 |   SERVICE_CONTROL_INTERROGATE

The Wrapper should be attempting to send a PING packet once
every 5 seconds as happens at 01:39:48 and 01:39:53.   But then
there is nothing.  The JVM does say that it received the ping
and there are no more attempts to send by the Wrapper.
The next bessage is 49 seconds later at 01:40:42 when the
Service Manager sends an interrogate control code.

Both of your logs show the same thing.   The wrapper sends a
ping which is never acknowledged by the Java side of the Wrapper
then about 50 seconds later an interrogate control code shows
up which fails to be sent to the JVM.

In addition to the wrapper.debug=TRUE property, can you also
try setting wrapper.state_output=TRUE  This will produce a LOT
of output, but it might also shed more light on what is happening
to you.

Cheers,
Leif

Ramakrishna Bv Sanku wrote:
> Hi Leif Mortenson,
>
> Thank you for quick response. Please check my answers in Blue for the 
> questions.
>
> Please find the attachment for the log.
>
>
> I have checked the logs on other days as well , this issue is occuring

> but for the recovery time is less, please check the log below:
>
> INFO   | jvm 9    | 2008/02/10 01:28:46 | Send a packet PING : ok
> DEBUG  | wrapperp | 2008/02/10 01:28:46 | read a packet PING : ok
> DEBUG  | wrapper  | 2008/02/10 01:28:46 | Got ping response from JVM
> DEBUG  | wrapperp | 2008/02/10 01:28:50 | send a packet PING : ping
> INFO   | jvm 9    | 2008/02/10 01:28:50 | Received a packet PING :
ping
> INFO   | jvm 9    | 2008/02/10 01:28:50 | Send a packet PING : ok
> DEBUG  | wrapperp | 2008/02/10 01:28:50 | read a packet PING : ok
> DEBUG  | wrapper  | 2008/02/10 01:28:50 | Got ping response from JVM
> DEBUG  | wrapperp | 2008/02/10 01:28:54 | send a packet PING : ping
> DEBUG  | wrapper  | 2008/02/10 01:29:25 | ServiceControlHandler(4)
> DEBUG  | wrapperp | 2008/02/10 01:29:25 | send a packet 
> SERVICE_CONTROL_CODE : 4
> DEBUG  | wrapperp | 2008/02/10 01:29:25 | socket send failed. (10053)
> DEBUG  | wrapper  | 2008/02/10 01:29:25 |
SERVICE_CONTROL_INTERROGATE
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Read Timed out. (Last Ping 
> was 30300 milliseconds ago)
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Wrapper Manager: The Wrapper

> code did not ping the JVM for 30 seconds.  Quit and let the Wrapper 
> resynch.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Send a packet RESTART : 
restart
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Thread, Wrapper-Connection, 
> handling the shutdown process.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | calling listener.stop()
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Waiting for 
> WrapperListener.stop runner thread to complete.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | WrapperListener.stop runner 
> thread started.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | WrapperSimpleApp: stop(1)
> INFO   | jvm 9    | 2008/02/10 01:29:25 | WrapperListener.stop runner 
> thread stopped.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | returned from 
> listener.stop() -> 1
> INFO   | jvm 9    | 2008/02/10 01:29:25 | shutdownJVM(1) 
> Thread:Wrapper-Connection
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Send a packet STOPPED : 1
> INFO   | jvm 9    | 2008/02/10 01:29:25 | Closing socket.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | calling System.exit(1)
> INFO   | jvm 9    | 2008/02/10 01:29:25 | 2008-02-10 
> 01:29:23,188|INFO|SequencerTool|shutting down
> INFO   | jvm 9    | 2008/02/10 01:29:25 | 2008-02-10 
> 01:29:23,266|INFO|SequencerTool|ok.
> INFO   | jvm 9    | 2008/02/10 01:29:25 | 2008-02-10 
> 01:29:23,266|INFO|SequencerTool|stopped.
> DEBUG  | wrapperp | 2008/02/10 01:29:25 | server listening on port 
32002.
> INFO   | wrapper  | 2008/02/10 01:29:25 | Wrapper Process has not 
> received any CPU time for 30 seconds.  Extending timeouts.
> DEBUG  | wrapper  | 2008/02/10 01:29:25 | JVM process exited with a 
> code of 1, setting the wrapper exit code to 1.
> ERROR  | wrapper  | 2008/02/10 01:29:25 | JVM exited unexpectedly.
> DEBUG  | wrapper  | 2008/02/10 01:29:25 | ServiceControlHandler(4)
> DEBUG  | wrapperp | 2008/02/10 01:29:25 | socket not open, so packet 
> not sent SERVICE_CONTROL_CODE : 4
> DEBUG  | wrapper  | 2008/02/10 01:29:25 |
SERVICE_CONTROL_INTERROGATE
> DEBUG  | wrapper  | 2008/02/10 01:29:25 | Waiting 5 seconds before 
> launching another JVM.
> DEBUG  | wrapper  | 2008/02/10 01:29:29 | Classpath element, 
> wrapper.java.classpath.10, does not exist: ../classes
> STATUS | wrapper  | 2008/02/10 01:29:29 | Launching a JVM...
> 
________________________________________________________________________
_________________________ 

>
> INFO   | jvm 7    | 2008/02/06 02:31:49 | Received a packet 
> SERVICE_CONTROL_CODE : 4
> INFO   | jvm 7    | 2008/02/06 02:31:49 | ServiceControlCode from 
> Wrapper with code 4
> DEBUG  | wrapperp | 2008/02/06 02:31:49 | send a packet PING : ping
> INFO   | jvm 7    | 2008/02/06 02:31:49 | Received a packet PING :
ping
> INFO   | jvm 7    | 2008/02/06 02:31:49 | Send a packet PING : ok
> DEBUG  | wrapperp | 2008/02/06 02:31:50 | read a packet PING : ok
> DEBUG  | wrapper  | 2008/02/06 02:31:50 | Got ping response from JVM
> DEBUG  | wrapperp | 2008/02/06 02:31:54 | send a packet PING : ping
> INFO   | jvm 7    | 2008/02/06 02:31:54 | Received a packet PING :
ping
> INFO   | jvm 7    | 2008/02/06 02:31:54 | Send a packet PING : ok
> DEBUG  | wrapperp | 2008/02/06 02:31:54 | read a packet PING : ok
> DEBUG  | wrapper  | 2008/02/06 02:31:54 | Got ping response from JVM
> DEBUG  | wrapperp | 2008/02/06 02:31:58 | send a packet PING : ping
> DEBUG  | wrapper  | 2008/02/06 02:32:50 | ServiceControlHandler(4)
> DEBUG  | wrapperp | 2008/02/06 02:32:50 | send a packet 
> SERVICE_CONTROL_CODE : 4
> DEBUG  | wrapperp | 2008/02/06 02:32:50 | socket send failed. (10053)
> DEBUG  | wrapper  | 2008/02/06 02:32:50 |
SERVICE_CONTROL_INTERROGATE
> DEBUG  | wrapper  | 2008/02/06 02:32:50 | ServiceControlHandler(4)
> DEBUG  | wrapperp | 2008/02/06 02:32:50 | socket not open, so packet 
> not sent SERVICE_CONTROL_CODE : 4
> DEBUG  | wrapper  | 2008/02/06 02:32:50 |
SERVICE_CONTROL_INTERROGATE
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Read Timed out. (Last Ping 
> was 30400 milliseconds ago)
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Wrapper Manager: The Wrapper

> code did not ping the JVM for 30 seconds.  Quit and let the Wrapper 
> resynch.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Send a packet RESTART : 
restart
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Thread, Wrapper-Connection, 
> handling the shutdown process.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | calling listener.stop()
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Waiting for 
> WrapperListener.stop runner thread to complete.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | WrapperListener.stop runner 
> thread started.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | WrapperSimpleApp: stop(1)
> INFO   | jvm 7    | 2008/02/06 02:32:50 | WrapperListener.stop runner 
> thread stopped.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | returned from 
> listener.stop() -> 1
> INFO   | jvm 7    | 2008/02/06 02:32:50 | shutdownJVM(1) 
> Thread:Wrapper-Connection
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Send a packet STOPPED : 1
> INFO   | jvm 7    | 2008/02/06 02:32:50 | Closing socket.
> INFO   | jvm 7    | 2008/02/06 02:32:50 | calling System.exit(1)
> INFO   | jvm 7    | 2008/02/06 02:32:50 | 2008-02-06 
> 02:32:26,750|INFO|SequencerTool|shutting down
> DEBUG  | wrapperp | 2008/02/06 02:32:50 | server listening on port 
32002.
> INFO   | wrapper  | 2008/02/06 02:32:50 | Wrapper Process has not 
> received any CPU time for 51 seconds.  Extending timeouts.
> DEBUG  | wrapper  | 2008/02/06 02:32:50 | JVM process exited with a 
> code of 1, setting the wrapper exit code to 1.
> ERROR  | wrapper  | 2008/02/06 02:32:50 | JVM exited unexpectedly.
> DEBUG  | wrapper  | 2008/02/06 02:32:50 | Waiting 5 seconds before 
> launching another JVM.
> DEBUG  | wrapper  | 2008/02/06 02:32:54 | Classpath element, 
> wrapper.java.classpath.10, does not exist: ../classes
> STATUS | wrapper  | 2008/02/06 02:32:54 | Launching a JVM...
>
> Best Regards,
> Ram
> IBM Global Services India Pvt. Ltd.
> Mindspace, Survey No 64, APIIC Software Layout,
> Hi-tech City, Hyderabad -500 081
> INDIA
> Phone: +91-40-66956756
>
>
> *Leif Mortenson <le...@ta...>*
> Sent by: wra...@li...
>
> 02/08/2008 01:17 PM
> Please respond to
> wra...@li...
>
>
> 
> To
>                wra...@li...
> cc
> 
> Subject
>                Re: [Wrapper-user] Issue with wrapper
>
>
>
> 
>
>
>
>
>
> Ramakrishna,
> According to the log, the backend socket between the Wrapper and
> Java process was somehow closed.   The Wrapper is failing saying
> that it can no longer communicate with the JVM.  It keeps going
> though because the JVM process is still running.
>
> The JVM then gives up after around 30 seconds because it has not
> received any communications from the Wrapper for that long.  This
> is a safety feature to shut the JVM process down just in case the
> Wrapper process should ever crash.
>
> Once the Wrapper detects that the JVM is shutdown, it is correctly
> restarting the JVM.
>
>
> The question is why is the backend socket being closed?  This is not
> a problem I have ever seen or heard of in the past.  Is anything else
> in the log file earlier than what you sent?
>
> How easy is this to reproduce?
> *A: We cannot reproduce.*
>
> Does it always happen at the same time?
> *A: No,it does not happen at the sametime.*
>
> Is it possible that some other application on your system is closing
> the socket?
> *A:Can't say whether someother application on the system might be 
> trying to close the socket.Another two applications are running on the

> same machine with wrapper having same configuration.*
>
> Is your system under load at the time of this reset?
> *A: Yes, it was under load.*
>
> Does your Java application respond during the 30 seconds between
> the socket being closed and the JVM shutting itself down?
> *A: Can't answer*
>
> Cheers,
> Leif
>
> Ramakrishna Bv Sanku wrote:
> >
> > Hi All,
> >
> > I came across a issue with wrapper, the Wrapper is getting degraded
> > for sometime and getting into normal state after some time. Please
> > check the wrapper log below.
> >
> > Can anyone help me and provide a solution, how can this be
rectified.
> >
> > *Information from the wrapper log*
> > WrapperManager class initialized by thread: main  Using classloader:
> > sun.misc.Launcher$AppClassLoader@27e3570f
> > ...............
> > Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
> > ...............
> >
> > Extract from wrapper log
> >
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4)
> > DEBUG  | wrapperp | 2008/02/08 01:40:42 | send a packet
> > SERVICE_CONTROL_CODE : 4
> > DEBUG  | wrapperp | 2008/02/08 01:40:42 | socket send failed.
(10053)
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 |
SERVICE_CONTROL_INTERROGATE
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4)
> > DEBUG  | wrapperp | 2008/02/08 01:40:42 | socket not open, so packet
> > not sent SERVICE_CONTROL_CODE : 4
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 |
SERVICE_CONTROL_INTERROGATE
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Read Timed out. (Last Ping
> > was 30600 milliseconds ago)
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Wrapper Manager: The
Wrapper
> > code did not ping the JVM for 30 seconds.  Quit and let the Wrapper
> > resynch.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Send a packet RESTART : 
> restart
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Thread,
Wrapper-Connection,
> > handling the shutdown process.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | calling listener.stop()
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Waiting for
> > WrapperListener.stop runner thread to complete.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | WrapperListener.stop
runner
> > thread started.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | WrapperSimpleApp: stop(1)
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | WrapperListener.stop
runner
> > thread stopped.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | returned from
> > listener.stop() -> 1
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | shutdownJVM(1)
> > Thread:Wrapper-Connection
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Send a packet STOPPED : 1
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | Closing socket.
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | calling System.exit(1)
> > INFO   | jvm 8    | 2008/02/08 01:40:42 | 2008-02-08
> > 01:40:22,031|INFO|SequencerTool|shutting down
> > DEBUG  | wrapperp | 2008/02/08 01:40:42 | server listening on port 
> 32002.
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | ServiceControlHandler(4)
> > DEBUG  | wrapperp | 2008/02/08 01:40:42 | socket not open, so packet
> > not sent SERVICE_CONTROL_CODE : 4
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 |
SERVICE_CONTROL_INTERROGATE
> > INFO   | wrapper  | 2008/02/08 01:40:42 | Wrapper Process has not
> > received any CPU time for 48 seconds.  Extending timeouts.
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | JVM process exited with a
> > code of 1, setting the wrapper exit code to 1.
> > ERROR  | wrapper  | 2008/02/08 01:40:42 | JVM exited unexpectedly.
> > DEBUG  | wrapper  | 2008/02/08 01:40:42 | Waiting 5 seconds before
> > launching another JVM.
> > DEBUG  | wrapper  | 2008/02/08 01:40:46 | Classpath element,
> > wrapper.java.classpath.10, does not exist: ../classes
> > STATUS | wrapper  | 2008/02/08 01:40:46 | Launching a JVM...
> > NONE   | wrapper  | 2008/02/08 01:40:46 | command:
> > "D:\IBM\WBIServer\jre\bin\java.exe"
> > -Dsequencer.context=AU04QWS130DCA32
> > -Dsequencer.logs=d:\wppaup\runtime\var\sequencer\logs
> > -Drepository.directory=D:\IBM\Sequencer -Djava.library.path="./lib"
> > -classpath
> > 
> 
"./lib/wrapper.jar;./lib/commons-collections-3.1.jar;./lib/commons-lang-
2.1.jar;./lib/commons-logging-1.0.4.jar;./lib/commons-net-1.4.1.jar;./li
b/jakarta-oro.jar;./lib/log4j-1.2.7.jar;./lib/spring.jar;./lib/velocity-
1.4.jar;../classes;./lib/sequencer.jar" 

>
> > -Dwrapper.key="2ZXzPWYAZ6Ry7obW" -Dwrapper.port=32002
> > -Dwrapper.jvm.port.min=31000 -Dwrapper.jvm.port.max=31999
> > -Dwrapper.debug="TRUE" -Dwrapper.pid=2508 -Dwrapper.version="3.2.3"
> > -Dwrapper.native_library="wrapper" -Dwrapper.service="TRUE"
> > -Dwrapper.cpu.timeout="10" -Dwrapper.jvmid=9
> > org.tanukisoftware.wrapper.WrapperSimpleApp SequencerTool LOOP
> > DEBUG  | wrapper  | 2008/02/08 01:40:46 | JVM started (PID=9500)
>
>
> 
------------------------------------------------------------------------
-
> This SF.net email is sponsored by: Microsoft
> Defy all challenges. Microsoft(R) Visual Studio 2008.
> http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
> _______________________________________________
> Wrapper-user mailing list
> Wra...@li...
> https://lists.sourceforge.net/lists/listinfo/wrapper-user
>
>
>
------------------------------------------------------------------------
>
> 
------------------------------------------------------------------------
-
> This SF.net email is sponsored by: Microsoft
> Defy all challenges. Microsoft(R) Visual Studio 2008.
> http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
>
------------------------------------------------------------------------
>
> _______________________________________________
> Wrapper-user mailing list
> Wra...@li...
> https://lists.sourceforge.net/lists/listinfo/wrapper-user


-------------- next part --------------
An HTML attachment was scrubbed...

------------------------------

------------------------------------------------------------------------
-
This SF.net email is sponsored by: Microsoft
Defy all challenges. Microsoft(R) Visual Studio 2008.
http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/

------------------------------

_______________________________________________
Wrapper-user mailing list
Wra...@li...
https://lists.sourceforge.net/lists/listinfo/wrapper-user


End of Wrapper-user Digest, Vol 21, Issue 9
*******************************************