logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Gary Gregory <garydgreg...@gmail.com>
Subject Re: Re: Log4j2 RollingFileAppender deadlock issue
Date Thu, 02 Jul 2015 09:34:01 GMT
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 <bit1129@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 <garydgregory@gmail.com>
> *Date:* 2015-07-02 16:55
> *To:* Log4J Developers List <log4j-dev@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 <bit1129@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 <log4j-dev@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 <garydgregory@gmail.com>
>> *Date:* 2015-07-02 15:57
>> *To:* Log4J Developers List <log4j-dev@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 <bit1129@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

Mime
View raw message