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: Log4j2 RollingFileAppender deadlock issue
Date Thu, 02 Jul 2015 13:00:27 GMT
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 <ralph.goers@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" <bit1129@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 <garydgregory@gmail.com>
> *Date:* 2015-07-02 17:35
> *To:* Log4J Developers List <log4j-dev@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>
> 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 <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.
>>>>>
>>>>> <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

Mime
View raw message