Thanks Gary.
Limit number of threads can help alleviate the problem, but can't
make it disappear. Especially when it happens during midnight when
the workload will far below the average than the day,but we have no
such problems happens during day.
I didn't dive into the code to see what it is doing within the
synchronized block,which takes so much time.
I still think there should be something that is problematic in log4j.
------------------------------------------------------------------------
[email protected] <mailto:[email protected]>
*From:* Gary Gregory <mailto:[email protected]>
*Date:* 2015-07-02 17:35
*To:* Log4J Developers List <mailto:[email protected]>
*Subject:* Re: Re: Log4j2 RollingFileAppender deadlock issue
and let's be clear, unlike the subject of this thread, there is
no deadlock here, at least not in the thread dump you shared; the
application appears hung but is in fact slowed down to a crawl.
IMO that is ;-)
Gary
On Thu, Jul 2, 2015 at 2:34 AM, Gary Gregory
<[email protected] <mailto:[email protected]>> wrote:
The more threads you run to service additional requests is
making the problem worse IMO. This likely causes swapping out
the wazoo. I would bind the thread pool to try to avoid
in service.
Gary
On Thu, Jul 2, 2015 at 2:25 AM, [email protected]
<mailto:[email protected]> <[email protected]
<mailto:[email protected]>> wrote:
Thanks Gary.
So, it's abnormal for so many (2000+)threads to wait for
the lock. The workload of our application is not very
high. So, It is kind of too long for the
<0x0000000772fe2860> owner thread to unlock it.
6k threads in total is abnormal, as we are using
*unlimited* thread pool in our code to do HTTP requests
to other services when responding user's request. Since
the threads of the thread pool is waiting for the lock,
so the thread pool has to kick off new threads when we
throw tasks to it.
------------------------------------------------------------------------
[email protected] <mailto:[email protected]>
*From:* Gary Gregory <mailto:[email protected]>
*Date:* 2015-07-02 16:55
*To:* Log4J Developers List
<mailto:[email protected]>
*Subject:* Re: Re: Log4j2 RollingFileAppender
deadlock issue
Wow, > 6k threads? Is that normal for your application?
I do see two locks on two DatePatternConverter
instances, and both are working:
"resin-port-7280-7309" daemon prio=10
tid=0x00002ba94d16e000 nid=0x69e6 runnable
[0x00002bab56be5000]
java.lang.Thread.State: RUNNABLE
at
java.lang.AbstractStringBuilder.<init>(AbstractStringBuilder.java:64)
at java.lang.StringBuffer.<init>(StringBuffer.java:96)
at java.text.Format.format(Format.java:157)
at
org.apache.logging.log4j.core.pattern.DatePatternConverter$PatternFormatter.format(DatePatternConverter.java:50)
at
org.apache.logging.log4j.core.pattern.DatePatternConverter.format(DatePatternConverter.java:251)
- locked <0x00000007a2cecaa0> (a
org.apache.logging.log4j.core.pattern.DatePatternConverter)
at
org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
at
org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:189)
...
"DataChannel-1-thread-802" prio=10
tid=0x00002ba8c0022800 nid=0x1fbc runnable
[0x00002ba983230000]
java.lang.Thread.State: RUNNABLE
at java.lang.StringBuffer.toString(StringBuffer.java:561)
- locked <0x0000000772fe2860> (a java.lang.StringBuffer)
at java.text.Format.format(Format.java:157)
at
org.apache.logging.log4j.core.pattern.DatePatternConverter$PatternFormatter.format(DatePatternConverter.java:50)
at
org.apache.logging.log4j.core.pattern.DatePatternConverter.format(DatePatternConverter.java:251)
- locked <0x00000007a2cecc08> (a
org.apache.logging.log4j.core.pattern.DatePatternConverter)
at
org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
at
org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:189)
Lots (> 2k) of threads are waiting on these two locks.
So that is all 'normal' in the sense that I do not
see a deadlock, this is more of a starvation scenario.
--
Tangent for us Log4j devs:
It sure is lame that java.text.Format still uses a
StringBuffer internally instead of a StringBuilder,
which would be faster.
Looking at reusing Commons Lang's FastDateParser
would not help since it does not add StringBuilder
version of the StringBuffer APIs.
Gary
On Thu, Jul 2, 2015 at 1:26 AM, [email protected]
<mailto:[email protected]> <[email protected]
<mailto:[email protected]>> wrote:
Sorry, looks that I forgot to attach the thread
dump file.
------------------------------------------------------------------------
[email protected] <mailto:[email protected]>
*From:* [email protected] <mailto:[email protected]>
*Date:* 2015-07-02 16:25
*To:* log4j-dev
<mailto:[email protected]>
*Subject:* Re: Re: Log4j2 RollingFileAppender
deadlock issue
Thanks Gary for the reply.
The log related stuff is:
<log4j2.version>2.0.2</log4j2.version>
<log4j.version>1.2.16</log4j.version>
<slf4j.version>1.7.7</slf4j.version>
I have the thread dump in question ,and
attach it in the attachment.
Thanks you!
------------------------------------------------------------------------
[email protected] <mailto:[email protected]>
*From:* Gary Gregory
<mailto:[email protected]>
*Date:* 2015-07-02 15:57
*To:* Log4J Developers List
<mailto:[email protected]>
*Subject:* Re: Log4j2 RollingFileAppender
deadlock issue
Hello,
What version of Log4j are you using?
Can you post the whole thread dump? You
can capture it from VisualVM (jvisualvm)
which ships with the JDK).
Gary
On Wed, Jul 1, 2015 at 10:36 PM,
[email protected] <mailto:[email protected]>
<[email protected]
<mailto:[email protected]>> wrote:
Hi,log4j developers,
I am using log4j2 to do log. Recently
I have encountered an
RollingFileAppender deadlock issue
from time to time which happens
around 12:00 am ~03:00am.
When I dump the thread, there are
lots of BLOCKED threads that waiting
for the lock 0x00000007a2cecaa0.
Following is my log4j configuration
in log4j2.xml:
<RollingFile name="rolling"
fileName="/data/logs/app/server.log"
filePattern="/data/logs/app/server.log.%d{yyyy-MM-dd}">
<PatternLayout pattern="[%-5level]
[%d{yyyy-MM-dd HH:mm:ss}]
[%C{1}:%M:%L] %m%n" />
<Policies>
<TimeBasedTriggeringPolicy />
</Policies>
<DefaultRolloverStrategy max="30"/>
</RollingFile>
Is this a bug or there is some
misconfiguration in my configuration.
Is there a way that I can work around
this? It happens in our production
environment.
<Catch(07-02-13-3(07-02-17-52-37).jpg>
------------------------------------------------------------------------
[email protected] <mailto:[email protected]>
--
E-Mail: [email protected]
<mailto:[email protected]> |
[email protected]
<mailto:[email protected]>
Java Persistence with Hibernate, Second
Edition <http://www.manning.com/bauer3/>
JUnit in Action, Second Edition
<http://www.manning.com/tahchiev/>
Spring Batch in Action
<http://www.manning.com/templier/>
Blog: http://garygregory.wordpress.com
<http://garygregory.wordpress.com/>
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
提示图标 邮件带有附件预览链接，若您转 发
或回复此邮件时不希望对方预 览附件，建议您
手动删除链接。
共 有 *1* 个附件
Catch(07-02-13-34-56).jpg(1M)
极速下载
<http://preview.mail.163.com/xdownload?filename=Catch%2807-02-13-34-56%29.jpg&mid=xtbBEQQrgVD%2BdaYDbgAAsv&part=3&sign=455fc16698556220f55a79d0de214c25&time=1435824425&uid=bit1129%40163.com>
在线预览
<http://preview.mail.163.com/preview?mid=xtbBEQQrgVD%2BdaYDbgAAsv&part=3&sign=455fc16698556220f55a79d0de214c25&time=1435824425&uid=bit1129%40163.com>
---------------------------------------------------------------------
To unsubscribe, e-mail:
[email protected]
<mailto:[email protected]>
For additional commands, e-mail:
[email protected]
<mailto:[email protected]>
--
E-Mail: [email protected]
<mailto:[email protected]> | [email protected]
<mailto:[email protected]>
Java Persistence with Hibernate, Second Edition
<http://www.manning.com/bauer3/>
JUnit in Action, Second Edition
<http://www.manning.com/tahchiev/>
Spring Batch in Action <http://www.manning.com/templier/>
Blog: http://garygregory.wordpress.com
<http://garygregory.wordpress.com/>
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
提示图标 邮件带有附件预览链接，若您转发或回复此邮件时
不希 望对方预览附件，建议您手动删除链接。
共 有 *1* 个附件
Catch(07-02-13-3(07-02-16-25-44).jpg(1M)
极速下载
<http://preview.mail.163.com/xdownload?filename=Catch%2807-02-13-3%2807-02-16-25-44%29.jpg&mid=1tbiqxUrgVUL5JhKtgAAsK&part=3&sign=23395f9d62f60d2dbad11e39911e54c8&time=1435827868&uid=bit1129%40163.com>
在线预览
<http://preview.mail.163.com/preview?mid=1tbiqxUrgVUL5JhKtgAAsK&part=3&sign=23395f9d62f60d2dbad11e39911e54c8&time=1435827868&uid=bit1129%40163.com>
--
E-Mail: [email protected]
<mailto:[email protected]> | [email protected]
<mailto:[email protected]>
Java Persistence with Hibernate, Second Edition
<http://www.manning.com/bauer3/>
JUnit in Action, Second Edition
<http://www.manning.com/tahchiev/>
Spring Batch in Action <http://www.manning.com/templier/>
Blog: http://garygregory.wordpress.com
<http://garygregory.wordpress.com/>
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
--
E-Mail: [email protected] <mailto:[email protected]> |
[email protected] <mailto:[email protected]>
Java Persistence with Hibernate, Second Edition
<http://www.manning.com/bauer3/>
JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
Spring Batch in Action <http://www.manning.com/templier/>
Blog: http://garygregory.wordpress.com
<http://garygregory.wordpress.com/>
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
提示图标 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预
览附件，建议您手动删除链接。
共有 *1* 个附件
Catch(07-02-13-3(07-02-17-13-37).jpg(1M)
极 速下载
<http://preview.mail.163.com/xdownload?filename=Catch%2807-02-13-3%2807-02-17-13-37%29.jpg&mid=1tbiqwYrgVUL5JjPdwAAsd&part=3&sign=9f422144b7596ead1d7a91185a34196d&time=1435829869&uid=bit1129%40163.com>
在 线预览
<http://preview.mail.163.com/preview?mid=1tbiqwYrgVUL5JjPdwAAsd&part=3&sign=9f422144b7596ead1d7a91185a34196d&time=1435829869&uid=bit1129%40163.com>
