Re: [Wrapper-user] Service consumes 100% of dual-CPU resources

[Leif M. <le...@ta...>]

John,
    The problem with the corrupted log messages is a problem that I have 
fixed for the
3.1.0 release.  The logging code used a static buffer to build up the 
log messages
which was not thread safe.   99% of the Wrapper operates in a single 
thread so this is
not normally a problem.  The exceptions are log messages made from 
within a signal
handler and callbacks from the NT Service Manager.  Both of which are in 
other
threads.   This has all been fixed for the next release.  But other than 
corrupted
messages, this should not be causing any other problems because of the 
way the
buffer conflicts were taking place.  You are actually the only user I 
have heard from
this problem on.  I encountered it myself while developing 3.1.0 because 
that version
makes use of an additional timer thread which made the problem more obvious.

    As to your problem with the application eating 100% CPU,  could you 
give me
a little more information.   When the CPU is at 100%, what does the Task 
Manager
show?  Is the CPU being used by the JVM or by the Wrapper process?  
Other than
Jennifer's idea about sending large quantities of log events to the 
Event Logger (syslog)
I don't think this is your problem however because it does not appear as 
if you have
that much log output.  I don't have many ideas at this point.  I don't 
know of any
problems where the Wrapper has been responsible for this sort of problem.

    Another user had a similar problem a little while ago which was 
being caused by
a thread that was attempting to read from System.in.  The Wrapper does 
not allow
this and was throwing an exception.   The problem was that he had the 
read in a
try catch Throwable block which was in a while loop without any delay.  
This of
course consumed 100% CPU.  The code would work when not running under the
Wrapper.
    It is often useful to write a runner thread which catches and logs 
everything and
designed to never die.  But as a rule I always add a sleep(5000) after I 
log such
unexpected exception.  By doing this, it guarantees that the code will 
never enter
a state where it starts consuming 100% CPU.   Defensive programming.

    If the CPU is being used by the JVM rather than the Wrapper process, try
pressing CTRL-BREAK a couple times in the console.   This will cause it 
to dump
a full thread dump to the log.  You may get some clues by looking at 
what the
various threads are doing.

Cheers,
Leif
 

john yanlin wrote:

>Hi, All,
>
>We have been using the wrapper for some win NT services. Recently we
>occasionally ran into some problem where the services consume almost all
>(99%, 100%) the CPU resources of a dual-CPU machine. The following is a
>segment of the wrapper log file:
>
>=============================================================================
>INFO   | jvm 1    | 2004/02/18 06:31:25 | Send a packet 103 : ok
>DEBUG  | wrapperp | 2004/02/18 06:31:25 | read a packet 103 : ok
>DEBUG  | wrapper  | 2004/02/18 06:31:25 | Got ping response from JVM
>DEBUG  | wrapper  | 2004/02/18 06:31:26 | ServiceControlHandler(4)
>DEBUG  | wrapper  | 2004/02/18 06:31:26 |   SERVICE_CONTROL_INTERROGATE
>DEBUG  | wrapperp | 2004/02/18 06:31:31 | sent 6 bytes
>INFO   | jvm 1    | 2004/02/18 06:31:31 | Received a packet 103 : ping
>INFO   | jvm 1    | 2004/02/18 06:31:31 | Send a packet 103 : ok
>DEBUG  | wrapperp | 2004/02/18 06:31:31 | read a packet 103 : ok
>DEBUG  | wrapper  | 2004/02/18 06:31:31 | Got ping response from JVM
>DEBUG  | wrapperp | 2004/02/18 06:31:37 | sent 6 bytes
>DEBUG  | wrapper  | 2004/02/18 06:31:37 | ServiceControlHandler(4)
>Dvm 1    | 20E0UG4/02 | 18 06wrapper  | 31:37 | Received a packet 103 :
>ping
>Dvm 1    | 20E0UG4/02 | 18 06wrapper  | 31:37 | Received a packet 103 :
>ping
>2004/02/18 06:31:37 |   SERVICE_CONTROL_INTERROGATE
>STATUS | wrapper  | 2004/02/18 10:38:00 | --> Wrapper Started as Service
>DEBUG  | wrapperp | 2004/02/18 10:38:00 | server listening on port 17005.
>DEBUG  | wrapper  | 2004/02/18 10:38:00 | JVM was only running for
>-322562155 seconds leading to a failed restart count of 1.
>STATUS | wrapper  | 2004/02/18 10:38:00 | Launching a JVM...
>===================================================================================
>
>>From which we can see that at 6:31:37 something went wrong. There are two
>lines in the log are exactly the same and the contents are sort of mixed.
>It should be something like:
>
>DEBUG | wrapper | 2004/02/18 | 06:31:37 | Received a packet 103 : ping
>
>Instead, it came out mixed as:
>
>Dvm 1    | 20E0UG4/02 | 18 06wrapper  | 31:37 | Received a packet 103 :
>ping
>Dvm 1    | 20E0UG4/02 | 18 06wrapper  | 31:37 | Received a packet 103 :
>ping
>
>The DEBUG and the date time were mixed. There was a 'B' in the 'DEBUG'
>missing. the 'J' for 'Jvm 1' was also missing. During that time, the
>service shown active in the windows service manager panel. But the actual
>service was hung. 
>
>It seems that there was something happening inside the wrapper native
>part. Have anyone ever got the similar situation like this? Could anyone
>suggest what was happening here?
>
>Thanks,
>
>  
>