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:35:36 GMT
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> 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 <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
>



-- 
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