I would prefer a solution that is reusable for all ThreadLocals, not just the one we are considering putting in PatternConverter. Are there any drawbacks with the registry idea?
Sent from my iPhone > On 2015/07/04, at 16:45, Gary Gregory <[email protected]> wrote: > > So the simplest thing to so would for PatternConverter to implement a stop() > method to clear the ThreadLocal (extending AbstractLifeCycle might be too > heavy for now) > > The tricky part is how to connect the dots from an appender stopping all the > way to the PatternConverter. Unless we go the route of the registry. > > Gary > >> On Thu, Jul 2, 2015 at 10:34 AM, Gary Gregory <[email protected]> wrote: >> Or the org.apache.logging.log4j.core.pattern.AbstractPatternConverter could >> extend org.apache.logging.log4j.core.AbstractLifeCycle and clearing the >> ThreadLocale would be done in stop(). The stop would have to be called at >> the right time of course. >> >> Gary >> >>> 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? >>> >>> 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 >>>>>> Date: 2015-07-02 17:35 >>>>>> To: Log4J Developers List >>>>>> 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 >>>>>>>> Date: 2015-07-02 16:55 >>>>>>>> To: Log4J Developers List >>>>>>>> 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 >>>>>>>>> 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 >>>>>>>>> Date: 2015-07-02 15:57 >>>>>>>>> To: Log4J Developers List >>>>>>>>> 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 >>>>>>>>> JUnit in Action, Second Edition >>>>>>>>> Spring Batch in Action >>>>>>>>> Blog: http://garygregory.wordpress.com >>>>>>>>> Home: http://garygregory.com/ >>>>>>>>> Tweet! http://twitter.com/GaryGregory >>>>>>>>> 邮件带有附件预览链接，若您转发或回复此邮件时不希望对方预览附件，建议您手动删除链接。 >>>>>>>>> 共有 1 个附件 >>>>>>>>> Catch(07-02-13-34-56).jpg(1M) >>>>>>>>> 极速下载 在线预览 >>>>>>>>> >>>>>>>>> >>>>>>>>> --------------------------------------------------------------------- >>>>>>>>> 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 >>>>>>>> JUnit in Action, Second Edition >>>>>>>> Spring Batch in Action >>>>>>>> Blog: 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) >>>>>>>> 极速下载 在线预览 >>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>> -- >>>>>>> E-Mail: [email protected] | [email protected] >>>>>>> Java Persistence with Hibernate, Second Edition >>>>>>> JUnit in Action, Second Edition >>>>>>> Spring Batch in Action >>>>>>> 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 >>>>>> JUnit in Action, Second Edition >>>>>> Spring Batch in Action >>>>>> Blog: 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) >>>>>> 极速下载 在线预览 >>>> >>>> >>>> >>>> -- >>>> E-Mail: [email protected] | [email protected] >>>> Java Persistence with Hibernate, Second Edition >>>> JUnit in Action, Second Edition >>>> Spring Batch in Action >>>> 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 >> JUnit in Action, Second Edition >> Spring Batch in Action >> 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 > JUnit in Action, Second Edition > Spring Batch in Action > Blog: http://garygregory.wordpress.com > Home: http://garygregory.com/ > Tweet! http://twitter.com/GaryGregory
