Menu
▾
▴
Re: [Wrapper-user] "JVM appears hung": Wrapper restarts webserver every week
|
From: Leif M. <lei...@ta...> - 2009-05-05 20:48:03
|
Andreas, This sounds like your application has a memory leak someplace. The Wrapper is failing because the JVM has run out of memory and is unable to continue. Have you tried playing around with creating a heap dump to see where your application is consuming so much memory? You can do so by adding the following to your wrapper.conf (set the additional number correctly): wrapper.java.additional.7=-Xrunhprof:heap=sites,depth=8 wrapper.shutdown.timeout=600 wrapper.jvm_exit.timeout=600 The long shutdown timeouts are needed to make sure the JVM has time to write the dump file. The JVM appears frozen while it is being written. Let me know if you have any questions understanding the file. Be aware that it will be quite large. Cheers, Leif On Mon, May 4, 2009 at 11:38 PM, Andreas Karlsson <and...@ya...> wrote: > > 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 |
