Bug 56546 - Improve thread trace logging in WebappClassLoader.clearReferencesThreads()
Improve thread trace logging in WebappClassLoader.clearReferencesThreads()
Status: NEW
Product: Tomcat 8
Classification: Unclassified
Component: Catalina
8.0.5
PC All
: P1 enhancement (vote)
: ----
Assigned To: Tomcat Developers Mailing List
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2014-05-19 21:58 UTC by Konstantin Kolinko
Modified: 2014-11-30 22:14 UTC (History)
1 user (show)



Attachments
Diff file fort to list all stack traces before clearing threads (1.66 KB, patch)
2014-11-30 22:14 UTC, Ahmed Hosny
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Konstantin Kolinko 2014-05-19 21:58:14 UTC
In r1574508 I added to Tomcat 8 the feature that when WebappClassLoader.clearReferencesThreads() detects a still-running thread in a web application, it prints not only a textual message, but also stacktrace of the problematic thread. This feature is released in 8.0.5 (8.0.4 onwards).

In Comment 3 of BZ 56399 Remy raises the issue that this feature is too noisy.
https://issues.apache.org/bugzilla/show_bug.cgi?id=56399#c3

For reference, the following test cases in tomcat 8.0.8 RC print this message:

org.apache.catalina.connector.TestMaxConnections
org.apache.catalina.loader.TestWebappClassLoaderExecutorMemoryLeak
org.apache.tomcat.websocket.TestWsWebSocketContainer
Comment 1 Konstantin Kolinko 2014-05-19 22:13:47 UTC
Possible ways to improve this:

A. Reduce the log level for stack trace message from log.error() to log.info().
In the current code there are two "log.error()" messages at once, which looks like overkill.

> log.error(sm.getString("webappClassLoader.warnThread",
>   getContextName(), threadName));
> log.error(sm.getString("webappClassLoader.stackTrace",
>   threadName, getStackTrace(thread)));

B. Make this an opt-in feature. A new property on <Context>?
Or two properties, to distinct handling of "request threads" vs. "non-request" threads.

C. Merge similar logs into a single message?
(E.g. if there are many request threads that are stuck in the same place).

I think "A." is a good and easy way to go.

Any additional ideas, concerns?
Comment 2 Konstantin Kolinko 2014-05-19 22:52:57 UTC
I applied "A." in r1596090.

D. Running org.apache.catalina.loader.TestWebappClassLoaderExecutorMemoryLeak,
I think it will be more readable, if all the stack traces are printed at once, as

20-May-2014 hh:mm:ss.sss INFO [threadname] org.apache.catalina.loader.WebappClassLoader.clearReferencesThreads Stack traces of threads for web application [/foo]:
Thread "name":
  stacktrace....
Thread "name":
  stacktrace....
Threads "name":
  stacktrace....
Comment 3 Mark Thomas 2014-05-22 08:58:58 UTC
org.apache.catalina.connector.TestMaxConnections no longer generates this message
Comment 4 Mark Thomas 2014-05-26 22:54:28 UTC
org.apache.tomcat.websocket.TestWsWebSocketContainer no longer generates this message.
Comment 5 Mark Thomas 2014-05-27 15:45:05 UTC
Is there anything more to do here? If not, I'll resolve this as fixed.
Comment 6 Konstantin Kolinko 2014-05-27 16:21:43 UTC
(In reply to Mark Thomas from comment #5)

I am OK to treat this as enhancement, though Remy raised this as a serious issue. In any case it is not a stopper for tagging 8.0.next.

On my TODO is to pursue idea from Comment 2 (print all traces at once).
I do no have time today though.

Implementing that needs some refactoring. My idea is to split threads loop into two loops, where the first one populates some informational structure and the second performs stopping (if enabled).

I think the current code has a minor issue:
It attempts to shut down executor for each encountered thread. Thus I think it does it N times if there are N running threads for the same Executor. This feature is off by default, though.
Comment 7 Remy Maucherat 2014-05-27 17:03:11 UTC
It is not actually a serious issue, it is cosmetic but fairly irriating ... So enhancement is fine, but I am bumping up the priority.
Comment 8 Ahmed Hosny 2014-11-30 22:14:12 UTC
Created attachment 32241 [details]
Diff file fort to list all stack traces before clearing threads

Fix bug 56546 list all stack traces before clearing threads, using two loops one for each purposem as Konstantin Kolinko suggested