log4j 错误邮件挂线程
log4j error mails hanging threads
我们遇到了一些问题，我们的生产环境对请求的响应极其缓慢，并且发现 Tomcat 有 运行 个工作线程。这在一定程度上是我们的错，因为一个旧功能占用了线程，但我们也发现了一些关于 log4j 和邮件错误日志的有趣内容。有一个 log4j 错误日志记录线程试图发送阻塞 34 个其他线程的邮件。来自阻塞线程的线程转储如下所示：
"http-apr-80-exec-777" - Thread t@4195
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:97)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
- locked <45b6408b> (a java.io.BufferedInputStream)
at com.sun.mail.util.LineInputStream.readLine(LineInputStream.java:75)
at com.sun.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:1440)
at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1260)
at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:370)
at javax.mail.Service.connect(Service.java:275)
at javax.mail.Service.connect(Service.java:156)
at javax.mail.Service.connect(Service.java:105)
at javax.mail.Transport.send0(Transport.java:168)
at javax.mail.Transport.send(Transport.java:98)
at org.apache.log4j.net.SMTPAppender.sendBuffer(SMTPAppender.java:416)
at org.apache.log4j.net.SMTPAppender.append(SMTPAppender.java:256)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <54ebd98f> (a org.apache.log4j.net.SMTPAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:206)
- locked <731a1e23> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.error(Category.java:305)
at org.apache.jsp.errorpage_jsp._jspService(errorpage_jsp.java:197)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:432)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:390)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:334)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:749)
at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:489)
at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:412)
at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:339)
at org.apache.catalina.core.StandardHostValve.custom(StandardHostValve.java:467)
at org.apache.catalina.core.StandardHostValve.throwable(StandardHostValve.java:412)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:201)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:947)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1009)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:1852)
- locked <6af9560> (a org.apache.tomcat.util.net.SocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- locked <7a82445e> (a java.util.concurrent.ThreadPoolExecutor$Worker)
虽然 34 个阻塞的线程通常看起来像这样：
"http-apr-80-exec-787" - Thread t@4306
java.lang.Thread.State: BLOCKED
at org.apache.log4j.Category.callAppenders(Category.java:204)
- waiting to lock <731a1e23> (a org.apache.log4j.spi.RootLogger) owned by "http-apr-80-exec-777" t@4195
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.error(Category.java:305)
at org.apache.jsp.errorpage_jsp._jspService(errorpage_jsp.java:197)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:432)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:390)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:334)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:749)
at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:489)
at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:412)
at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:339)
at org.apache.catalina.core.StandardHostValve.custom(StandardHostValve.java:467)
at org.apache.catalina.core.StandardHostValve.throwable(StandardHostValve.java:412)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:201)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:947)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1009)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:1852)
- locked <2d079e0c> (a org.apache.tomcat.util.net.SocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- locked <7dac19bb> (a java.util.concurrent.ThreadPoolExecutor$Worker)
这可能是什么原因造成的？邮件服务器的问题？ log4j 中是否有任何配置可以防止或减少锁的后果？
Server 运行ning on Tomcat 7 on windows server 2008 using log4j 1.2.17, javax.mail 1.4
您可能想检查 Apache Log4j 中关于 Logger 线程阻塞的错误：https://issues.apache.org/bugzilla/show_bug.cgi?id=50213
在大多数情况下这应该不是问题，但如果我们使用类似 SMTPAppender 的东西，它可能需要一些时间来执行，那么这可能会导致问题。
一个可能的解决方案是使用异步记录器
<appender name="asyncAppender" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="theTargetAppender"/>
<param name="BufferSize" value="512" />
<param name="Blocking" value="false" />
</appender>
要记住的一件事是，由于它是异步的，如果您的程序在异步线程记录之前崩溃，那么该日志消息可能会丢失。
更多信息： http://troyjsd.blogspot.sg/2009/07/user-complaints-of-slow-j2ee-pages.html
我们遇到了一些问题，我们的生产环境对请求的响应极其缓慢，并且发现 Tomcat 有 运行 个工作线程。这在一定程度上是我们的错，因为一个旧功能占用了线程，但我们也发现了一些关于 log4j 和邮件错误日志的有趣内容。有一个 log4j 错误日志记录线程试图发送阻塞 34 个其他线程的邮件。来自阻塞线程的线程转储如下所示：
"http-apr-80-exec-777" - Thread t@4195
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:97)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
- locked <45b6408b> (a java.io.BufferedInputStream)
at com.sun.mail.util.LineInputStream.readLine(LineInputStream.java:75)
at com.sun.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:1440)
at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1260)
at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:370)
at javax.mail.Service.connect(Service.java:275)
at javax.mail.Service.connect(Service.java:156)
at javax.mail.Service.connect(Service.java:105)
at javax.mail.Transport.send0(Transport.java:168)
at javax.mail.Transport.send(Transport.java:98)
at org.apache.log4j.net.SMTPAppender.sendBuffer(SMTPAppender.java:416)
at org.apache.log4j.net.SMTPAppender.append(SMTPAppender.java:256)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <54ebd98f> (a org.apache.log4j.net.SMTPAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:206)
- locked <731a1e23> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.error(Category.java:305)
at org.apache.jsp.errorpage_jsp._jspService(errorpage_jsp.java:197)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:432)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:390)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:334)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:749)
at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:489)
at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:412)
at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:339)
at org.apache.catalina.core.StandardHostValve.custom(StandardHostValve.java:467)
at org.apache.catalina.core.StandardHostValve.throwable(StandardHostValve.java:412)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:201)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:947)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1009)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:1852)
- locked <6af9560> (a org.apache.tomcat.util.net.SocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- locked <7a82445e> (a java.util.concurrent.ThreadPoolExecutor$Worker)
虽然 34 个阻塞的线程通常看起来像这样：
"http-apr-80-exec-787" - Thread t@4306
java.lang.Thread.State: BLOCKED
at org.apache.log4j.Category.callAppenders(Category.java:204)
- waiting to lock <731a1e23> (a org.apache.log4j.spi.RootLogger) owned by "http-apr-80-exec-777" t@4195
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.error(Category.java:305)
at org.apache.jsp.errorpage_jsp._jspService(errorpage_jsp.java:197)
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:432)
at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:390)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:334)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:749)
at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:489)
at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:412)
at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:339)
at org.apache.catalina.core.StandardHostValve.custom(StandardHostValve.java:467)
at org.apache.catalina.core.StandardHostValve.throwable(StandardHostValve.java:412)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:201)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:947)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1009)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
at org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:1852)
- locked <2d079e0c> (a org.apache.tomcat.util.net.SocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- locked <7dac19bb> (a java.util.concurrent.ThreadPoolExecutor$Worker)
这可能是什么原因造成的？邮件服务器的问题？ log4j 中是否有任何配置可以防止或减少锁的后果？
Server 运行ning on Tomcat 7 on windows server 2008 using log4j 1.2.17, javax.mail 1.4
您可能想检查 Apache Log4j 中关于 Logger 线程阻塞的错误：https://issues.apache.org/bugzilla/show_bug.cgi?id=50213
在大多数情况下这应该不是问题，但如果我们使用类似 SMTPAppender 的东西，它可能需要一些时间来执行，那么这可能会导致问题。
一个可能的解决方案是使用异步记录器
<appender name="asyncAppender" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="theTargetAppender"/>
<param name="BufferSize" value="512" />
<param name="Blocking" value="false" />
</appender>
要记住的一件事是，由于它是异步的，如果您的程序在异步线程记录之前崩溃，那么该日志消息可能会丢失。
更多信息： http://troyjsd.blogspot.sg/2009/07/user-complaints-of-slow-j2ee-pages.html