logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "bit1129@163.com" <bit1...@163.com>
Subject Re: Re: Log4j2 RollingFileAppender deadlock issue
Date Thu, 02 Jul 2015 12:56:10 GMT
Thanks Ralph for the reply.  It is ugly that SimpleDateFormat is a not thread safe API.
Since this problem occurs from time to time, I want to ask how to proceed at this point.



bit1129@163.com
 
From: Ralph Goers
Date: 2015-07-02 20:34
To: Log4J Developers List
Subject: Re: Log4j2 RollingFileAppender deadlock issue
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
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 <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
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, 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
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
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, 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
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: 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
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: garydgregory@gmail.com | ggregory@apache.org 
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: garydgregory@gmail.com | ggregory@apache.org 
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) 极速下载 在线预览 
Mime
View raw message