You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "bit1129@163.com" <bi...@163.com> on 2015/07/02 07:36:26 UTC
Log4j2 RollingFileAppender deadlock issue
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.
bit1129@163.com
Re: Re: Log4j2 RollingFileAppender deadlock issue
Posted by Gary Gregory <ga...@gmail.com>.
I would suggest NOT having both Log4j 1 and 2 on the class path at the same
time.
Instead, use the current version of Log4j 2 which is 2.3 and then use the
Log4j 2 1.2 compatibility module log4j-1.2-api.
Gary
On Thu, Jul 2, 2015 at 1:25 AM, bit1129@163.com <bi...@163.com> wrote:
> 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!
>
> ------------------------------
> bit1129@163.com
>
>
> *From:* Gary Gregory <ga...@gmail.com>
> *Date:* 2015-07-02 15:57
> *To:* Log4J Developers List <lo...@logging.apache.org>
> *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, bit1129@163.com <bi...@163.com> 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.
>>
>>
>>
>>
>>
>> ------------------------------
>> bit1129@163.com
>>
>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> 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
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
> 共有 *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: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
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
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Jess Holle <je...@ptc.com>.
So use a separate SimpleDateFormat for each thread ala ThreadLocal.
I've been doing that in a patch to log4j 1.2 for a long time now --
along with moving the formatting out of the sync appender block on a
per-layout-class opt-in basis.
Yes, I should move to log4j 2.x, but I've had these concurrency
bottleneck fixes in place in my patched 1.2 for a long time now and
moving a huge quantity of code and numerous complex custom appenders and
layouts to 2.x is non-trivial.
And, yes, I am aware that ThreadLocals and web app context reload, etc,
use cases do not mix very well. At some point I should patch my 1.2 to
use Java 8 date/time stuff instead of SimpleDateFormat (but right now I
only require Java 6, e.g. for CopyOnWriteArrayList).
On 7/2/2015 7:34 AM, Ralph Goers wrote:
> The date pattern converter will be locking because it uses
> SimpleDateFormat to format the date. This can be changed in Java 8,
> but the only alternative until then is to use the Joda Time library
> and we have been reluctant to be reliant on third party libraries for
> such core components.
>
> Sent from my iPad
>
> On Jul 2, 2015, at 3:44 AM, "bit1129@163.com <ma...@163.com>"
> <bit1129@163.com <ma...@163.com>> wrote:
>
>> 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.
>>
>> ------------------------------------------------------------------------
>> bit1129@163.com <ma...@163.com>
>>
>> *From:* Gary Gregory <ma...@gmail.com>
>> *Date:* 2015-07-02 17:35
>> *To:* Log4J Developers List <ma...@logging.apache.org>
>> *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
>> <garydgregory@gmail.com <ma...@gmail.com>> 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, bit1129@163.com
>> <ma...@163.com> <bit1129@163.com
>> <ma...@163.com>> 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.
>>
>>
>>
>>
>> ------------------------------------------------------------------------
>> bit1129@163.com <ma...@163.com>
>>
>> *From:* Gary Gregory <ma...@gmail.com>
>> *Date:* 2015-07-02 16:55
>> *To:* Log4J Developers List
>> <ma...@logging.apache.org>
>> *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, bit1129@163.com
>> <ma...@163.com> <bit1129@163.com
>> <ma...@163.com>> wrote:
>>
>> Sorry, looks that I forgot to attach the thread
>> dump file.
>>
>> ------------------------------------------------------------------------
>> bit1129@163.com <ma...@163.com>
>>
>> *From:* bit1129@163.com <ma...@163.com>
>> *Date:* 2015-07-02 16:25
>> *To:* log4j-dev
>> <ma...@logging.apache.org>
>> *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!
>>
>> ------------------------------------------------------------------------
>> bit1129@163.com <ma...@163.com>
>>
>> *From:* Gary Gregory
>> <ma...@gmail.com>
>> *Date:* 2015-07-02 15:57
>> *To:* Log4J Developers List
>> <ma...@logging.apache.org>
>> *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,
>> bit1129@163.com <ma...@163.com>
>> <bit1129@163.com
>> <ma...@163.com>> 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>
>>
>>
>>
>>
>> ------------------------------------------------------------------------
>> bit1129@163.com <ma...@163.com>
>>
>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com
>> <ma...@gmail.com> |
>> ggregory@apache.org
>> <ma...@apache.org>
>> 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:
>> log4j-dev-unsubscribe@logging.apache.org
>> <ma...@logging.apache.org>
>> For additional commands, e-mail:
>> log4j-dev-help@logging.apache.org
>> <ma...@logging.apache.org>
>>
>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com
>> <ma...@gmail.com> | ggregory@apache.org
>> <ma...@apache.org>
>> 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: garydgregory@gmail.com
>> <ma...@gmail.com> | ggregory@apache.org
>> <ma...@apache.org>
>> 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: garydgregory@gmail.com <ma...@gmail.com> |
>> ggregory@apache.org <ma...@apache.org>
>> 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>
>>
>>
Re: Re: Log4j2 RollingFileAppender deadlock issue
Posted by "bit1129@163.com" <bi...@163.com>.
Thanks Ralph for the reply. It is ugly that SimpleDateFormat is a not thread safe API.
Since this problem occurs from time to time, I want to ask how to proceed at this point.
bit1129@163.com
From: Ralph Goers
Date: 2015-07-02 20:34
To: Log4J Developers List
Subject: Re: Log4j2 RollingFileAppender deadlock issue
The date pattern converter will be locking because it uses SimpleDateFormat to format the date. This can be changed in Java 8, but the only alternative until then is to use the Joda Time library and we have been reluctant to be reliant on third party libraries for such core components.
Sent from my iPad
On Jul 2, 2015, at 3:44 AM, "bit1129@163.com" <bi...@163.com> wrote:
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.
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 17:35
To: Log4J Developers List
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 <ga...@gmail.com> 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, bit1129@163.com <bi...@163.com> 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.
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 16:55
To: Log4J Developers List
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, bit1129@163.com <bi...@163.com> wrote:
Sorry, looks that I forgot to attach the thread dump file.
bit1129@163.com
From: bit1129@163.com
Date: 2015-07-02 16:25
To: log4j-dev
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!
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 15:57
To: Log4J Developers List
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, bit1129@163.com <bi...@163.com> 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>
bit1129@163.com
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
共有 1 个附件
Catch(07-02-13-34-56).jpg(1M) 极速下载 在线预览
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: 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) 极速下载 在线预览
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: 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) 极速下载 在线预览
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Remko Popma <re...@gmail.com>.
ThreadLocal is implemented as an internal Map in each Thread instance, so there is constant lookup time regardless of the number of Threads and the number of lookups. Contrast this with a lock, where performance will decrease exponentially with more concurrent threads.
(See also https://plumbr.eu/blog/java/how-is-threadlocal-implemented )
Sent from my iPhone
> On 2015/07/04, at 20:40, Jess Holle <je...@ptc.com> wrote:
>
>> On 7/4/2015 2:51 AM, Gary Gregory wrote:
>> On Thu, Jul 2, 2015 at 6:18 AM, Remko Popma <re...@gmail.com> wrote:
>>> Yes, that could still work: We could use a ThreadLocal containing a custom class which holds the lastTimestamp, cachedDateString as well as a SimpleDateFormat instance.
>>>
>>> As Jess pointed out, we would also need a way to clear the ThreadLocal when the LoggerContext is stopped (to prevent memory leaks in web apps). This may be the third usage of ThreadLocals in log4j2 now, so it may be worth creating a reusable mechanism for this.
>>> One idea would be to have a ThreadLocal registry in the LoggerContext, where the LoggerContext is responsible for cleaning up all registered ThreadLocals in its stop() method.
>>>
>>> Thoughts?
>>
>> I'm wondering what the performance cost are of doing a ThreadLocal.get() vs. synchronized(this) on each call to format().
> Personally I'd be less concerned with optimizing maximum logger throughput on any given thread than:
> Ensuring that not logging takes minimal time
> Minimizing potential thread contention
> Logging at maximum efficiency is a priority, but comes after these others.
> --
> Jess Holle
>
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Jess Holle <je...@ptc.com>.
On 7/4/2015 2:51 AM, Gary Gregory wrote:
> On Thu, Jul 2, 2015 at 6:18 AM, Remko Popma <remko.popma@gmail.com
> <ma...@gmail.com>> wrote:
>
> Yes, that could still work: We could use a ThreadLocal containing
> a custom class which holds the lastTimestamp, cachedDateString as
> well as a SimpleDateFormat instance.
>
> As Jess pointed out, we would also need a way to clear the
> ThreadLocal when the LoggerContext is stopped (to prevent memory
> leaks in web apps). This may be the third usage of ThreadLocals in
> log4j2 now, so it may be worth creating a reusable mechanism for
> this.
> One idea would be to have a ThreadLocal registry in the
> LoggerContext, where the LoggerContext is responsible for cleaning
> up all registered ThreadLocals in its stop() method.
>
> Thoughts?
>
>
> I'm wondering what the performance cost are of doing a
> ThreadLocal.get() vs. synchronized(this) on each call to format().
>
Personally I'd be less concerned with optimizing maximum logger
throughput on any given thread than:
1. Ensuring that /not/ logging takes minimal time
2. Minimizing potential thread contention
Logging at maximum efficiency is a priority, but comes after these others.
--
Jess Holle
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Gary Gregory <ga...@gmail.com>.
On Thu, Jul 2, 2015 at 6:18 AM, Remko Popma <re...@gmail.com> wrote:
> Yes, that could still work: We could use a ThreadLocal containing a custom
> class which holds the lastTimestamp, cachedDateString as well as a
> SimpleDateFormat instance.
>
> As Jess pointed out, we would also need a way to clear the ThreadLocal
> when the LoggerContext is stopped (to prevent memory leaks in web apps).
> This may be the third usage of ThreadLocals in log4j2 now, so it may be
> worth creating a reusable mechanism for this.
> One idea would be to have a ThreadLocal registry in the LoggerContext,
> where the LoggerContext is responsible for cleaning up all registered
> ThreadLocals in its stop() method.
>
> Thoughts?
>
I'm wondering what the performance cost are of doing a ThreadLocal.get()
vs. synchronized(this) on each call to format().
Gary
>
> Remko..
> Sent from my iPhone
>
> On 2015/07/02, at 22:00, Gary Gregory <ga...@gmail.com> wrote:
>
> What about storing a SimpleDateFormat in a ThreadLocal?
>
> But, more importantly and aside from SimpleDateFormat not being
> thread-safe [1], I thought we used synchronized to keep
> the lastTimestamp and cachedDateString ivar perfectly matched up:
>
> public void format(final LogEvent event, final StringBuilder output) {
> final long timestamp = event.getTimeMillis();
>
> synchronized (this) {
> if (timestamp != lastTimestamp) {
> lastTimestamp = timestamp;
> cachedDateString = formatter.format(timestamp);
> }
> }
> output.append(cachedDateString);
> }
>
> But #2, lastTimestamp and cachedDateString are not volatile, so do we
> really care?
>
> Gary
>
> [1] Javadoc: Date formats are not synchronized.
> * It is recommended to create separate format instances for each thread.
> * If multiple threads access a format concurrently, it must be
> synchronized
> * externally.
>
>
> On Thu, Jul 2, 2015 at 5:34 AM, Ralph Goers <ra...@dslextreme.com>
> wrote:
>
>> The date pattern converter will be locking because it uses
>> SimpleDateFormat to format the date. This can be changed in Java 8, but
>> the only alternative until then is to use the Joda Time library and we have
>> been reluctant to be reliant on third party libraries for such core
>> components.
>>
>> Sent from my iPad
>>
>> On Jul 2, 2015, at 3:44 AM, "bit1129@163.com" <bi...@163.com> wrote:
>>
>> 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.
>>
>> ------------------------------
>> bit1129@163.com
>>
>>
>> *From:* Gary Gregory <ga...@gmail.com>
>> *Date:* 2015-07-02 17:35
>> *To:* Log4J Developers List <lo...@logging.apache.org>
>> *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 <ga...@gmail.com>
>> 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, bit1129@163.com <bi...@163.com> 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.
>>>>
>>>>
>>>>
>>>>
>>>> ------------------------------
>>>> bit1129@163.com
>>>>
>>>>
>>>> *From:* Gary Gregory <ga...@gmail.com>
>>>> *Date:* 2015-07-02 16:55
>>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>>> *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, bit1129@163.com <bi...@163.com>
>>>> wrote:
>>>>
>>>>> Sorry, looks that I forgot to attach the thread dump file.
>>>>>
>>>>> ------------------------------
>>>>> bit1129@163.com
>>>>>
>>>>>
>>>>> *From:* bit1129@163.com
>>>>> *Date:* 2015-07-02 16:25
>>>>> *To:* log4j-dev <lo...@logging.apache.org>
>>>>> *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!
>>>>>
>>>>> ------------------------------
>>>>> bit1129@163.com
>>>>>
>>>>>
>>>>> *From:* Gary Gregory <ga...@gmail.com>
>>>>> *Date:* 2015-07-02 15:57
>>>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>>>> *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, bit1129@163.com <bi...@163.com>
>>>>> 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>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> ------------------------------
>>>>>> bit1129@163.com
>>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>> 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
>>>>> Home: http://garygregory.com/
>>>>> Tweet! http://twitter.com/GaryGregory
>>>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>>> 共有 *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: log4j-dev-unsubscribe@logging.apache.org
>>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>>>
>>>>
>>>>
>>>>
>>>> --
>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>> 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
>>>> Home: http://garygregory.com/
>>>> Tweet! http://twitter.com/GaryGregory
>>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>> 共有 *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: garydgregory@gmail.com | ggregory@apache.org
>>> 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
>>> Home: http://garygregory.com/
>>> Tweet! http://twitter.com/GaryGregory
>>>
>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>> 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
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>> 共有 *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>
>>
>>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> 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
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
>
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
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
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Remko Popma <re...@gmail.com>.
I would prefer a solution that is reusable for all ThreadLocals, not just the one we are considering putting in PatternConverter.
Are there any drawbacks with the registry idea?
Sent from my iPhone
> On 2015/07/04, at 16:45, Gary Gregory <ga...@gmail.com> wrote:
>
> So the simplest thing to so would for PatternConverter to implement a stop() method to clear the ThreadLocal (extending AbstractLifeCycle might be too heavy for now)
>
> The tricky part is how to connect the dots from an appender stopping all the way to the PatternConverter. Unless we go the route of the registry.
>
> Gary
>
>> On Thu, Jul 2, 2015 at 10:34 AM, Gary Gregory <ga...@gmail.com> wrote:
>> Or the org.apache.logging.log4j.core.pattern.AbstractPatternConverter could extend org.apache.logging.log4j.core.AbstractLifeCycle and clearing the ThreadLocale would be done in stop(). The stop would have to be called at the right time of course.
>>
>> Gary
>>
>>> On Thu, Jul 2, 2015 at 6:18 AM, Remko Popma <re...@gmail.com> wrote:
>>> Yes, that could still work: We could use a ThreadLocal containing a custom class which holds the lastTimestamp, cachedDateString as well as a SimpleDateFormat instance.
>>>
>>> As Jess pointed out, we would also need a way to clear the ThreadLocal when the LoggerContext is stopped (to prevent memory leaks in web apps). This may be the third usage of ThreadLocals in log4j2 now, so it may be worth creating a reusable mechanism for this.
>>> One idea would be to have a ThreadLocal registry in the LoggerContext, where the LoggerContext is responsible for cleaning up all registered ThreadLocals in its stop() method.
>>>
>>> Thoughts?
>>>
>>> Remko..
>>> Sent from my iPhone
>>>
>>>> On 2015/07/02, at 22:00, Gary Gregory <ga...@gmail.com> wrote:
>>>>
>>>> What about storing a SimpleDateFormat in a ThreadLocal?
>>>>
>>>> But, more importantly and aside from SimpleDateFormat not being thread-safe [1], I thought we used synchronized to keep the lastTimestamp and cachedDateString ivar perfectly matched up:
>>>>
>>>> public void format(final LogEvent event, final StringBuilder output) {
>>>> final long timestamp = event.getTimeMillis();
>>>>
>>>> synchronized (this) {
>>>> if (timestamp != lastTimestamp) {
>>>> lastTimestamp = timestamp;
>>>> cachedDateString = formatter.format(timestamp);
>>>> }
>>>> }
>>>> output.append(cachedDateString);
>>>> }
>>>>
>>>> But #2, lastTimestamp and cachedDateString are not volatile, so do we really care?
>>>>
>>>> Gary
>>>>
>>>> [1] Javadoc: Date formats are not synchronized.
>>>> * It is recommended to create separate format instances for each thread.
>>>> * If multiple threads access a format concurrently, it must be synchronized
>>>> * externally.
>>>>
>>>>
>>>>> On Thu, Jul 2, 2015 at 5:34 AM, Ralph Goers <ra...@dslextreme.com> wrote:
>>>>> The date pattern converter will be locking because it uses SimpleDateFormat to format the date. This can be changed in Java 8, but the only alternative until then is to use the Joda Time library and we have been reluctant to be reliant on third party libraries for such core components.
>>>>>
>>>>> Sent from my iPad
>>>>>
>>>>>> On Jul 2, 2015, at 3:44 AM, "bit1129@163.com" <bi...@163.com> wrote:
>>>>>>
>>>>>> 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.
>>>>>>
>>>>>> bit1129@163.com
>>>>>>
>>>>>> From: Gary Gregory
>>>>>> Date: 2015-07-02 17:35
>>>>>> To: Log4J Developers List
>>>>>> 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 <ga...@gmail.com> 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, bit1129@163.com <bi...@163.com> 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.
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> bit1129@163.com
>>>>>>>>
>>>>>>>> From: Gary Gregory
>>>>>>>> Date: 2015-07-02 16:55
>>>>>>>> To: Log4J Developers List
>>>>>>>> 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, bit1129@163.com <bi...@163.com> wrote:
>>>>>>>>> Sorry, looks that I forgot to attach the thread dump file.
>>>>>>>>>
>>>>>>>>> bit1129@163.com
>>>>>>>>>
>>>>>>>>> From: bit1129@163.com
>>>>>>>>> Date: 2015-07-02 16:25
>>>>>>>>> To: log4j-dev
>>>>>>>>> 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!
>>>>>>>>>
>>>>>>>>> bit1129@163.com
>>>>>>>>>
>>>>>>>>> From: Gary Gregory
>>>>>>>>> Date: 2015-07-02 15:57
>>>>>>>>> To: Log4J Developers List
>>>>>>>>> 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, bit1129@163.com <bi...@163.com> 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>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> bit1129@163.com
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> --
>>>>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>>>>> JUnit in Action, Second Edition
>>>>>>>>> Spring Batch in Action
>>>>>>>>> Blog: http://garygregory.wordpress.com
>>>>>>>>> Home: http://garygregory.com/
>>>>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>>>>> 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>>>>>>> 共有 1 个附件
>>>>>>>>> Catch(07-02-13-34-56).jpg(1M)
>>>>>>>>> 极速下载 在线预览
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> ---------------------------------------------------------------------
>>>>>>>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>>>>>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> --
>>>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>>>> JUnit in Action, Second Edition
>>>>>>>> Spring Batch in Action
>>>>>>>> Blog: 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)
>>>>>>>> 极速下载 在线预览
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> --
>>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>>> JUnit in Action, Second Edition
>>>>>>> Spring Batch in Action
>>>>>>> Blog: http://garygregory.wordpress.com
>>>>>>> Home: http://garygregory.com/
>>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> --
>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>> JUnit in Action, Second Edition
>>>>>> Spring Batch in Action
>>>>>> Blog: 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)
>>>>>> 极速下载 在线预览
>>>>
>>>>
>>>>
>>>> --
>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>> Java Persistence with Hibernate, Second Edition
>>>> JUnit in Action, Second Edition
>>>> Spring Batch in Action
>>>> Blog: http://garygregory.wordpress.com
>>>> Home: http://garygregory.com/
>>>> Tweet! http://twitter.com/GaryGregory
>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>> Java Persistence with Hibernate, Second Edition
>> JUnit in Action, Second Edition
>> Spring Batch in Action
>> Blog: http://garygregory.wordpress.com
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> Java Persistence with Hibernate, Second Edition
> JUnit in Action, Second Edition
> Spring Batch in Action
> Blog: http://garygregory.wordpress.com
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Gary Gregory <ga...@gmail.com>.
So the simplest thing to so would for PatternConverter to implement a
stop() method to clear the ThreadLocal (extending AbstractLifeCycle might
be too heavy for now)
The tricky part is how to connect the dots from an appender stopping all
the way to the PatternConverter. Unless we go the route of the registry.
Gary
On Thu, Jul 2, 2015 at 10:34 AM, Gary Gregory <ga...@gmail.com>
wrote:
> Or the org.apache.logging.log4j.core.pattern.AbstractPatternConverter
> could extend org.apache.logging.log4j.core.AbstractLifeCycle and clearing
> the ThreadLocale would be done in stop(). The stop would have to be called
> at the right time of course.
>
> Gary
>
> On Thu, Jul 2, 2015 at 6:18 AM, Remko Popma <re...@gmail.com> wrote:
>
>> Yes, that could still work: We could use a ThreadLocal containing a
>> custom class which holds the lastTimestamp, cachedDateString as well as a
>> SimpleDateFormat instance.
>>
>> As Jess pointed out, we would also need a way to clear the ThreadLocal
>> when the LoggerContext is stopped (to prevent memory leaks in web apps).
>> This may be the third usage of ThreadLocals in log4j2 now, so it may be
>> worth creating a reusable mechanism for this.
>> One idea would be to have a ThreadLocal registry in the LoggerContext,
>> where the LoggerContext is responsible for cleaning up all registered
>> ThreadLocals in its stop() method.
>>
>> Thoughts?
>>
>> Remko..
>> Sent from my iPhone
>>
>> On 2015/07/02, at 22:00, Gary Gregory <ga...@gmail.com> wrote:
>>
>> What about storing a SimpleDateFormat in a ThreadLocal?
>>
>> But, more importantly and aside from SimpleDateFormat not being
>> thread-safe [1], I thought we used synchronized to keep
>> the lastTimestamp and cachedDateString ivar perfectly matched up:
>>
>> public void format(final LogEvent event, final StringBuilder output) {
>> final long timestamp = event.getTimeMillis();
>>
>> synchronized (this) {
>> if (timestamp != lastTimestamp) {
>> lastTimestamp = timestamp;
>> cachedDateString = formatter.format(timestamp);
>> }
>> }
>> output.append(cachedDateString);
>> }
>>
>> But #2, lastTimestamp and cachedDateString are not volatile, so do we
>> really care?
>>
>> Gary
>>
>> [1] Javadoc: Date formats are not synchronized.
>> * It is recommended to create separate format instances for each thread.
>> * If multiple threads access a format concurrently, it must be
>> synchronized
>> * externally.
>>
>>
>> On Thu, Jul 2, 2015 at 5:34 AM, Ralph Goers <ra...@dslextreme.com>
>> wrote:
>>
>>> The date pattern converter will be locking because it uses
>>> SimpleDateFormat to format the date. This can be changed in Java 8, but
>>> the only alternative until then is to use the Joda Time library and we have
>>> been reluctant to be reliant on third party libraries for such core
>>> components.
>>>
>>> Sent from my iPad
>>>
>>> On Jul 2, 2015, at 3:44 AM, "bit1129@163.com" <bi...@163.com> wrote:
>>>
>>> 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.
>>>
>>> ------------------------------
>>> bit1129@163.com
>>>
>>>
>>> *From:* Gary Gregory <ga...@gmail.com>
>>> *Date:* 2015-07-02 17:35
>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>> *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 <ga...@gmail.com>
>>> 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, bit1129@163.com <bi...@163.com>
>>>> 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.
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> ------------------------------
>>>>> bit1129@163.com
>>>>>
>>>>>
>>>>> *From:* Gary Gregory <ga...@gmail.com>
>>>>> *Date:* 2015-07-02 16:55
>>>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>>>> *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, bit1129@163.com <bi...@163.com>
>>>>> wrote:
>>>>>
>>>>>> Sorry, looks that I forgot to attach the thread dump file.
>>>>>>
>>>>>> ------------------------------
>>>>>> bit1129@163.com
>>>>>>
>>>>>>
>>>>>> *From:* bit1129@163.com
>>>>>> *Date:* 2015-07-02 16:25
>>>>>> *To:* log4j-dev <lo...@logging.apache.org>
>>>>>> *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!
>>>>>>
>>>>>> ------------------------------
>>>>>> bit1129@163.com
>>>>>>
>>>>>>
>>>>>> *From:* Gary Gregory <ga...@gmail.com>
>>>>>> *Date:* 2015-07-02 15:57
>>>>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>>>>> *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, bit1129@163.com <bi...@163.com>
>>>>>> 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>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> ------------------------------
>>>>>>> bit1129@163.com
>>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> --
>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>> 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
>>>>>> Home: http://garygregory.com/
>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>>>> 共有 *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: log4j-dev-unsubscribe@logging.apache.org
>>>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>> 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
>>>>> Home: http://garygregory.com/
>>>>> Tweet! http://twitter.com/GaryGregory
>>>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>>> 共有 *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: garydgregory@gmail.com | ggregory@apache.org
>>>> 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
>>>> Home: http://garygregory.com/
>>>> Tweet! http://twitter.com/GaryGregory
>>>>
>>>
>>>
>>>
>>> --
>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>> 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
>>> Home: http://garygregory.com/
>>> Tweet! http://twitter.com/GaryGregory
>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>> 共有 *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>
>>>
>>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>> 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
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>>
>>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> 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
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
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
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Gary Gregory <ga...@gmail.com>.
Or the org.apache.logging.log4j.core.pattern.AbstractPatternConverter could
extend org.apache.logging.log4j.core.AbstractLifeCycle and clearing the
ThreadLocale would be done in stop(). The stop would have to be called at
the right time of course.
Gary
On Thu, Jul 2, 2015 at 6:18 AM, Remko Popma <re...@gmail.com> wrote:
> Yes, that could still work: We could use a ThreadLocal containing a custom
> class which holds the lastTimestamp, cachedDateString as well as a
> SimpleDateFormat instance.
>
> As Jess pointed out, we would also need a way to clear the ThreadLocal
> when the LoggerContext is stopped (to prevent memory leaks in web apps).
> This may be the third usage of ThreadLocals in log4j2 now, so it may be
> worth creating a reusable mechanism for this.
> One idea would be to have a ThreadLocal registry in the LoggerContext,
> where the LoggerContext is responsible for cleaning up all registered
> ThreadLocals in its stop() method.
>
> Thoughts?
>
> Remko..
> Sent from my iPhone
>
> On 2015/07/02, at 22:00, Gary Gregory <ga...@gmail.com> wrote:
>
> What about storing a SimpleDateFormat in a ThreadLocal?
>
> But, more importantly and aside from SimpleDateFormat not being
> thread-safe [1], I thought we used synchronized to keep
> the lastTimestamp and cachedDateString ivar perfectly matched up:
>
> public void format(final LogEvent event, final StringBuilder output) {
> final long timestamp = event.getTimeMillis();
>
> synchronized (this) {
> if (timestamp != lastTimestamp) {
> lastTimestamp = timestamp;
> cachedDateString = formatter.format(timestamp);
> }
> }
> output.append(cachedDateString);
> }
>
> But #2, lastTimestamp and cachedDateString are not volatile, so do we
> really care?
>
> Gary
>
> [1] Javadoc: Date formats are not synchronized.
> * It is recommended to create separate format instances for each thread.
> * If multiple threads access a format concurrently, it must be
> synchronized
> * externally.
>
>
> On Thu, Jul 2, 2015 at 5:34 AM, Ralph Goers <ra...@dslextreme.com>
> wrote:
>
>> The date pattern converter will be locking because it uses
>> SimpleDateFormat to format the date. This can be changed in Java 8, but
>> the only alternative until then is to use the Joda Time library and we have
>> been reluctant to be reliant on third party libraries for such core
>> components.
>>
>> Sent from my iPad
>>
>> On Jul 2, 2015, at 3:44 AM, "bit1129@163.com" <bi...@163.com> wrote:
>>
>> 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.
>>
>> ------------------------------
>> bit1129@163.com
>>
>>
>> *From:* Gary Gregory <ga...@gmail.com>
>> *Date:* 2015-07-02 17:35
>> *To:* Log4J Developers List <lo...@logging.apache.org>
>> *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 <ga...@gmail.com>
>> 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, bit1129@163.com <bi...@163.com> 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.
>>>>
>>>>
>>>>
>>>>
>>>> ------------------------------
>>>> bit1129@163.com
>>>>
>>>>
>>>> *From:* Gary Gregory <ga...@gmail.com>
>>>> *Date:* 2015-07-02 16:55
>>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>>> *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, bit1129@163.com <bi...@163.com>
>>>> wrote:
>>>>
>>>>> Sorry, looks that I forgot to attach the thread dump file.
>>>>>
>>>>> ------------------------------
>>>>> bit1129@163.com
>>>>>
>>>>>
>>>>> *From:* bit1129@163.com
>>>>> *Date:* 2015-07-02 16:25
>>>>> *To:* log4j-dev <lo...@logging.apache.org>
>>>>> *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!
>>>>>
>>>>> ------------------------------
>>>>> bit1129@163.com
>>>>>
>>>>>
>>>>> *From:* Gary Gregory <ga...@gmail.com>
>>>>> *Date:* 2015-07-02 15:57
>>>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>>>> *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, bit1129@163.com <bi...@163.com>
>>>>> 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>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> ------------------------------
>>>>>> bit1129@163.com
>>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>> 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
>>>>> Home: http://garygregory.com/
>>>>> Tweet! http://twitter.com/GaryGregory
>>>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>>> 共有 *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: log4j-dev-unsubscribe@logging.apache.org
>>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>>>
>>>>
>>>>
>>>>
>>>> --
>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>> 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
>>>> Home: http://garygregory.com/
>>>> Tweet! http://twitter.com/GaryGregory
>>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>> 共有 *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: garydgregory@gmail.com | ggregory@apache.org
>>> 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
>>> Home: http://garygregory.com/
>>> Tweet! http://twitter.com/GaryGregory
>>>
>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>> 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
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>> 共有 *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>
>>
>>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> 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
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
>
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
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
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Remko Popma <re...@gmail.com>.
Yes, that could still work: We could use a ThreadLocal containing a custom class which holds the lastTimestamp, cachedDateString as well as a SimpleDateFormat instance.
As Jess pointed out, we would also need a way to clear the ThreadLocal when the LoggerContext is stopped (to prevent memory leaks in web apps). This may be the third usage of ThreadLocals in log4j2 now, so it may be worth creating a reusable mechanism for this.
One idea would be to have a ThreadLocal registry in the LoggerContext, where the LoggerContext is responsible for cleaning up all registered ThreadLocals in its stop() method.
Thoughts?
Remko..
Sent from my iPhone
> On 2015/07/02, at 22:00, Gary Gregory <ga...@gmail.com> wrote:
>
> What about storing a SimpleDateFormat in a ThreadLocal?
>
> But, more importantly and aside from SimpleDateFormat not being thread-safe [1], I thought we used synchronized to keep the lastTimestamp and cachedDateString ivar perfectly matched up:
>
> public void format(final LogEvent event, final StringBuilder output) {
> final long timestamp = event.getTimeMillis();
>
> synchronized (this) {
> if (timestamp != lastTimestamp) {
> lastTimestamp = timestamp;
> cachedDateString = formatter.format(timestamp);
> }
> }
> output.append(cachedDateString);
> }
>
> But #2, lastTimestamp and cachedDateString are not volatile, so do we really care?
>
> Gary
>
> [1] Javadoc: Date formats are not synchronized.
> * It is recommended to create separate format instances for each thread.
> * If multiple threads access a format concurrently, it must be synchronized
> * externally.
>
>
>> On Thu, Jul 2, 2015 at 5:34 AM, Ralph Goers <ra...@dslextreme.com> wrote:
>> The date pattern converter will be locking because it uses SimpleDateFormat to format the date. This can be changed in Java 8, but the only alternative until then is to use the Joda Time library and we have been reluctant to be reliant on third party libraries for such core components.
>>
>> Sent from my iPad
>>
>>> On Jul 2, 2015, at 3:44 AM, "bit1129@163.com" <bi...@163.com> wrote:
>>>
>>> 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.
>>>
>>> bit1129@163.com
>>>
>>> From: Gary Gregory
>>> Date: 2015-07-02 17:35
>>> To: Log4J Developers List
>>> 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 <ga...@gmail.com> 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, bit1129@163.com <bi...@163.com> 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.
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> bit1129@163.com
>>>>>
>>>>> From: Gary Gregory
>>>>> Date: 2015-07-02 16:55
>>>>> To: Log4J Developers List
>>>>> 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, bit1129@163.com <bi...@163.com> wrote:
>>>>>> Sorry, looks that I forgot to attach the thread dump file.
>>>>>>
>>>>>> bit1129@163.com
>>>>>>
>>>>>> From: bit1129@163.com
>>>>>> Date: 2015-07-02 16:25
>>>>>> To: log4j-dev
>>>>>> 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!
>>>>>>
>>>>>> bit1129@163.com
>>>>>>
>>>>>> From: Gary Gregory
>>>>>> Date: 2015-07-02 15:57
>>>>>> To: Log4J Developers List
>>>>>> 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, bit1129@163.com <bi...@163.com> 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>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> bit1129@163.com
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> --
>>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>>> Java Persistence with Hibernate, Second Edition
>>>>>> JUnit in Action, Second Edition
>>>>>> Spring Batch in Action
>>>>>> Blog: http://garygregory.wordpress.com
>>>>>> Home: http://garygregory.com/
>>>>>> Tweet! http://twitter.com/GaryGregory
>>>>>> 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>>>> 共有 1 个附件
>>>>>> Catch(07-02-13-34-56).jpg(1M)
>>>>>> 极速下载 在线预览
>>>>>>
>>>>>>
>>>>>> ---------------------------------------------------------------------
>>>>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>>> Java Persistence with Hibernate, Second Edition
>>>>> JUnit in Action, Second Edition
>>>>> Spring Batch in Action
>>>>> Blog: 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)
>>>>> 极速下载 在线预览
>>>>
>>>>
>>>>
>>>>
>>>> --
>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>> Java Persistence with Hibernate, Second Edition
>>>> JUnit in Action, Second Edition
>>>> Spring Batch in Action
>>>> Blog: http://garygregory.wordpress.com
>>>> Home: http://garygregory.com/
>>>> Tweet! http://twitter.com/GaryGregory
>>>
>>>
>>>
>>>
>>> --
>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>> Java Persistence with Hibernate, Second Edition
>>> JUnit in Action, Second Edition
>>> Spring Batch in Action
>>> Blog: 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)
>>> 极速下载 在线预览
>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> Java Persistence with Hibernate, Second Edition
> JUnit in Action, Second Edition
> Spring Batch in Action
> Blog: http://garygregory.wordpress.com
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Gary Gregory <ga...@gmail.com>.
What about storing a SimpleDateFormat in a ThreadLocal?
But, more importantly and aside from SimpleDateFormat not being thread-safe
[1], I thought we used synchronized to keep
the lastTimestamp and cachedDateString ivar perfectly matched up:
public void format(final LogEvent event, final StringBuilder output) {
final long timestamp = event.getTimeMillis();
synchronized (this) {
if (timestamp != lastTimestamp) {
lastTimestamp = timestamp;
cachedDateString = formatter.format(timestamp);
}
}
output.append(cachedDateString);
}
But #2, lastTimestamp and cachedDateString are not volatile, so do we
really care?
Gary
[1] Javadoc: Date formats are not synchronized.
* It is recommended to create separate format instances for each thread.
* If multiple threads access a format concurrently, it must be synchronized
* externally.
On Thu, Jul 2, 2015 at 5:34 AM, Ralph Goers <ra...@dslextreme.com>
wrote:
> The date pattern converter will be locking because it uses
> SimpleDateFormat to format the date. This can be changed in Java 8, but
> the only alternative until then is to use the Joda Time library and we have
> been reluctant to be reliant on third party libraries for such core
> components.
>
> Sent from my iPad
>
> On Jul 2, 2015, at 3:44 AM, "bit1129@163.com" <bi...@163.com> wrote:
>
> 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.
>
> ------------------------------
> bit1129@163.com
>
>
> *From:* Gary Gregory <ga...@gmail.com>
> *Date:* 2015-07-02 17:35
> *To:* Log4J Developers List <lo...@logging.apache.org>
> *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 <ga...@gmail.com>
> 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, bit1129@163.com <bi...@163.com> 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.
>>>
>>>
>>>
>>>
>>> ------------------------------
>>> bit1129@163.com
>>>
>>>
>>> *From:* Gary Gregory <ga...@gmail.com>
>>> *Date:* 2015-07-02 16:55
>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>> *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, bit1129@163.com <bi...@163.com> wrote:
>>>
>>>> Sorry, looks that I forgot to attach the thread dump file.
>>>>
>>>> ------------------------------
>>>> bit1129@163.com
>>>>
>>>>
>>>> *From:* bit1129@163.com
>>>> *Date:* 2015-07-02 16:25
>>>> *To:* log4j-dev <lo...@logging.apache.org>
>>>> *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!
>>>>
>>>> ------------------------------
>>>> bit1129@163.com
>>>>
>>>>
>>>> *From:* Gary Gregory <ga...@gmail.com>
>>>> *Date:* 2015-07-02 15:57
>>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>>> *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, bit1129@163.com <bi...@163.com>
>>>> 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>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> ------------------------------
>>>>> bit1129@163.com
>>>>>
>>>>
>>>>
>>>>
>>>> --
>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>> 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
>>>> Home: http://garygregory.com/
>>>> Tweet! http://twitter.com/GaryGregory
>>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>> 共有 *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: log4j-dev-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>>
>>>
>>>
>>>
>>> --
>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>> 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
>>> Home: http://garygregory.com/
>>> Tweet! http://twitter.com/GaryGregory
>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>> 共有 *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: garydgregory@gmail.com | ggregory@apache.org
>> 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
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>>
>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> 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
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
> 共有 *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>
>
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
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
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Ralph Goers <ra...@dslextreme.com>.
The date pattern converter will be locking because it uses SimpleDateFormat to format the date. This can be changed in Java 8, but the only alternative until then is to use the Joda Time library and we have been reluctant to be reliant on third party libraries for such core components.
Sent from my iPad
> On Jul 2, 2015, at 3:44 AM, "bit1129@163.com" <bi...@163.com> wrote:
>
> 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.
>
> bit1129@163.com
>
> From: Gary Gregory
> Date: 2015-07-02 17:35
> To: Log4J Developers List
> 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 <ga...@gmail.com> 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, bit1129@163.com <bi...@163.com> 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.
>>>
>>>
>>>
>>>
>>> bit1129@163.com
>>>
>>> From: Gary Gregory
>>> Date: 2015-07-02 16:55
>>> To: Log4J Developers List
>>> 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, bit1129@163.com <bi...@163.com> wrote:
>>>> Sorry, looks that I forgot to attach the thread dump file.
>>>>
>>>> bit1129@163.com
>>>>
>>>> From: bit1129@163.com
>>>> Date: 2015-07-02 16:25
>>>> To: log4j-dev
>>>> 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!
>>>>
>>>> bit1129@163.com
>>>>
>>>> From: Gary Gregory
>>>> Date: 2015-07-02 15:57
>>>> To: Log4J Developers List
>>>> 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, bit1129@163.com <bi...@163.com> 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>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> bit1129@163.com
>>>>
>>>>
>>>>
>>>> --
>>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>>> Java Persistence with Hibernate, Second Edition
>>>> JUnit in Action, Second Edition
>>>> Spring Batch in Action
>>>> Blog: http://garygregory.wordpress.com
>>>> Home: http://garygregory.com/
>>>> Tweet! http://twitter.com/GaryGregory
>>>> 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>>> 共有 1 个附件
>>>> Catch(07-02-13-34-56).jpg(1M)
>>>> 极速下载 在线预览
>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>
>>>
>>>
>>> --
>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>> Java Persistence with Hibernate, Second Edition
>>> JUnit in Action, Second Edition
>>> Spring Batch in Action
>>> Blog: 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)
>>> 极速下载 在线预览
>>
>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>> Java Persistence with Hibernate, Second Edition
>> JUnit in Action, Second Edition
>> Spring Batch in Action
>> Blog: http://garygregory.wordpress.com
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> Java Persistence with Hibernate, Second Edition
> JUnit in Action, Second Edition
> Spring Batch in Action
> Blog: 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)
> 极速下载 在线预览
Re: Re: Log4j2 RollingFileAppender deadlock issue
Posted by "bit1129@163.com" <bi...@163.com>.
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.
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 17:35
To: Log4J Developers List
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 <ga...@gmail.com> 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, bit1129@163.com <bi...@163.com> 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.
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 16:55
To: Log4J Developers List
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, bit1129@163.com <bi...@163.com> wrote:
Sorry, looks that I forgot to attach the thread dump file.
bit1129@163.com
From: bit1129@163.com
Date: 2015-07-02 16:25
To: log4j-dev
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!
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 15:57
To: Log4J Developers List
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, bit1129@163.com <bi...@163.com> 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.
bit1129@163.com
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
共有 1 个附件
Catch(07-02-13-34-56).jpg(1M) 极速下载 在线预览
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: 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) 极速下载 在线预览
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: 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) 极速下载 在线预览
Re: Re: Log4j2 RollingFileAppender deadlock issue
Posted by Gary Gregory <ga...@gmail.com>.
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 <ga...@gmail.com> 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 deterioration in service.
>
> Gary
>
> On Thu, Jul 2, 2015 at 2:25 AM, bit1129@163.com <bi...@163.com> 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.
>>
>>
>>
>>
>> ------------------------------
>> bit1129@163.com
>>
>>
>> *From:* Gary Gregory <ga...@gmail.com>
>> *Date:* 2015-07-02 16:55
>> *To:* Log4J Developers List <lo...@logging.apache.org>
>> *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, bit1129@163.com <bi...@163.com> wrote:
>>
>>> Sorry, looks that I forgot to attach the thread dump file.
>>>
>>> ------------------------------
>>> bit1129@163.com
>>>
>>>
>>> *From:* bit1129@163.com
>>> *Date:* 2015-07-02 16:25
>>> *To:* log4j-dev <lo...@logging.apache.org>
>>> *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!
>>>
>>> ------------------------------
>>> bit1129@163.com
>>>
>>>
>>> *From:* Gary Gregory <ga...@gmail.com>
>>> *Date:* 2015-07-02 15:57
>>> *To:* Log4J Developers List <lo...@logging.apache.org>
>>> *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, bit1129@163.com <bi...@163.com>
>>> 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.
>>>>
>>>>
>>>>
>>>>
>>>>
>>>> ------------------------------
>>>> bit1129@163.com
>>>>
>>>
>>>
>>>
>>> --
>>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>>> 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
>>> Home: http://garygregory.com/
>>> Tweet! http://twitter.com/GaryGregory
>>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>>> 共有 *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: log4j-dev-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>>
>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>> 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
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>> 共有 *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: garydgregory@gmail.com | ggregory@apache.org
> 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
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
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
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Re: Log4j2 RollingFileAppender deadlock issue
Posted by Gary Gregory <ga...@gmail.com>.
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 deterioration in service.
Gary
On Thu, Jul 2, 2015 at 2:25 AM, bit1129@163.com <bi...@163.com> 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.
>
>
>
>
> ------------------------------
> bit1129@163.com
>
>
> *From:* Gary Gregory <ga...@gmail.com>
> *Date:* 2015-07-02 16:55
> *To:* Log4J Developers List <lo...@logging.apache.org>
> *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, bit1129@163.com <bi...@163.com> wrote:
>
>> Sorry, looks that I forgot to attach the thread dump file.
>>
>> ------------------------------
>> bit1129@163.com
>>
>>
>> *From:* bit1129@163.com
>> *Date:* 2015-07-02 16:25
>> *To:* log4j-dev <lo...@logging.apache.org>
>> *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!
>>
>> ------------------------------
>> bit1129@163.com
>>
>>
>> *From:* Gary Gregory <ga...@gmail.com>
>> *Date:* 2015-07-02 15:57
>> *To:* Log4J Developers List <lo...@logging.apache.org>
>> *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, bit1129@163.com <bi...@163.com> 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.
>>>
>>>
>>>
>>>
>>>
>>> ------------------------------
>>> bit1129@163.com
>>>
>>
>>
>>
>> --
>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>> 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
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
>> 共有 *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: log4j-dev-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>>
>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> 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
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
> 共有 *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: garydgregory@gmail.com | ggregory@apache.org
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
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Re: Log4j2 RollingFileAppender deadlock issue
Posted by "bit1129@163.com" <bi...@163.com>.
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.
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 16:55
To: Log4J Developers List
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, bit1129@163.com <bi...@163.com> wrote:
Sorry, looks that I forgot to attach the thread dump file.
bit1129@163.com
From: bit1129@163.com
Date: 2015-07-02 16:25
To: log4j-dev
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!
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 15:57
To: Log4J Developers List
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, bit1129@163.com <bi...@163.com> 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.
bit1129@163.com
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
共有 1 个附件
Catch(07-02-13-34-56).jpg(1M) 极速下载 在线预览
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: 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) 极速下载 在线预览
Re: Re: Log4j2 RollingFileAppender deadlock issue
Posted by Gary Gregory <ga...@gmail.com>.
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, bit1129@163.com <bi...@163.com> wrote:
> Sorry, looks that I forgot to attach the thread dump file.
>
> ------------------------------
> bit1129@163.com
>
>
> *From:* bit1129@163.com
> *Date:* 2015-07-02 16:25
> *To:* log4j-dev <lo...@logging.apache.org>
> *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!
>
> ------------------------------
> bit1129@163.com
>
>
> *From:* Gary Gregory <ga...@gmail.com>
> *Date:* 2015-07-02 15:57
> *To:* Log4J Developers List <lo...@logging.apache.org>
> *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, bit1129@163.com <bi...@163.com> 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.
>>
>>
>>
>>
>>
>> ------------------------------
>> bit1129@163.com
>>
>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> 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
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
> [image: 提示图标] 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
> 共有 *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: log4j-dev-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-dev-help@logging.apache.org
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
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
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Re: Log4j2 RollingFileAppender deadlock issue
Posted by "bit1129@163.com" <bi...@163.com>.
Sorry, looks that I forgot to attach the thread dump file.
bit1129@163.com
From: bit1129@163.com
Date: 2015-07-02 16:25
To: log4j-dev
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!
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 15:57
To: Log4J Developers List
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, bit1129@163.com <bi...@163.com> 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.
bit1129@163.com
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
共有 1 个附件
Catch(07-02-13-34-56).jpg(1M) 极速下载 在线预览
Re: Re: Log4j2 RollingFileAppender deadlock issue
Posted by "bit1129@163.com" <bi...@163.com>.
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!
bit1129@163.com
From: Gary Gregory
Date: 2015-07-02 15:57
To: Log4J Developers List
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, bit1129@163.com <bi...@163.com> 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.
bit1129@163.com
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
JUnit in Action, Second Edition
Spring Batch in Action
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。
共有 1 个附件
Catch(07-02-13-34-56).jpg(1M) 极速下载 在线预览
Re: Log4j2 RollingFileAppender deadlock issue
Posted by Gary Gregory <ga...@gmail.com>.
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, bit1129@163.com <bi...@163.com> 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.
>
>
>
>
>
> ------------------------------
> bit1129@163.com
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
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
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory