perf4j / perf4j Goto Github PK
View Code? Open in Web Editor NEWPerformance Monitoring and Statistics for Java Code
Home Page: perf4j.codehaus.org
License: Other
Performance Monitoring and Statistics for Java Code
Home Page: perf4j.codehaus.org
License: Other
AsyncCoalescingStatisticsAppender is not compatible with log4j2.
This feature works only with logback and log4j (1).
Hi, this could have had a well known work around or is not strictly related to perf4j, but I'm facing a weird issue running a SpringMVC application: whenever I deploy a new version of the WAR, my Tomcat 7 instance prints the following log line and after a while goes into OutOfMemoryError: PermGen space
.
SEVERE: The web application [/rest] appears to have started a thread named [perf4j-async-stats-appender-sink-CoalescingStatistics] but has failed to stop it. This is very likely to create a memory leak. ago 31, 2015 6:14:56 PM org.apache.catalina.core.ApplicationContext log
Now, I know I can bump up the PermGen space, but that would be just a temporary workaround and it might work for one or two redeployements.
Is there something I am missing or doing wrong?
Clearly my setup is plain: perf4j and slf4j libraries are hosted within the web application, no specific reference from Spring context to perf4j or slf4j, an AspectJ aspect is used to invoke the StopWatch.
I can publish configuration files if needed, but they are pretty standard
ones...
Hello,
we've been stressing perf4j a bit and, sadly, encountered a deadlock where the log4j-config would not finish re-loading, which also meant regular logging calls to log4j were blocked. Here's the stacktrace:
"Timer-Log4jService" daemon prio=6 tid=0x0000000011224000 nid=0x1dfc waiting on condition [0x000000000eebe000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007ad8f3048> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:324)
at org.perf4j.helpers.GenericAsyncCoalescingStatisticsAppender.stopDrainingThread(GenericAsyncCoalescingStatisticsAppender.java:279)
at org.perf4j.helpers.GenericAsyncCoalescingStatisticsAppender.stop(GenericAsyncCoalescingStatisticsAppender.java:269)
at org.perf4j.log4j.AsyncCoalescingStatisticsAppender.close(AsyncCoalescingStatisticsAppender.java:293)
at org.apache.log4j.helpers.AppenderAttachableImpl.removeAllAppenders(AppenderAttachableImpl.java:140)
at org.apache.log4j.Category.removeAllAppenders(Category.java:868)
- locked <0x0000000784fa5af0> (a org.apache.log4j.Logger)
at org.apache.log4j.xml.DOMConfigurator.parseChildrenOfLoggerElement(DOMConfigurator.java:410)
at org.apache.log4j.xml.DOMConfigurator.parseCategory(DOMConfigurator.java:345)
- locked <0x0000000784fa5af0> (a org.apache.log4j.Logger)
at org.apache.log4j.xml.DOMConfigurator.parse(DOMConfigurator.java:827)
at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:712)
at org.apache.log4j.xml.DOMConfigurator.doConfigure(DOMConfigurator.java:618)
at org.apache.log4j.xml.DOMConfigurator.configure(DOMConfigurator.java:743)
at org.jboss.logging.Log4jService$URLWatchTimerTask.reconfigure(Log4jService.java:697)
at org.jboss.logging.Log4jService$URLWatchTimerTask.run(Log4jService.java:636)
at java.util.TimerThread.mainLoop(Timer.java:555)
at java.util.TimerThread.run(Timer.java:505)
Locked ownable synchronizers:
- None
Here's such a blocked call, waiting for log4j:
"WorkerThread#1[127.0.0.1:59645]" prio=6 tid=0x0000000022fdf800 nid=0xae0 waiting for monitor entry [0x00000000318bd000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:201)
- waiting to lock <0x0000000784fa5af0> (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:853)
at org.jboss.logging.log4j.Log4jLoggerPlugin.info(Log4jLoggerPlugin.java:193)
at org.jboss.logging.Logger.info(Logger.java:307)
at org.jboss.slf4j.JBossLoggerAdapter.info(JBossLoggerAdapter.java:180)
at org.perf4j.slf4j.Slf4JStopWatch.log(Slf4JStopWatch.java:407)
at org.perf4j.slf4j.Slf4JStopWatch.log(Slf4JStopWatch.java:359)
at org.perf4j.LoggingStopWatch.doLogInternal(LoggingStopWatch.java:238)
at org.perf4j.LoggingStopWatch.stop(LoggingStopWatch.java:130)
at org.perf4j.StopWatch.stop(StopWatch.java:209)
at my.company.PerformanceTestICI.stressPerf4j(PerformanceTestICI.java:37)
...
And yes, it's executing a method called stressPerf4j
;)
Which brings us to what I think happened:
We've been stressing perf4j, producing and stopping log4j-stopwatches as fast as possible within our JBoss 5.1. The production of stopwatches is faster than the async thread can process them. Therefore, the queue is full most of the time, and events get dropped. So far this works as designed.
However, we then refreshed the log4j-config a few times. And I think we got into a situation where the old draining thread was already shut down (or had an exception or what do I know) but GenericAsyncCoalescingStatisticsAppender.stopDrainingThread still or again tried to shut it down. However, the queue is full (as there was still a worker thread trying to write to it at full speed), the draining thread already shut down, so the stopDraininingThread-method will block forever when delivering the stopping message ""
to the full queue:
private void stopDrainingThread() {
try {
//pushing an empty string on the queue tells the draining thread that we're closing
loggedMessages.put(""); // <---- BLOCKED because the queue was full
//wait for the draining thread to finish
drainingThread.join(shutdownWaitMillis); // <---- this would have been more careful, but we never get here
drainingThread.interrupt();
So this method never gets anywhere.
For completeness sake, there is an active draining thread, but I think it's not the one the stopDrainingMethod is trying to talk to, as it seems to wait on a presumably empty queue:
"perf4j-async-stats-appender-sink-PERF_STATS_AGGREGATOR" daemon prio=6 tid=0x0000000011a9b800 nid=0xf18 waiting on condition [0x000000003124f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007de5b1470> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:389)
at org.perf4j.helpers.GenericAsyncCoalescingStatisticsAppender$StopWatchesFromQueueIterator.getNext(GenericAsyncCoalescingStatisticsAppender.java:388)
at org.perf4j.helpers.GenericAsyncCoalescingStatisticsAppender$StopWatchesFromQueueIterator.hasNext(GenericAsyncCoalescingStatisticsAppender.java:349)
at org.perf4j.helpers.GroupingStatisticsIterator.getNext(GroupingStatisticsIterator.java:149)
at org.perf4j.helpers.GroupingStatisticsIterator.hasNext(GroupingStatisticsIterator.java:102)
at org.perf4j.helpers.GenericAsyncCoalescingStatisticsAppender$Dispatcher.run(GenericAsyncCoalescingStatisticsAppender.java:314)
at java.lang.Thread.run(Thread.java:744)
Locked ownable synchronizers:
- None
I admit, the scenario might have been caused by some wonky reload of the log4j-configuration, but that stopDrainingThread method should not block forever if the thread is not working anymore as intended and the queue has filled up because of that. If I understand things correctly, if there ever is any reason for the draining thread to die, the queue would fill up even under slow load and the next log4j-reload would effectively stop all worker threads indefinitely.
So ... what's a good way to handle this situation and stop the thread reliably?
Regards
Daniel
PS: I'm posting this to perf4j so that people can see this, but the code looks the same in the jperf fork.
A declarative, efficient, and flexible JavaScript library for building user interfaces.
๐ Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
An Open Source Machine Learning Framework for Everyone
The Web framework for perfectionists with deadlines.
A PHP framework for web artisans
Bring data to life with SVG, Canvas and HTML. ๐๐๐
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
Some thing interesting about web. New door for the world.
A server is a program made to process requests and deliver data to clients.
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
Some thing interesting about visualization, use data art
Some thing interesting about game, make everyone happy.
We are working to build community through open source technology. NB: members must have two-factor auth.
Open source projects and samples from Microsoft.
Google โค๏ธ Open Source for everyone.
Alibaba Open Source for everyone
Data-Driven Documents codes.
China tencent open source team.