On Thu, Jul 2, 2015 at 6:18 AM, Remko Popma <[email protected]> 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 <[email protected]> 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 <[email protected]> > 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, "[email protected]" <[email protected]> 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. >> >> ------------------------------ >> [email protected] >> >> >> *From:* Gary Gregory <[email protected]> >> *Date:* 2015-07-02 17:35 >> *To:* Log4J Developers List <[email protected]> >> *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 <[email protected]> >> 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, [email protected] <[email protected]> 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. >>>> >>>> >>>> >>>> >>>> ------------------------------ >>>> [email protected] >>>> >>>> >>>> *From:* Gary Gregory <[email protected]> >>>> *Date:* 2015-07-02 16:55 >>>> *To:* Log4J Developers List <[email protected]> >>>> *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, [email protected] <[email protected]> >>>> wrote: >>>> >>>>> Sorry, looks that I forgot to attach the thread dump file. >>>>> >>>>> ------------------------------ >>>>> [email protected] >>>>> >>>>> >>>>> *From:* [email protected] >>>>> *Date:* 2015-07-02 16:25 >>>>> *To:* log4j-dev <[email protected]> >>>>> *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! >>>>> >>>>> ------------------------------ >>>>> [email protected] >>>>> >>>>> >>>>> *From:* Gary Gregory <[email protected]> >>>>> *Date:* 2015-07-02 15:57 >>>>> *To:* Log4J Developers List <[email protected]> >>>>> *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, [email protected] <[email protected]> >>>>> 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> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> ------------------------------ >>>>>> [email protected] >>>>>> >>>>> >>>>> >>>>> >>>>> -- >>>>> E-Mail: [email protected] | [email protected] >>>>> 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: [email protected] >>>>> For additional commands, e-mail: [email protected] >>>>> >>>> >>>> >>>> >>>> -- >>>> E-Mail: [email protected] | [email protected] >>>> 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: [email protected] | [email protected] >>> 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: [email protected] | [email protected] >> 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: [email protected] | [email protected] > 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: [email protected] | [email protected] 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
