Menu
▾
▴
Re: [Wrapper-user] "JVM appears hung": Wrapper restarts webserver every week
|
From: Andreas K. <and...@ya...> - 2009-05-04 14:38:10
|
Hi again, So now the server has crashed again - running longer than before thanks to the extended timout limit. The app eats memory and reports about low memory for days before the actual crash. The home made garbage collector thread takes 50% of processor-load also for days before the crash. I saw once in the log that the GC-succeeded to reduce the memory used significantly and the wrapper complained about it taking long time and increasing its limits. Here is a snap of the log prior to the crash. Any hints on how to debug this is highly appreciated;) brgds Andreas ************************************************************ ************************************************************ 2009/05/01 10:29:32 | send a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:32 | Received a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:32 | Send a packet PING : ok DEBUG | wrapperp | 2009/05/01 10:29:32 | read a packet PING : ok DEBUG | wrapper | 2009/05/01 10:29:32 | Got ping response from JVM INFO | jvm 1 | 2009/05/01 10:29:34 | 256520976 2009-05-01 10:29:34,894 WARN com.sse.supervisor.SSESupervisor ** Low of memory [0]mb free ! SSEGarbageCollect will occur. INFO | jvm 1 | 2009/05/01 10:29:36 | 2395102070 2009-05-01 10:29:36,191 WARN com.sse.supervisor.SSESupervisor ***** Real low of memory [0]mb free!!! Will garbagecollect all singletons and throwing out old members. INFO | jvm 1 | 2009/05/01 10:29:37 | 727880698 2009-05-01 10:29:37,472 ERROR com.sse.supervisor.SSESupervisor *************************** OUT OF MEMORY *** WILL DIE ***************************** DEBUG | wrapperp | 2009/05/01 10:29:38 | send a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:38 | Received a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:38 | Send a packet PING : ok INFO | jvm 1 | 2009/05/01 10:29:38 | 176404686 2009-05-01 10:29:38,769 WARN com.sse.thread.SSEThreadManager 1604 long living threads alive (warn limit = 25) DEBUG | wrapperp | 2009/05/01 10:29:38 | read a packet PING : ok DEBUG | wrapper | 2009/05/01 10:29:38 | Got ping response from JVM INFO | jvm 1 | 2009/05/01 10:29:43 | 4102609922 2009-05-01 10:29:42,644 WARN com.sse.supervisor.SSESupervisor ** Low of memory [0]mb free ! SSEGarbageCollect will occur. DEBUG | wrapperp | 2009/05/01 10:29:44 | send a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:45 | Received a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:45 | Send a packet PING : ok INFO | jvm 1 | 2009/05/01 10:29:45 | 3599369368 2009-05-01 10:29:45,207 WARN com.sse.supervisor.SSESupervisor ***** Real low of memory [0]mb free!!! Will garbagecollect all singletons and throwing out old members. DEBUG | wrapperp | 2009/05/01 10:29:45 | read a packet PING : ok DEBUG | wrapper | 2009/05/01 10:29:45 | Got ping response from JVM INFO | jvm 1 | 2009/05/01 10:29:49 | 1881161018 2009-05-01 10:29:47,801 ERROR com.sse.supervisor.SSESupervisor *************************** OUT OF MEMORY *** WILL DIE ***************************** DEBUG | wrapperp | 2009/05/01 10:29:50 | send a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:50 | Received a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:50 | Send a packet PING : ok DEBUG | wrapperp | 2009/05/01 10:29:50 | read a packet PING : ok DEBUG | wrapper | 2009/05/01 10:29:50 | Got ping response from JVM DEBUG | wrapperp | 2009/05/01 10:29:56 | send a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:56 | Received a packet PING : ping INFO | jvm 1 | 2009/05/01 10:29:56 | Send a packet PING : ok DEBUG | wrapperp | 2009/05/01 10:29:56 | read a packet PING : ok DEBUG | wrapper | 2009/05/01 10:29:56 | Got ping response from JVM INFO | jvm 1 | 2009/05/01 10:29:59 | 1644323367 2009-05-01 10:29:49,097 WARN com.sse.thread.SSEThreadManager 1605 long living threads alive (warn limit = 25) DEBUG | wrapperp | 2009/05/01 10:30:02 | send a packet PING : ping INFO | jvm 1 | 2009/05/01 10:30:03 | Closing socket. INFO | jvm 1 | 2009/05/01 10:30:03 | 1959232901 2009-05-01 10:29:54,254 WARN com.sse.thread.SSEATThread ATWork jammed: SSEGarbageWrapper: [java.lang.ref.WeakReference@1662402] INFO | jvm 1 | 2009/05/01 10:30:03 | Server daemon died! INFO | jvm 1 | 2009/05/01 10:30:03 | java.lang.OutOfMemoryError INFO | jvm 1 | 2009/05/01 10:30:03 | Open socket to wrapper... DEBUG | wrapperp | 2009/05/01 10:30:03 | socket read no code (closed?). DEBUG | wrapperp | 2009/05/01 10:30:03 | accepted a socket from 127.0.0.1 on port 2779 INFO | jvm 1 | 2009/05/01 10:30:07 | Opened Socket INFO | jvm 1 | 2009/05/01 10:30:07 | Send a packet KEY : iRUaWR2l6u5k5Rdr DEBUG | wrapperp | 2009/05/01 10:30:07 | read a packet KEY : iRUaWR2l6u5k5Rdr DEBUG | wrapper | 2009/05/01 10:30:07 | Got key from JVM: iRUaWR2l6u5k5Rdr DEBUG | wrapperp | 2009/05/01 10:30:08 | send a packet PING : ping INFO | jvm 1 | 2009/05/01 10:30:10 | INFO | jvm 1 | 2009/05/01 10:30:11 | Unexpected Signal : EXCEPTION_ACCESS_VIOLATION occurred at PC=0x6D3A5947 INFO | jvm 1 | 2009/05/01 10:30:11 | Function=[Unknown.] INFO | jvm 1 | 2009/05/01 10:30:11 | Library=C:\Program Files\Singleton\knahem\jre\bin\client\jvm.dll INFO | jvm 1 | 2009/05/01 10:30:11 | INFO | jvm 1 | 2009/05/01 10:30:11 | NOTE: We are unable to locate the function name symbol for the error INFO | jvm 1 | 2009/05/01 10:30:11 | just occurred. Please refer to release documentation for possible INFO | jvm 1 | 2009/05/01 10:30:11 | reason and solutions. INFO | jvm 1 | 2009/05/01 10:30:11 | INFO | jvm 1 | 2009/05/01 10:30:11 | INFO | jvm 1 | 2009/05/01 10:30:11 | Current Java thread: INFO | jvm 1 | 2009/05/01 10:30:11 | at java.net.PlainSocketImpl.socketAccept(Native Method) INFO | jvm 1 | 2009/05/01 10:30:11 | at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:353) INFO | jvm 1 | 2009/05/01 10:30:11 | - locked <03C62228> (a java.net.PlainSocketImpl) INFO | jvm 1 | 2009/05/01 10:30:11 | at java.net.ServerSocket.implAccept(ServerSocket.java:439) INFO | jvm 1 | 2009/05/01 10:30:11 | at java.net.ServerSocket.accept(ServerSocket.java:410) INFO | jvm 1 | 2009/05/01 10:30:11 | at org.mortbay.util.ThreadedServer.acceptSocket(ThreadedServer.java:346) INFO | jvm 1 | 2009/05/01 10:30:11 | at org.mortbay.util.ThreadedServer$Acceptor.run(ThreadedServer.java:523) INFO | jvm 1 | 2009/05/01 10:30:11 | INFO | jvm 1 | 2009/05/01 10:30:11 | Dynamic libraries: INFO | jvm 1 | 2009/05/01 10:30:11 | 0x00400000 - 0x00406000 C:\Program Files\Singleton\knahem\jre\bin\java.exe INFO | jvm 1 | 2009/05/01 10:30:11 | 0x7C800000 - 0x7C8C2000 C:\WINDOWS\system32\ntdll.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x77E40000 - 0x77F42000 C:\WINDOWS\system32\kernel32.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x7D1E0000 - 0x7D27C000 C:\WINDOWS\system32\ADVAPI32.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x77C50000 - 0x77CEF000 C:\WINDOWS\system32\RPCRT4.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x76F50000 - 0x76F63000 C:\WINDOWS\system32\Secur32.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x77BA0000 - 0x77BFA000 C:\WINDOWS\system32\MSVCRT.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x6D330000 - 0x6D45A000 C:\Program Files\Singleton\knahem\jre\bin\client\jvm.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x77380000 - 0x77411000 C:\WINDOWS\system32\USER32.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x77C00000 - 0x77C49000 C:\WINDOWS\system32\GDI32.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x76AA0000 - 0x76ACD000 C:\WINDOWS\system32\WINMM.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x6D1D0000 - 0x6D1D7000 C:\Program Files\Singleton\knahem\jre\bin\hpi.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x6D300000 - 0x6D30D000 C:\Program Files\Singleton\knahem\jre\bin\verify.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x6D210000 - 0x6D229000 C:\Program Files\Singleton\knahem\jre\bin\java.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x6D320000 - 0x6D32D000 C:\Program Files\Singleton\knahem\jre\bin\zip.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x16C10000 - 0x16C1E000 C:\Program Files\Singleton\knahem\jar\Wrapper.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x6D2D0000 - 0x6D2DE000 C:\Program Files\Singleton\knahem\jre\bin\net.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x71BB0000 - 0x71BB9000 C:\WINDOWS\system32\WSOCK32.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x71C00000 - 0x71C17000 C:\WINDOWS\system32\WS2_32.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x71BF0000 - 0x71BF8000 C:\WINDOWS\system32\WS2HELP.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x71B20000 - 0x71B61000 C:\WINDOWS\system32\mswsock.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x5F270000 - 0x5F2CA000 C:\WINDOWS\system32\hnetcfg.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x71AE0000 - 0x71AE8000 C:\WINDOWS\System32\wshtcpip.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x76ED0000 - 0x76EFA000 C:\WINDOWS\system32\DNSAPI.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x76F70000 - 0x76F77000 C:\WINDOWS\System32\winrnr.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x76F10000 - 0x76F3E000 C:\WINDOWS\system32\WLDAP32.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x76F80000 - 0x76F85000 C:\WINDOWS\system32\rasadhlp.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x76C10000 - 0x76C38000 C:\WINDOWS\system32\imagehlp.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x6D580000 - 0x6D628000 C:\WINDOWS\system32\dbghelp.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x77B90000 - 0x77B98000 C:\WINDOWS\system32\VERSION.dll INFO | jvm 1 | 2009/05/01 10:30:11 | 0x76B70000 - 0x76B7B000 C:\WINDOWS\system32\PSAPI.DLL INFO | jvm 1 | 2009/05/01 10:30:11 | INFO | jvm 1 | 2009/05/01 10:30:11 | Local Time = Fri May 01 10:30:10 2009 INFO | jvm 1 | 2009/05/01 10:30:11 | Elapsed Time = 1073809 INFO | jvm 1 | 2009/05/01 10:30:11 | # INFO | jvm 1 | 2009/05/01 10:30:11 | # HotSpot Virtual Machine Error : EXCEPTION_ACCESS_VIOLATION INFO | jvm 1 | 2009/05/01 10:30:11 | # Error ID : 4F530E43505002E6 INFO | jvm 1 | 2009/05/01 10:30:11 | # Please report this error at INFO | jvm 1 | 2009/05/01 10:30:11 | # http://java.sun.com/cgi-bin/bugreport.cgi INFO | jvm 1 | 2009/05/01 10:30:11 | # INFO | jvm 1 | 2009/05/01 10:30:11 | # Java VM: Java HotSpot(TM) Client VM (1.4.1_01-b01 mixed mode) INFO | jvm 1 | 2009/05/01 10:30:11 | # INFO | jvm 1 | 2009/05/01 10:30:11 | # An error report file has been saved as hs_err_pid1416.log. INFO | jvm 1 | 2009/05/01 10:30:11 | # Please refer to the file for further information. INFO | jvm 1 | 2009/05/01 10:30:11 | # ERROR | wrapper | 2009/05/01 10:30:11 | JVM exited unexpectedly. STATUS | wrapper | 2009/05/01 10:30:18 | Launching a JVM... DEBUG | wrapper | 2009/05/01 10:30:18 | command: ".\jre\bin\java.exe" -Xms96m -Xmx256m -Djava.library.path="jar" -classpath "jar/wrapper.jar;bin;jar/scm/jndi.zip;jar/scm/xmlParserAPIs.jar;jar/scm/xml-apis.jar;jar/scm/xercesImpl.jar;jar/scm/org.mortbay.jmx.jar;jar/scm/org.mortbay.jetty.jar;jar/scm/msutil.jar;jar/scm/mssqlserver.jar;jar/scm/msbase.jar;jar/scm/mail.jar;jar/scm/log4j-1.2.8.jar;jar/scm/jsse.jar;jar/scm/jnet.jar;jar/scm/jmxtools.jar;jar/scm/jmxri.jar;jar/scm/jcert.jar;jar/scm/javax.servlet.jar;jar/scm/jasper-runtime.jar;jar/scm/jasper-compiler.jar;jar/scm/ant.jar;jar/scm/activation.jar;jar/scm/jta.zip;jar/scm/nls_charset12.zip;jar/scm/jxl.jar" -Dwrapper.key="__cnKEm_eo5rsqvD" -Dwrapper.port=32000 -Dwrapper.debug="TRUE" -Dwrapper.service="TRUE" -Dwrapper.cpu.timeout="10" -Dwrapper.jvmid=2 org.tanukisoftware.wrapper.WrapperSimpleApp com.scm.main.WebServer khm DEBUG | wrapper | 2009/05/01 10:30:18 | Java Virtual Machine started (PID=8972) INFO | jvm 2 | 2009/05/01 10:30:20 | Wrapper Manager: JVM #2 INFO | jvm 2 | 2009/05/01 10:30:20 | Wrapper Manager: Registering shutdown hook INFO | jvm 2 | 2009/05/01 10:30:20 | Wrapper Manager: Using wrapper INFO | jvm 2 | 2009/05/01 10:30:20 | Calling native initialization method. INFO | jvm 2 | 2009/05/01 10:30:20 | Initializing WrapperManager native library. INFO | jvm 2 | 2009/05/01 10:30:20 | Java Executable: C:\Program Files\Singleton\knahem\jre\bin\java.exe INFO | jvm 2 | 2009/05/01 10:30:20 | Java Version : 1.4.1_01-b01 Java HotSpot(TM) Client VM INFO | jvm 2 | 2009/05/01 10:30:20 | Java VM Vendor : Sun Microsystems Inc. INFO | jvm 2 | 2009/05/01 10:30:20 | INFO | jvm 2 | 2009/05/01 10:30:20 | Wrapper (Version 3.0.5) INFO | jvm 2 | 2009/05/01 10:30:20 | INFO | jvm 2 | 2009/05/01 10:30:20 | Open socket to wrapper... INFO | jvm 2 | 2009/05/01 10:30:20 | Opened Socket INFO | jvm 2 | 2009/05/01 10:30:20 | Send a packet KEY : __cnKEm_eo5rsqvD INFO | jvm 2 | 2009/05/01 10:30:20 | handleSocket(Socket[addr=/127.0.0.1,port=32000,localport=2780]) DEBUG | wrapperp | 2009/05/01 10:30:20 | accepted a socket from 127.0.0.1 on port 2780 DEBUG | wrapperp | 2009/05/01 10:30:20 | read a packet KEY : __cnKEm_eo5rsqvD DEBUG | wrapper | 2009/05/01 10:30:20 | Got key from JVM: __cnKEm_eo5rsqvD DEBUG | wrapperp | 2009/05/01 10:30:20 | send a packet LOW_LOG_LEVEL : 1 DEBUG | wrapperp | 2009/05/01 10:30:20 | send a packet PING_TIMEOUT : 120 DEBUG | wrapper | 2009/05/01 10:30:20 | Start Application. DEBUG | wrapperp | 2009/05/01 10:30:20 | send a packet START : start INFO | jvm 2 | 2009/05/01 10:30:21 | Received a packet LOW_LOG_LEVEL : 1 INFO | jvm 2 | 2009/05/01 10:30:21 | Wrapper Manager: LowLogLevel from Wrapper is 1 INFO | jvm 2 | 2009/05/01 10:30:21 | Received a packet PING_TIMEOUT : 120 INFO | jvm 2 | 2009/05/01 10:30:21 | Wrapper Manager: PingTimeout from Wrapper is 120000 INFO | jvm 2 | 2009/05/01 10:30:21 | Received a packet START : start INFO | jvm 2 | 2009/05/01 10:30:21 | calling listener.start() INFO | jvm 2 | 2009/05/01 10:30:21 | WrapperSimpleApp: start(args) INFO | jvm 2 | 2009/05/01 10:30:21 | WrapperSimpleApp: invoking main method INFO | jvm 2 | 2009/05/01 10:30:22 | 1 2009-05-01 10:30:22,285 INFO com.sse.thread.SSEThreadManager SSEThreadManager created ****************************************************** ****************************************************** ****************************************************** --- Leif Mortenson <lei...@ta...> wrote: > Andreas, > One think that you have to be very careful of is to make sure that the > JVM is never forced to swap any of its memory to disk. This is > nothing related to the Wrapper. But Java gets VERY VERY VERY slow > when its memory is being swapped. It is common for 1/1000 affect on > performance. It may be possible that your new database is using a > lot more memory and thus forcing the JVM to swap. > > Take a look at your task manager and make sure you have enough memory. > I will see if there is any way that I can tell when this is happening > to Java and warn the user about it in the log. > > Cheers, > Leif > > On Fri, Apr 17, 2009 at 5:02 PM, Andreas Karlsson > <and...@ya...> wrote: > > > > Hi Leif, > > I've restarted it with the setting you suggested. > > The problem shows up at any time between 7-10 days from last restart. > > Often the application complains about low memory and performs garbage collection > > prior to that. > > I've been fiddling with the memory settings and now they should be the same for > the > > server-jvm-wrapper but the error still occurs. > > I'll get back to you next week when it has restarted again. > > brgds > > Andreas > > > > --- Leif Mortenson <le...@ta...> wrote: > > > >> Andreas, > >> Most likely the Java process is being starved of CPU and that is > >> leading to the Wrapper thinking it is frozen. If that is the case > >> then you can easily resolve the problem by setting the following > >> property: > >> wrapper.ping.timeout=120 > >> (http://wrapper.tanukisoftware.org/doc/english/prop-ping-timeout.html) > >> > >> That will tell the Wrapper to allow the JVM to be frozen for 120 > >> seconds before it is killed. The default is 30 seconds. > >> > >> However, your web site would be unresponsive during that period still. > >> Most likely it is now for at least 30 seconds. Do the restarts > >> happen at any particular time each week? Is there some large DB > >> processing being done that is consuming all of the CPU? It may be > >> necessary to move the Database over to another physical server to make > >> sure your app server is not being affected by that processing. > >> > >> If you set the wrapper.debug=TRUE property and then reproduce this, I > >> might be able to tell you a little more information about what is > >> happening prior to the restart. I would only need the 3-5 minutes of > >> time prior to the Wrapper timing out and killing the JVM. > >> > >> There have also been several bugs fixed since 3.0.5 which could affect > >> this. Please review the release-notes: > >> http://wrapper.tanukisoftware.org/doc/english/release-notes.html > >> > >> Cheers, > >> Leif > >> > >> On Thu, Apr 16, 2009 at 5:55 PM, Andreas Karlsson > >> <and...@ya...> wrote: > >> > > >> > Hi wrapper-folks! > >> > I would love some hints and ideas on how to debug this problem and find a > >> solution. > >> > > >> > The system is a > >> > - windows server 2003 > >> > - jettyserver > >> > - java 1.4.1 > >> > - wrapper 3.0.5 > >> > > >> > It has been running for years without any problems. But after some updates of > >> the > >> > data in the database where the web-content is stored and a recompile of the > code > >> it > >> > started to produce these messages (pasted below). It happens approximately > once > >> > every week. > >> > How can I debug this? > >> > Is there a way to trigg a dump when it happens? > >> > > >> > > >> > ERROR | wrapper | 2009/04/15 10:17:07 | JVM appears hung: Timed out waiting > >> for > >> > signal from JVM. > >> > ERROR | wrapper | 2009/04/15 10:17:07 | Java Virtual Machine did not exit > on > >> > request, terminated > >> > STATUS | wrapper | 2009/04/15 10:17:13 | Launching a JVM... > >> > INFO | jvm 2 | 2009/04/15 10:17:14 | Wrapper (Version 3.0.5) > >> > > >> > brgds > >> > Andreas > > ------------------------------------------------------------------------------ > Stay on top of everything new and different, both inside and > around Java (TM) technology - register by April 22, and save > $200 on the JavaOne (SM) conference, June 2-5, 2009, San Francisco. > 300 plus technical and hands-on sessions. Register today. > Use priority code J9JMT32. http://p.sf.net/sfu/p > _______________________________________________ > Wrapper-user mailing list > Wra...@li... > https://lists.sourceforge.net/lists/listinfo/wrapper-user > |
