logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jess Holle <je...@ptc.com>
Subject Re: Log4j2 RollingFileAppender deadlock issue
Date Thu, 02 Jul 2015 12:49:28 GMT
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 <mailto:bit1129@163.com>" 
> <bit1129@163.com <mailto: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 <mailto:bit1129@163.com>
>>
>>     *From:* Gary Gregory <mailto:garydgregory@gmail.com>
>>     *Date:* 2015-07-02 17:35
>>     *To:* Log4J Developers List <mailto: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 <mailto: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
>>         <mailto:bit1129@163.com> <bit1129@163.com
>>         <mailto: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 <mailto:bit1129@163.com>
>>
>>                 *From:* Gary Gregory <mailto:garydgregory@gmail.com>
>>                 *Date:* 2015-07-02 16:55
>>                 *To:* Log4J Developers List
>>                 <mailto: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
>>                 <mailto:bit1129@163.com> <bit1129@163.com
>>                 <mailto:bit1129@163.com>> wrote:
>>
>>                     Sorry, looks that I forgot to attach the thread
>>                     dump file.
>>
>>                     ------------------------------------------------------------------------
>>                     bit1129@163.com <mailto:bit1129@163.com>
>>
>>                         *From:* bit1129@163.com <mailto:bit1129@163.com>
>>                         *Date:* 2015-07-02 16:25
>>                         *To:* log4j-dev
>>                         <mailto: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 <mailto:bit1129@163.com>
>>
>>                             *From:* Gary Gregory
>>                             <mailto:garydgregory@gmail.com>
>>                             *Date:* 2015-07-02 15:57
>>                             *To:* Log4J Developers List
>>                             <mailto: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 <mailto:bit1129@163.com>
>>                             <bit1129@163.com
>>                             <mailto: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 <mailto:bit1129@163.com>
>>
>>
>>
>>
>>                             -- 
>>                             E-Mail: garydgregory@gmail.com
>>                             <mailto:garydgregory@gmail.com> |
>>                             ggregory@apache.org
>>                             <mailto: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
>>                             <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
>>                     <mailto:log4j-dev-unsubscribe@logging.apache.org>
>>                     For additional commands, e-mail:
>>                     log4j-dev-help@logging.apache.org
>>                     <mailto:log4j-dev-help@logging.apache.org>
>>
>>
>>
>>
>>                 -- 
>>                 E-Mail: garydgregory@gmail.com
>>                 <mailto:garydgregory@gmail.com> | ggregory@apache.org
>>                 <mailto: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
>>                 <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
>>         <mailto:garydgregory@gmail.com> | ggregory@apache.org
>>         <mailto: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
>>         <http://garygregory.wordpress.com/>
>>         Home: http://garygregory.com/
>>         Tweet! http://twitter.com/GaryGregory
>>
>>
>>
>>
>>     -- 
>>     E-Mail: garydgregory@gmail.com <mailto:garydgregory@gmail.com> |
>>     ggregory@apache.org <mailto: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
>>     <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>
>>
>>


Mime
View raw message