troubleshoot.xtp

RESIN 3.2 最新源码

<!-- section  -->
<s2 name="debug-log" title="Enable debug logging">

<p>Resin provides a number of diagnostic messages using the JDK logging
facility.  Full debug logging is enabled with an empty name (meaning match all
names) and a level of 'all'.  Since this will produce many messages, it is
useful to put the messages in a a seperate file.</p>

<s3 title="Full debug logging of the server and all applications">

<p>The following configuration creates a debug log for each day, and when a
problem occurs the debug log is used to help find out what the problem is.
Since the <a config-tag="log"/> entry is in <var>resin.xml</var>, the log will
capture messages from the server itself and all applications.  The resulting
log messages are found in the file <var>$RESIN_HOME/log/debug.log</var>.</p>

<example title="Full debug logging of the server to $RESIN_HOME/log/debug.log">
&lt;!-- resin.xml --&gt;
&lt;resin xmlns="http://caucho.com/ns/resin"&gt;
  &lt;log-handler name="" level="all" path="log/debug.log"
                  timestamp="[%H:%M:%S.%s] {%{thread}} "/>

  &lt;logger name="" level="finer"/>

&lt;/resin&gt;
</example>

<p>More specific areas can be targetted with appropriate values for
<code>name</code>.  The documentation for <a config-tag="log"/> provides a
table of useful values for <code>name</code>.

</p></s3>

<s3 title="Full debug logging of one web application">

<p>Often you can narrow down the logging requirements to a single web
application.  The log entry can be placed in
<var>&lt;web-app-root&gt;/WEB-INF/web.xml</var> and only log messages from that
web application will go to the log file.</p>

<p>The following configuration creates a debug log for each day in <var>&lt;web-app-root&gt;/WEB-INF/work/debug.log</var>.</p>


<example title="Full debug logging of one application to &lt;web-app-root&gt;/WEB-INF/work/debug.log">
&lt;!-- &lt;web-app-root&gt;/WEB-INF/web.xml --&gt;

&lt;web-app&gt;
  ...
  &lt;log name="" path="WEB-INF/work/debug.log" timestamp="[%H:%M:%S.%s] {%{thread}} "/>

  &lt;logger name="" level="finer"/>
  ...
&lt;/web-app&gt;
</example>
</s3>

</s2> <!-- debug-log -->

<!-- section  -->

<s2 name="thread-dump" title="Thread dump">

<p>If an application seems stuck, or is running out of resources, a thread dump
will reveal the state of the server.</p>

<p>Java's thread dumps are a vital tool for server debugging.  Because
servlets are intrinsically multithreaded, it is very possible to create
deadlocks without realizing it, or to have runaway threads that
consume resources and cause OutOfMemory exceptions.  That's
especially true when you start adding third-party software like
databases, EJB, and Corba ORBs.</p>

<s3 title="Thread dump using JDK 5 tools">
<p>
<var>jps</var> and <var>jstack</var> are useful tools included in JDK 5, providing a
quick command line method for obtaining stack traces of all current threads.
</p>

<example title="jps and jstack">
<b># jps</b>
12903 Jps
20087 Resin
<b># jstack 20087</b>
Attaching to process ID 20087, please wait...
Debugger attached successfully.
Client compiler detected.
JVM version is 1.5.0-beta2-b51
Thread 12691: (state = BLOCKED)
 - java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
 - com.caucho.util.ThreadPool.runTasks() @bci=111, line=474 (Compiled frame)
 - com.caucho.util.ThreadPool.run() @bci=85, line=423 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=595 (Interpreted frame)


Thread 12689: (state = BLOCKED)
 - java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
 - com.caucho.util.ThreadPool.runTasks() @bci=111, line=474 (Compiled frame)
 - com.caucho.util.ThreadPool.run() @bci=85, line=423 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=595 (Interpreted frame)

...

</example>

</s3>

<s3 title="Thread dump by sending a signal">

<p>On Windows, ctrl-break may produce a thread dump.</p>

<p>On Unix, "kill -QUIT" will produce a thread dump.</p>

</s3>

<s3 title="Thread dump if signalling doesn't work">

<p>You get a thread dump without signalling the process by starting the JVM
with some extra arguments to allow a debugger to attach.  You can then attach
with the debugger at any time to get a thread dump.  This
technique works on all operating systems.</p>

<p>Here are some step by step instructions:</p>

<ol>
<li>Start Resin with some extra arguments that allow a debugger to attach:

<example title="resin.xml for debugging">
&lt;resin xmlns="http://caucho.com/ns/resin">
&lt;cluster id="">

  &lt;server-default>
    &lt;jvm-arg>-Xdebug&lt;/jvm-arg>
    &lt;jvm-arg>-Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=5432&lt;/jvm-arg>
  &lt;/server-default>

  &lt;server id="" address="127.0.0.1" port="6800"/>
    
&lt;/cluster>
&lt;/resin>
</example>

</li><li>Wait until you believe the application is in a state of deadlock
or has runaway threads.

</li><li>In another terminal (window), use jdb to connect to the running instance of Resin:

<example>
$JAVA_HOME/bin/jdb -connect com.sun.jdi.SocketAttach:hostname=localhost,port=5432
</example>

jdb will show something like:

<example>
Set uncaught java.lang.Throwable
Set deferred uncaught java.lang.Throwable
Initializing jdb ...
&gt;
</example>

</li><li>Use the "suspend" command and then the "where all" command to get
a thread dump:

<example title="Example: jdbc suspend">
&gt; suspend

All threads suspended.
&gt; where all

tcpConnection-6862-3:

 [1] java.lang.Object.wait (native method)
 [2] com.caucho.server.TcpServer.accept (TcpServer.java:650)
 [3] com.caucho.server.TcpConnection.accept
(TcpConnection.java:208)
 [4] com.caucho.server.TcpConnection.run (TcpConnection.java:131)
 [5] java.lang.Thread.run (Thread.java:536)
tcpConnection-543-2:
 [1] java.lang.Object.wait (native method)
 [2] com.caucho.server.TcpServer.accept (TcpServer.java:650)
 [3] com.caucho.server.TcpConnection.accept
(TcpConnection.java:208)
 [4] com.caucho.server.TcpConnection.run (TcpConnection.java:131)
 [5] java.lang.Thread.run (Thread.java:536)

..
</example>
</li><li>Use the "resume" command to resume the process
<example>
&gt; resume
</example>

</li></ol>

<p>Unix users (and Cygwin users on Windows) will recognize the
opportunity to make a script:</p>
<example title="resin-thread-dump.sh">
#!/bin/sh
echo -e "suspend\nwhere all\nresume\nquit" | $JAVA_HOME/bin/jdb -connect \
  com.sun.jdi.SocketAttach:hostname=localhost,port=5432
</example>

<p>Although no rigorous benchmarking has been done, there appears to
be little overhead or performance penalties involved in having the JVM
start with the options that allow a debugger to attach.</p>
</s3>

<s3 title="Understanding the thread dump">

<p>In any case, you'll eventually get a trace that looks something like the following (each JDK is slightly different):</p>

<example>
Full thread dump:

"tcpConnection-8080-2" daemon waiting on monitor [0xbddff000..0xbddff8c4]
        at java.lang.Object.wait(Native Method)
        at com.caucho.server.TcpServer.accept(TcpServer.java:525)
        at com.caucho.server.TcpConnection.accept(TcpConnection.java:190)
        at com.caucho.server.TcpConnection.run(TcpConnection.java:136)
        at java.lang.Thread.run(Thread.java:484)

"tcpConnection-8080-1" daemon waiting on monitor [0xbdfff000..0xbdfff8c4]
        at java.lang.Object.wait(Native Method)
        at com.caucho.server.TcpServer.accept(TcpServer.java:525)
        at com.caucho.server.TcpConnection.accept(TcpConnection.java:190)
        at com.caucho.server.TcpConnection.run(TcpConnection.java:136)
        at java.lang.Thread.run(Thread.java:484)

"tcpConnection-8080-0" daemon waiting on monitor [0xbe1ff000..0xbe1ff8c4]
        at java.lang.Object.wait(Native Method)
        at com.caucho.server.TcpServer.accept(TcpServer.java:525)
        at com.caucho.server.TcpConnection.accept(TcpConnection.java:190)
        at com.caucho.server.TcpConnection.run(TcpConnection.java:136)
        at java.lang.Thread.run(Thread.java:484)

"tcp-accept-8080" runnable [0xbe7ff000..0xbe7ff8c4]
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:413)
        at java.net.ServerSocket.implAccept(ServerSocket.java:243)
        at java.net.ServerSocket.accept(ServerSocket.java:222)
        at com.caucho.server.TcpServer.run(TcpServer.java:415)
        at java.lang.Thread.run(Thread.java:484)

"resin-cron" daemon waiting on monitor [0xbe9ff000..0xbe9ff8c4]
        at java.lang.Thread.sleep(Native Method)
        at com.caucho.util.Cron$CronThread.run(Cron.java:195)

"resin-alarm" daemon waiting on monitor [0xbebff000..0xbebff8c4]
        at java.lang.Thread.sleep(Native Method)
        at com.caucho.util.Alarm$AlarmThread.run(Alarm.java:268)

"Signal Dispatcher" runnable [0..0]

"Finalizer" daemon waiting on monitor [0xbf3ff000..0xbf3ff8c4]
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:108)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:123)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:162)

"Reference Handler" daemon waiting on monitor [0xbf5ff000..0xbf5ff8c4]
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:420)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:110)

"main" waiting on monitor [0xbfffd000..0xbfffd210]
        at java.lang.Thread.sleep(Native Method)
        at com.caucho.server.http.ResinServer.waitForExit(ResinServer.java:674)
        at com.caucho.server.http.ResinServer.main(ResinServer.java:821)
        at com.caucho.server.http.HttpServer.main(HttpServer.java:95)
</example>

<p>Each thread is named.  Here are some of the common names:</p>

<deftable>
<tr><th>Thread Name</th><th>Description
</th></tr><tr><td>tcp-accept-8080</td><td>Resin thread listening for new connections
on port 8080.
</td></tr><tr><td>tcpConnection-8080-3</td><td>Resin servlet thread handling 
a connection from port 8080.
</td></tr><tr><td>tcp-cron</td><td>Resin's run-at thread
</td></tr><tr><td>tcp-alarm</td><td>Resin's alarm thread
</td></tr></deftable>

<p>There should be one tcp-accept-xxx thread for each &lt;http&gt; and
&lt;srun&gt; that Resin's listening for.  The tcp-accept-xxx thread should
almost always be in socketAccept.</p>

<p>There should be several tcpConnection-xxx-n threads.  Each of these
is the servlet thread.  On a busy server, these can appear anywhere in
your code.  If several appear in one location, you've likely got some sort
of deadlock or at least a slow lock.  Idle threads are either in tcpAccept or
httpRequest or runnerRequest (for keepalive threads.)</p>

<p>For deadlocks, you'll want to look at the "waiting on monitor" threads
and any case where lots of threads are stuck at the same location.</p>
</s3>

</s2> <!-- thread-dump -->

<s2 name="out-of-memory" title="Out of Memory and Garbage Collection">

<p>Most memory problems are due to memory leaks in the application
program.  For example, a cache or a vector that fills up with stale
data, or a singleton or static variable which doesn't properly
detect a web-app reload.  Some more exotic memory issues
relate to running out of heap memory or virtual memory when using
a large number of threads (&gt; 256).</p>

<p>The steps to track down a memory problem are:</p>

<ol>
<li>Enable -J-verbosegc with the resin.sh start or resin.exe -install.
The -verbosegc flag logs the garbage collection of the heap, which will
let you know if you're running out of heap memory (the most common case).
</li><li>Get a heap profiler or use the heap dump in the JVM.  JProfiler is an
inexpensive commercial heap profiler.  Although the JVM's heap dump is
not very user friendly, it's always available.  You should be using
a heap profiler as part of your development process and certainly use one
before any production launch.
</li><li>With the heap profiler, find the 2-3 top memory users and fix those
memory leaks.
</li><li>Common application errors include:
<ul>
<li>ThreadLocal variables that are not properly cleared at the end of each request.
</li><li>Singleton or static hash maps and caches, esp check for clearing web-app restarts.
</li><li>Spawned threads which are not stopped on web-app restart.
</li><li>web-app variables (like the "application" variable), stored in a static variable.
</li></ul>
</li><li>If the heap is clean, i.e. -verbosegc shows a steady heap, you'll need to
look at non-heap memory:
<ul>
<li>Thread stack usage (-Xss2m).  Each thread takes up some non-heap memory.
The default on some systems is 8 meg.  Because of 32-bit virtual memory limits of about 2G on some systems, even 256 threads with 8 meg stacks can chew up the virtual memory.  You can drop the stack size with the -Xss directive.
</li><li>JNI memory.  If you're using JNI libraries or drivers that use JNI,
it's possible that the JNI can allocate more memory than is available.
</li><li>fork/exec and OS limits.  If the OS does not have enough available
swap space, for example, the OS might refuse a "jikes" compilation.
</li><li>NIO, memory mapping, and .jar files.  The JDK memory-maps .jar files.
In some cases with very large numbers of jars, this can result in
running out of virtual memory.  The same issue can appear for NIO memory mapping.
</li></ul>
</li><li>If all of these are eliminated, it might be a Resin bug.  However,
you will need to have located the memory leak as Resin-related before
any memory-related bug report, i.e. it's necessary to go through the
above steps before reporting a bug.  Bug reports that complain
about OutOfMemory errors, but have not even gotten a JDK memory
dump are most likely application errors.  You must provide a
heap dump when reporting any potential Resin memory problems.
</li></ol>

<s3 title="-verbosegc">

<p>-verbosegc is a debugging output from the JVM.  It's very convenient
for checking basic memory usage and garbage collection time.  
It's a good idea to use -verbosegc for any production system.
When starting Resin, you'll use -J-verbosegc.</p>

<p>The specific output depends on the JVM, and looks something like
the following:</p>

<example title="-verbosegc output">
[GC 9176K-&gt;8647K(9768K), 0.0014790 secs]
[GC 9287K-&gt;8668K(9768K), 0.0011120 secs]
[GC 9308K-&gt;8668K(9768K), 0.0007810 secs]
</example>

<p>The "(9768K)" is the most important number, showing that the
maximum allocated heap is about 10 meg.  The other numbers show the
actual heap used before and after garbage collection.</p>

</s3>

<s3 name="heap-dump" title="Check memory usage with a heap dump">

<p>If an application gobbles up memory until it throws an OutOfMemory