You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by ma...@apache.org on 2013/04/28 15:19:48 UTC

svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Author: markt
Date: Sun Apr 28 13:19:48 2013
New Revision: 1476761

URL: http://svn.apache.org/r1476761
Log:
Improve logging by naming the Servlet that hasn't stopped.

Modified:
    tomcat/trunk/java/org/apache/catalina/core/LocalStrings.properties
    tomcat/trunk/java/org/apache/catalina/core/StandardWrapper.java

Modified: tomcat/trunk/java/org/apache/catalina/core/LocalStrings.properties
URL: http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/catalina/core/LocalStrings.properties?rev=1476761&r1=1476760&r2=1476761&view=diff
==============================================================================
--- tomcat/trunk/java/org/apache/catalina/core/LocalStrings.properties (original)
+++ tomcat/trunk/java/org/apache/catalina/core/LocalStrings.properties Sun Apr 28 13:19:48 2013
@@ -175,7 +175,7 @@ standardWrapper.serviceExceptionRoot=Ser
 standardWrapper.unavailable=Marking servlet {0} as unavailable
 standardWrapper.unloadException=Servlet {0} threw unload() exception
 standardWrapper.unloading=Cannot allocate servlet {0} because it is being unloaded
-standardWrapper.waiting=Waiting for {0} instance(s) to be deallocated
+standardWrapper.waiting=Waiting for {0} instance(s) to be deallocated for Servlet [{1}]
 threadLocalLeakPreventionListener.lifecycleEvent.error=Exception processing lifecycle event {0}
 threadLocalLeakPreventionListener.containerEvent.error=Exception processing container event {0}
 

Modified: tomcat/trunk/java/org/apache/catalina/core/StandardWrapper.java
URL: http://svn.apache.org/viewvc/tomcat/trunk/java/org/apache/catalina/core/StandardWrapper.java?rev=1476761&r1=1476760&r2=1476761&view=diff
==============================================================================
--- tomcat/trunk/java/org/apache/catalina/core/StandardWrapper.java (original)
+++ tomcat/trunk/java/org/apache/catalina/core/StandardWrapper.java Sun Apr 28 13:19:48 2013
@@ -1403,7 +1403,8 @@ public class StandardWrapper extends Con
             while ((nRetries < 21) && (countAllocated.get() > 0)) {
                 if ((nRetries % 10) == 0) {
                     log.info(sm.getString("standardWrapper.waiting",
-                                          countAllocated.toString()));
+                                          countAllocated.toString(),
+                                          getName()));
                 }
                 try {
                     Thread.sleep(delay);



---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Mark Thomas <ma...@apache.org>.
On 28/04/2013 16:53, Rainer Jung wrote:
> On 28.04.2013 16:01, Konstantin Kolinko wrote:
>> 2. Maybe change default logging configuration to use OneLineFormatter.
>> It will give us thread names in the log,
>>
>> Alternatively, there appears to be a way to customize the pattern used
>> by SimpleFormatter
>> http://tomcat.markmail.org/thread/dxvweaxzkgwjymai
>> ("Cannot apply simpleformtatter pattern to catalina.sh" thread from Jan 2013)
> 
> The format customization added in Java 7 for SimpleFormatter is somehow
> limitted:
> 
> http://docs.oracle.com/javase/7/docs/api/java/util/logging/SimpleFormatter.html
> 
> The data from which you can choose is "date, source, logger, level,
> message, thrown", so current thread name doesn't seem to be an option.

Thanks for all the suggestions. I have console access to the box where
the test runs and it appears that the initialisation of the JSP servlet
is causing the request to take longer than the read timeout.

The test fails consistently from the command line with -Dtest.entry=...

I'll commit this change shortly while I continue to investigate why the
scan takes so long.

Mark

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Rainer Jung <ra...@kippdata.de>.
On 28.04.2013 16:01, Konstantin Kolinko wrote:
> 2. Maybe change default logging configuration to use OneLineFormatter.
> It will give us thread names in the log,
> 
> Alternatively, there appears to be a way to customize the pattern used
> by SimpleFormatter
> http://tomcat.markmail.org/thread/dxvweaxzkgwjymai
> ("Cannot apply simpleformtatter pattern to catalina.sh" thread from Jan 2013)

The format customization added in Java 7 for SimpleFormatter is somehow
limitted:

http://docs.oracle.com/javase/7/docs/api/java/util/logging/SimpleFormatter.html

The data from which you can choose is "date, source, logger, level,
message, thrown", so current thread name doesn't seem to be an option.

Regards,

Rainer

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Mark Thomas <ma...@apache.org>.
On 28/04/2013 15:01, Konstantin Kolinko wrote:
> 2013/4/28 Konstantin Kolinko <kn...@gmail.com>:
>> 2013/4/28 Mark Thomas <ma...@apache.org>:
>>> On 28/04/2013 14:19, markt@apache.org wrote:
>>>> Author: markt
>>>> Date: Sun Apr 28 13:19:48 2013
>>>> New Revision: 1476761
>>>>
>>>> URL: http://svn.apache.org/r1476761
>>>> Log:
>>>> Improve logging by naming the Servlet that hasn't stopped.
>>>
>>> I'm currently looking at the trunk unit test failures with buildbot. I'm
>>> not at all sure what is going on. The logs suggest threads are getting
>>> stuck for extended periods of time (minutes in some cases) but it always
>>> seems to happen with the same tests.
>>>
>>> The delays are too long for GC but they could be swapping related as
>>> buildbot is running on a VM. If that were the case I'd expect to see
>>> more variation in the test failures though.
>>>
>>> At the moment I am looking at improving the logging which has the added
>>> benefit of being useful to our users as well.
>>>
>>> What I really need is the ability to trigger a thread dump from within
>>> the JVM. While there are ways of doing it, none of them are particularly
>>> simple. I might look into this if the logging doesn't get me anywhere.
>>>
>>>
>>> Suggestions - and better still help - welcome.
>>>
> 
> 1.
> 
>> There exists Thread.getStackTrace()  @since 1.5 that can get
>> stacktrace from a different thread.
>>
>> I thought it could be a good addition to our WebAppLoader report of
>> non-stopped threads.
>>
>> There exists static method Thread.getAllStackTraces(): Map<Thread,
>> StackTraceElement[]>.

+1

> 2. Maybe change default logging configuration to use OneLineFormatter.
> It will give us thread names in the log,
> 
> Alternatively, there appears to be a way to customize the pattern used
> by SimpleFormatter
> http://tomcat.markmail.org/thread/dxvweaxzkgwjymai
> ("Cannot apply simpleformtatter pattern to catalina.sh" thread from Jan 2013)
> 
> 3. "Read time out" errors
> http://ci.apache.org/projects/tomcat/tomcat8/logs/1476401/TEST-org.apache.catalina.loader.TestVirtualContext.BIO.txt
> http://ci.apache.org/projects/tomcat/tomcat8/logs/1476401/TEST-org.apache.catalina.loader.TestVirtualContext.NIO.txt
> 
> What is strange is that the whole Tomcat startup and shutdown appears
> to be faster
> than timeout value reported by client thread
> (read fails after 12 and 9 seconds and Tomcat goes up and down in 10 and 7).

The read fails after 3s. The 12s and 9s figures are for the entire test.

> 4.
> http://ci.apache.org/projects/tomcat/tomcat8/logs/1476401/TEST-org.apache.catalina.core.TestAsyncContextImpl.BIO.txt
> 
> says
> "java.lang.IllegalStateException: Calling [asyncDispatch()] is not
> valid for a request with Async state [MUST_COMPLETE]"
> 
> There is no such message in NIO test.

Haven't looked into this yet but it looks possible this might have the
same root cause.


Fundamentally, the VM running the tests appears to have quite big IO
delays. This is triggering failures in some timing related tests.

I suspect there isn't much we can do about this short of buying new
hardware. I'll stick my infra hat on and take a look at the VM host.

Mark


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Konstantin Kolinko <kn...@gmail.com>.
2013/4/28 Konstantin Kolinko <kn...@gmail.com>:
> 2013/4/28 Mark Thomas <ma...@apache.org>:
>> On 28/04/2013 14:19, markt@apache.org wrote:
>>> Author: markt
>>> Date: Sun Apr 28 13:19:48 2013
>>> New Revision: 1476761
>>>
>>> URL: http://svn.apache.org/r1476761
>>> Log:
>>> Improve logging by naming the Servlet that hasn't stopped.
>>
>> I'm currently looking at the trunk unit test failures with buildbot. I'm
>> not at all sure what is going on. The logs suggest threads are getting
>> stuck for extended periods of time (minutes in some cases) but it always
>> seems to happen with the same tests.
>>
>> The delays are too long for GC but they could be swapping related as
>> buildbot is running on a VM. If that were the case I'd expect to see
>> more variation in the test failures though.
>>
>> At the moment I am looking at improving the logging which has the added
>> benefit of being useful to our users as well.
>>
>> What I really need is the ability to trigger a thread dump from within
>> the JVM. While there are ways of doing it, none of them are particularly
>> simple. I might look into this if the logging doesn't get me anywhere.
>>
>>
>> Suggestions - and better still help - welcome.
>>

1.

> There exists Thread.getStackTrace()  @since 1.5 that can get
> stacktrace from a different thread.
>
> I thought it could be a good addition to our WebAppLoader report of
> non-stopped threads.
>
> There exists static method Thread.getAllStackTraces(): Map<Thread,
> StackTraceElement[]>.

2. Maybe change default logging configuration to use OneLineFormatter.
It will give us thread names in the log,

Alternatively, there appears to be a way to customize the pattern used
by SimpleFormatter
http://tomcat.markmail.org/thread/dxvweaxzkgwjymai
("Cannot apply simpleformtatter pattern to catalina.sh" thread from Jan 2013)

3. "Read time out" errors
http://ci.apache.org/projects/tomcat/tomcat8/logs/1476401/TEST-org.apache.catalina.loader.TestVirtualContext.BIO.txt
http://ci.apache.org/projects/tomcat/tomcat8/logs/1476401/TEST-org.apache.catalina.loader.TestVirtualContext.NIO.txt

What is strange is that the whole Tomcat startup and shutdown appears
to be faster
than timeout value reported by client thread
(read fails after 12 and 9 seconds and Tomcat goes up and down in 10 and 7).

4.
http://ci.apache.org/projects/tomcat/tomcat8/logs/1476401/TEST-org.apache.catalina.core.TestAsyncContextImpl.BIO.txt

says
"java.lang.IllegalStateException: Calling [asyncDispatch()] is not
valid for a request with Async state [MUST_COMPLETE]"

There is no such message in NIO test.




Best regards,
Konstantin Kolinko

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Konstantin Kolinko <kn...@gmail.com>.
2013/4/28 Mark Thomas <ma...@apache.org>:
> On 28/04/2013 14:19, markt@apache.org wrote:
>> Author: markt
>> Date: Sun Apr 28 13:19:48 2013
>> New Revision: 1476761
>>
>> URL: http://svn.apache.org/r1476761
>> Log:
>> Improve logging by naming the Servlet that hasn't stopped.
>
> I'm currently looking at the trunk unit test failures with buildbot. I'm
> not at all sure what is going on. The logs suggest threads are getting
> stuck for extended periods of time (minutes in some cases) but it always
> seems to happen with the same tests.
>
> The delays are too long for GC but they could be swapping related as
> buildbot is running on a VM. If that were the case I'd expect to see
> more variation in the test failures though.
>
> At the moment I am looking at improving the logging which has the added
> benefit of being useful to our users as well.
>
> What I really need is the ability to trigger a thread dump from within
> the JVM. While there are ways of doing it, none of them are particularly
> simple. I might look into this if the logging doesn't get me anywhere.
>
>
> Suggestions - and better still help - welcome.
>


There exists Thread.getStackTrace()  @since 1.5 that can get
stacktrace from a different thread.

I thought it could be a good addition to our WebAppLoader report of
non-stopped threads.

There exists static method Thread.getAllStackTraces(): Map<Thread,
StackTraceElement[]>.

Best regards,
Konstantin Kolinko

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Rainer Jung <ra...@kippdata.de>.
On 28.04.2013 16:44, Rainer Jung wrote:
> thread dump formatted very similar to the usual "kipp -QUIT" one:

Freudian typo: I mean't "kill -QUIT" :)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Rainer Jung <ra...@kippdata.de>.
On 28.04.2013 20:05, Mark Thomas wrote:
> On 28/04/2013 15:44, Rainer Jung wrote:
>> On 28.04.2013 15:28, Mark Thomas wrote:

>> I uploaded a class that has a static getDump() method which returns a
>> thread dump formatted very similar to the usual "kipp -QUIT" one:
>>
>> http://people.apache.org/~rjung/ThreadDump.java
>>
>> It retrieves the ThreadMXBean from the platform MBean server, gets the
>> ThreadInfo for each thread and formats the data. HTH.
>>
>> I had to strip down some longer code I had and only did a very quick
>> test but it seemed to work for me. It assumes Java 6 or newer.
> 
> I'm thinking o.a.tomcat.util.Diagnostics and add an option to call it
> from the manager. It is then available to any code that wants to use it.

I cleand it up and added it to trunk. I wired it to the text/script
manager (/text/vminfo and /text/threaddump). Not documented yet and some
XXX Todos in the file.

Regards,

Rainer

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Mark Thomas <ma...@apache.org>.
On 28/04/2013 15:44, Rainer Jung wrote:
> On 28.04.2013 15:28, Mark Thomas wrote:
>> On 28/04/2013 14:19, markt@apache.org wrote:
>>> Author: markt
>>> Date: Sun Apr 28 13:19:48 2013
>>> New Revision: 1476761
>>>
>>> URL: http://svn.apache.org/r1476761
>>> Log:
>>> Improve logging by naming the Servlet that hasn't stopped.
>>
>> I'm currently looking at the trunk unit test failures with buildbot. I'm
>> not at all sure what is going on. The logs suggest threads are getting
>> stuck for extended periods of time (minutes in some cases) but it always
>> seems to happen with the same tests.
>>
>> The delays are too long for GC but they could be swapping related as
>> buildbot is running on a VM. If that were the case I'd expect to see
>> more variation in the test failures though.
>>
>> At the moment I am looking at improving the logging which has the added
>> benefit of being useful to our users as well.
>>
>> What I really need is the ability to trigger a thread dump from within
>> the JVM. While there are ways of doing it, none of them are particularly
>> simple. I might look into this if the logging doesn't get me anywhere.
> 
> I uploaded a class that has a static getDump() method which returns a
> thread dump formatted very similar to the usual "kipp -QUIT" one:
> 
> http://people.apache.org/~rjung/ThreadDump.java
> 
> It retrieves the ThreadMXBean from the platform MBean server, gets the
> ThreadInfo for each thread and formats the data. HTH.
> 
> I had to strip down some longer code I had and only did a very quick
> test but it seemed to work for me. It assumes Java 6 or newer.

I'm thinking o.a.tomcat.util.Diagnostics and add an option to call it
from the manager. It is then available to any code that wants to use it.

Mark


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Rainer Jung <ra...@kippdata.de>.
On 28.04.2013 15:28, Mark Thomas wrote:
> On 28/04/2013 14:19, markt@apache.org wrote:
>> Author: markt
>> Date: Sun Apr 28 13:19:48 2013
>> New Revision: 1476761
>>
>> URL: http://svn.apache.org/r1476761
>> Log:
>> Improve logging by naming the Servlet that hasn't stopped.
> 
> I'm currently looking at the trunk unit test failures with buildbot. I'm
> not at all sure what is going on. The logs suggest threads are getting
> stuck for extended periods of time (minutes in some cases) but it always
> seems to happen with the same tests.
> 
> The delays are too long for GC but they could be swapping related as
> buildbot is running on a VM. If that were the case I'd expect to see
> more variation in the test failures though.
> 
> At the moment I am looking at improving the logging which has the added
> benefit of being useful to our users as well.
> 
> What I really need is the ability to trigger a thread dump from within
> the JVM. While there are ways of doing it, none of them are particularly
> simple. I might look into this if the logging doesn't get me anywhere.

I uploaded a class that has a static getDump() method which returns a
thread dump formatted very similar to the usual "kipp -QUIT" one:

http://people.apache.org/~rjung/ThreadDump.java

It retrieves the ThreadMXBean from the platform MBean server, gets the
ThreadInfo for each thread and formats the data. HTH.

I had to strip down some longer code I had and only did a very quick
test but it seemed to work for me. It assumes Java 6 or newer.

Regards,

Rainer

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org


Re: svn commit: r1476761 - in /tomcat/trunk/java/org/apache/catalina/core: LocalStrings.properties StandardWrapper.java

Posted by Mark Thomas <ma...@apache.org>.
On 28/04/2013 14:19, markt@apache.org wrote:
> Author: markt
> Date: Sun Apr 28 13:19:48 2013
> New Revision: 1476761
> 
> URL: http://svn.apache.org/r1476761
> Log:
> Improve logging by naming the Servlet that hasn't stopped.

I'm currently looking at the trunk unit test failures with buildbot. I'm
not at all sure what is going on. The logs suggest threads are getting
stuck for extended periods of time (minutes in some cases) but it always
seems to happen with the same tests.

The delays are too long for GC but they could be swapping related as
buildbot is running on a VM. If that were the case I'd expect to see
more variation in the test failures though.

At the moment I am looking at improving the logging which has the added
benefit of being useful to our users as well.

What I really need is the ability to trigger a thread dump from within
the JVM. While there are ways of doing it, none of them are particularly
simple. I might look into this if the logging doesn't get me anywhere.


Suggestions - and better still help - welcome.

Mark

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org