Re: [Wrapper-user] Wrapper did not ping JVM for several minutes

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

Osiris,
Could you please send me your wrapper.conf, and the full wrapper.log
file so I can review this in context.  Initially I am interested in
what the various timeout values in your wrapper.conf are set to.  I
would also like to see in more detail exactly what is and isn't
happening, and when.

The first message is normal line of output when
wrapper.state_output=TRUE is set.   The second line you sent is a
message from the JVM that is logged when it has not received any pings
from the Wrapper process for a long period of time.  The fact that you
are seeing the message however shows that the Wrapper process is alive
to log it.

As your CPU is low, one possible cause is when the system is
undergoing heavy swapping.   Your iowait is low however.

Is this a physical server or a virtual machine?

Please feel free to contact su...@ta... directly with
your reply so we don't hit the list with the large log files.  I will
update the thread when we figure out what is happening.

Cheers,
Leif

On Mon, Aug 16, 2010 at 4:34 PM, Osiris <os...@ia...> wrote:
> I am running the Linux Java Service Wrapper (3.5.3) and have been having the
> following problem for months: every few hours (randomly it seems), the
> wrapper does not ping the JVM for about 5 minutes:
>
>
>
> STATUS | wrapper  | 2010/08/15 18:47:08 |     Ticks=0001c8b5,
> WrapperState=STARTED, JVMState=STARTED JVMStateTimeoutTicks=0001c9ed (31s),
> Exit=false, RestartMode=0, Orphan=false
>
>        INFO   | jvm 1    | 2010/08/15 18:52:08 | WrapperManager Debug: Read
> Timed out. (Last Ping was 303,200 milliseconds ago)
>
>
>
> CPU usage is minimal during this time, and the server was given a hardware
> swap to rule out faulty hardware and there is no power management on the
> server. Has anyone seen this behaviour before?
>
>
>
> In the following sar output (logs every minute), there are some missing
> entries (18:49, 18:51), which might indicate CPU suspension for some reason:
>
> sar -s 18:48:00 -e 18:52:00 -f /var/log/sysstat/sa15 -u -d -r -n ALL
>
>
>
> 18:48:01        CPU     %user     %nice   %system   %iowait    %steal
> %idle
>
> 18:50:01        all      0.10      0.00      0.16      0.01      0.00
> 99.74
>
> Average:        all      0.10      0.00      0.16      0.01      0.00
> 99.74
>
>
>
> 18:48:01    kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit
> %commit
>
> 18:50:01      3078524   1033780     25.14    144144    487128    665964
> 3.19
>
> Average:      3078524   1033780     25.14    144144    487128    665964
> 3.19
>
>
>
> 18:48:01          DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz
> await     svctm     %util
>
> 18:50:01       dev8-0     22.40      0.00    307.20     13.71      0.14
> 6.43      5.93     13.28
>
> 18:50:01      dev8-16     22.40      0.00    307.20     13.71      0.14
> 6.07      5.57     12.48
>
> 18:50:01       dev9-0      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
>
> 18:50:01       dev9-1     25.60      0.00    204.80      8.00      0.00
> 0.00      0.00      0.00
>
> Average:       dev8-0     22.40      0.00    307.20     13.71      0.14
> 6.43      5.93     13.28
>
> Average:      dev8-16     22.40      0.00    307.20     13.71      0.14
> 6.07      5.57     12.48
>
> Average:       dev9-0      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00
>
> Average:       dev9-1     25.60      0.00    204.80      8.00      0.00
> 0.00      0.00      0.00
>
>
>
> 18:48:01        IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s
> txcmp/s  rxmcst/s
>
> 18:50:01           lo      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00
>
> 18:50:01         eth0      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00
>
> Average:           lo      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00
>
> Average:         eth0      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00
>
>
>
> 18:48:01        IFACE   rxerr/s   txerr/s    coll/s  rxdrop/s  txdrop/s
> txcarr/s  rxfram/s  rxfifo/s  txfifo/s
>
> 18:50:01           lo      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00      0.00
>
> 18:50:01         eth0      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00      0.00
>
> Average:           lo      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00      0.00
>
> Average:         eth0      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00      0.00
>
>
>
> 18:48:01       call/s retrans/s    read/s   write/s  access/s  getatt/s
>
> 18:50:01         0.00      0.00      0.00      0.00      0.00      0.00
>
> Average:         0.00      0.00      0.00      0.00      0.00      0.00
>
>
>
> 18:48:01      scall/s badcall/s  packet/s     udp/s     tcp/s     hit/s
> miss/s   sread/s  swrite/s saccess/s sgetatt/s
>
> 18:50:01         0.00      0.00      0.00      0.00      0.00      0.00
> 0.00      0.00      0.00      0.00      0.00
>
> Average:         0.00      0.00      0.00      0.00      0.00      0.00
>     0.00      0.00      0.00      0.00      0.00
>
>
>
> 18:48:01       totsck    tcpsck    udpsck    rawsck   ip-frag    tcp-tw
>
> 18:50:01          105        12         2         0         0         0
>
> Average:          105        12         2         0         0         0