Apache Log4j是一个基于Java的日志记录工具，用起来非常方便，但是Log4j 1.x如果使用不慎，会引起死锁问题，进行导致整个网站的宕机
示例如下：
log4j 配置
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration PUBLIC "-//APACHE//DTD LOG4J 1.2//EN" "log4j.dtd"> <appender name="console" class="org.apache.log4j.ConsoleAppender">
<param name="Target" value="System.out"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %t %-5p (%c:%L) - %m%n"/>
</layout>
</appender>
<logger name="a" additivity="false">
<level value="info"/>
<appender-ref ref="console"/>
</logger>
<logger name="b" additivity="false">
<level value="info"/>
<appender-ref ref="console"/>
</logger>
<root>
<appender-ref ref="console"/>
</root>
</log4j:configuration>
|
使用logger a进行日志输出的java文件
package a;
import org.apache.log4j.Logger;
public class A {
private static final Logger logger = Logger.getLogger(A.class);
public A() {
try {
logger.info("[A.A()] class A");
} catch (Exception ex) {
logger.error("[A.A()]", ex);
}
}
} |
使用logger b进行日志输出的java文件
package b;
import org.apache.log4j.Logger;
import a.*;
public class B {
private static final Logger logger = Logger.getLogger(B.class.getName());
public static void main(String[] args) {
new Thread(new Runnable() {
public void run() {
logger.info(new B());
}
}).start();
new A();
}
public String toString() {
logger.info("[B.toString]");
new A();
return "[B.toString] finish";
}
} |
运行上面的程序，相当大的概率，程序会卡在这里不动，通过jstack命令，我们可以发现程序死锁了
jstack 3876 |
2016-12-22 16:54:38Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.65-b01 mixed mode):
"Attach Listener" #12 daemon prio=9 os_prio=31 tid=0x00007fb932944000 nid=0x3b0b waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Thread-0" #11 prio=5 os_prio=31 tid=0x00007fb9341c1800 nid=0x5903 waiting for monitor entry [0x000070000175b000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:205)
- waiting to lock (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at a.A.(A.java:11)
at b.B.toString(B.java:18)
at org.apache.log4j.or.DefaultRenderer.doRender(DefaultRenderer.java:37)
at org.apache.log4j.or.RendererMap.findAndRender(RendererMap.java:80)
at org.apache.log4j.spi.LoggingEvent.getRenderedMessage(LoggingEvent.java:368)
at org.apache.log4j.helpers.PatternParser$BasicPatternConverter.convert(PatternParser.java:402)
at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:506)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked (a org.apache.log4j.ConsoleAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:206)
- locked (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at b.B$1.run(B.java:10)
at java.lang.Thread.run(Thread.java:745)
"Monitor Ctrl-Break" #10 daemon prio=5 os_prio=31 tid=0x00007fb9358de800 nid=0x5703 runnable [0x0000700001658000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
at java.net.ServerSocket.implAccept(ServerSocket.java:545)
at java.net.ServerSocket.accept(ServerSocket.java:513)
at com.intellij.rt.execution.application.AppMain$1.run(AppMain.java:90)
at java.lang.Thread.run(Thread.java:745)
"Service Thread" #9 daemon prio=9 os_prio=31 tid=0x00007fb933002800 nid=0x5303 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread3" #8 daemon prio=9 os_prio=31 tid=0x00007fb936020800 nid=0x5103 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007fb935007800 nid=0x4f03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007fb935006800 nid=0x4d03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007fb933801000 nid=0x4b03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fb935837800 nid=0x3a13 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fb933802000 nid=0x3803 in Object.wait() [0x0000700000d3a000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
- locked (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fb936009000 nid=0x3603 in Object.wait() [0x0000700000c37000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
- locked (a java.lang.ref.Reference$Lock)
"main" #1 prio=5 os_prio=31 tid=0x00007fb935801800 nid=0x1703 waiting for monitor entry [0x0000700000218000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
- waiting to lock (a org.apache.log4j.ConsoleAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:206)
- locked (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at a.A.(A.java:11)
at b.B.main(B.java:13)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:144)
"VM Thread" os_prio=31 tid=0x00007fb936006800 nid=0x3403 runnable
"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fb93580a800 nid=0x2403 runnable
"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fb932804800 nid=0x2603 runnable
"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fb93580b000 nid=0x2803 runnable
"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fb936003000 nid=0x2a03 runnable
"GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007fb93580b800 nid=0x2c03 runnable
"GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007fb936003800 nid=0x2e03 runnable
"GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007fb936004000 nid=0x3003 runnable
"GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007fb936004800 nid=0x3203 runnable
"VM Periodic Task Thread" os_prio=31 tid=0x00007fb935838000 nid=0x5503 waiting on condition
JNI global references: 60Found one Java-level deadlock:============================="Thread-0":
waiting to lock monitor 0x00007fb93600edf8 (object 0x000000076b2a21d0, a org.apache.log4j.Logger),
which is held by "main"
"main":
waiting to lock monitor 0x00007fb93600d8a8 (object 0x000000076b311008, a org.apache.log4j.ConsoleAppender),
which is held by "Thread-0"
Java stack information for the threads listed above:
==================================================="Thread-0":
at org.apache.log4j.Category.callAppenders(Category.java:205)
- waiting to lock (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at a.A.(A.java:11)
at b.B.toString(B.java:18)
at org.apache.log4j.or.DefaultRenderer.doRender(DefaultRenderer.java:37)
at org.apache.log4j.or.RendererMap.findAndRender(RendererMap.java:80)
at org.apache.log4j.spi.LoggingEvent.getRenderedMessage(LoggingEvent.java:368)
at org.apache.log4j.helpers.PatternParser$BasicPatternConverter.convert(PatternParser.java:402)
at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:506)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked (a org.apache.log4j.ConsoleAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:206)
- locked (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at b.B$1.run(B.java:10)
at java.lang.Thread.run(Thread.java:745)
"main":
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
- waiting to lock (a org.apache.log4j.ConsoleAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:206)
- locked (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at a.A.(A.java:11)
at b.B.main(B.java:13)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:144)
Found 1 deadlock. |
jstack命令的最后，给我们一个很重要的提示，就是程序发生了死锁，那么接下来，就是要分析程序为什么会产生死锁, jstack命令也给了相应的提示信息，如下所示
"Thread-0":
waiting to lock monitor 0x00007fb93600edf8 (object 0x000000076b2a21d0, a org.apache.log4j.Logger),
which is held by "main"
"main":
waiting to lock monitor 0x00007fb93600d8a8 (object 0x000000076b311008, a org.apache.log4j.ConsoleAppender),
which is held by "Thread-0"
|
Thread-0尝试去lock一个Logger, org.apache.log4j.Logger这个类继承于org.apache.log4j.category，而调用的info方法在category这个类中，由org.apache.log4j.category中这段源码可以发现，Thread-0实际上是去尝试lock一个category
public void callAppenders(LoggingEvent event) {
int writes = 0;
for(Category c = this; c != null; c=c.parent) {
// Protected against simultaneous call to addAppender, removeAppender,...
synchronized(c) {
if(c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
break;
}
}
}
if(writes == 0) {
repository.emitNoAppenderWarning(this);
}
} |
从上面的代码中可以看出Thread-0实际上在等待lock一个category,再结合上面的log4j的配置文件，很容易的发现，Thread-0会使用两个logger文件，即name=a与name=b的logger文件均会使用，当调用logger.info(new B())的时候，实际上最后会被自动的转化为对new B().toString()方法的调用，在这个方法里面即输出了A的日志，又输出了B的日志，再结合jstack命令下面的描述，可以发现再lock [name=a的logger时，由于已经被其他线程占用，因此 Thread-0 block]
"Thread-0": at org.apache.log4j.Category.callAppenders(Category.java:205)
- waiting to lock (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at a.A.(A.java:11)
at b.B.toString(B.java:18)
at org.apache.log4j.or.DefaultRenderer.doRender(DefaultRenderer.java:37)
|
综上所述，Thread-0线程拥有了logger name=b的category,ConsoleAppender ,且正在尝试去获取logger name=a的category
jstack命令显示main线程正在wait一个ConsoleAppender,由源码可以发现ConsoleAppender继承于AppenderSkeleton，再结合以下输出
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
- waiting to lock (a org.apache.log4j.ConsoleAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:206)
|
可以发现，main线程在执行AppenderSkeleton.java中doAppend方法时发生了wait,看源码如下所示
publicsynchronized void doAppend(LoggingEvent event) {
if(closed) {
LogLog.error("Attempted to append to closed appender named ["+name+"].");
return;
}
if(!isAsSevereAsThreshold(event.getLevel())) {
return;
}
Filter f = this.headFilter;
FILTER_LOOP:
while(f != null) {
switch(f.decide(event)) {
case Filter.DENY: return;
case Filter.ACCEPT: break FILTER_LOOP;
case Filter.NEUTRAL: f = f.getNext();
}
}
this.append(event);
} |
看到了synchronized,也就明白了，main线程无法获取到ConsoleAppender的对象锁，因为此对象锁正在被Thread-0占用，综上所述，main线程拥有了logger name=a的category,正在尝试去获取ConsoleAppender的对象锁，去进行日志输出，因此两线程死锁了
Log4j的日志输出流程
由上面的流程图可以看出，在一个日志的输出过程中，会尝试进行两次lock,在高并发的情况下，两次lock就很容易造成死锁，上面产生死锁的可能执行序列如下:
1.Thread-0 lock b的category
2.Thread-0 lock ConsoleAppender
3.main线程 lock a的category
4.Thread-0 尝试去获取 a的category,因为要进行日志a的输出了, block
5.main线程尝试去lock ConsoleAppender，由于被Thread-0占用, bloc
最终死锁了!
找到死锁发生的原因，那如何解决这个问题:
取决于log4j配置文件的合理性
在log4j的上面加上slf4j,将要输出的日志提前格式化成一个字符串，对于上面的例子，也就是将logger.info(new A()) 中new A().toString()提前调用，没有slf4j时的调用序列是
lock b->lock consoleappender->lock a->lock consoleappender 是一个步骤完成的
加入slf4j后的设用序列就变成了
lock a -> lock consoleappender 完成了第一阶段new A()
lock b -> lock consoleappender 完成了第二阶段 logger.info(string)
加入slf4j后可以发现的是日志的输出分成两步执行了，因为执行logger.info时，会首先对要输出的内容进行格式化，将其格式化成一个string, so,不会发生死锁了。
转载原文：http://www.aiprograming.com/b/pengpeng/23
相关推荐
1. **线程安全问题**：如内存泄漏、资源争抢、数据一致性问题等。 2. **性能优化**：如何平衡线程数量以最大化系统性能。 3. **线程间的通信**：线程间如何交换信息，如使用管道、消息队列、共享内存等。 4. **线程...
4. **阻塞态（Blocked）**：线程因为等待某个事件（如I/O操作或同步锁）而无法运行。 5. **消亡态（Dead）**：线程运行结束或者被显式终止。 #### 四、线程的调度原则 Java中的线程调度采用的是基于优先级的抢占式...
Java线程有五种基本状态：新建（NEW）、可运行（RUNNABLE）、阻塞（BLOCKED）、等待（WAITING）和终止（TERMINATED）。线程从新建到终止会经历这些状态的转换。 4. 线程同步与互斥： 为了避免多线程环境下资源...
线程堆栈反映了程序运行时的线程状态，帮助开发者定位和解决多线程问题，如死锁、资源竞争等。IBM为WebSphere Application Server (WAS) 提供了一款名为"jca467.jar"的线程堆栈分析工具，专门用于处理与IBM Java相关...
死锁是SQL Server中常见的问题之一，它会导致数据库性能下降、甚至数据库崩溃。因此，了解如何查询和解决死锁是非常重要的。本节将为您介绍如何查询SQL Server死锁，并提供解决死锁的方法。 死锁的查询方法 1. ...
- **线程状态**：Java线程有新建（New）、就绪（Runnable）、运行（Running）、阻塞（Blocked）、等待（Waiting）、超时等待（Timed Waiting）和终止（Terminated）7种状态。 - **线程控制**：包括`sleep()`, `...
5. 使用select id=identity(int, 1, 1), 标志, 进程ID=spid, 线程ID=kpid, 块进程ID=blocked, 数据库ID=dbid命令来查询死锁的进程信息。 6. 使用select 数据库名=dbname(dbid), 用户ID=uid, 用户名=loginame, 累计...
未提交的事务可能会导致阻塞其他事务，进一步引发死锁。以下是一段SQL查询语句，用于找出所有未提交事务的详细信息： ```sql SELECT spid, blocked, waittime, waittype, waitresource, p.dbid, cpu, physical_io, ...
1. 死锁的概念：两个或更多线程相互等待对方释放资源，导致都无法继续执行。 2. 避免死锁的方法：避免循环等待、设置超时、加锁顺序等。 十、线程安全的类 1. java.util.concurrent包下的工具类，如CountDownLatch...
了解这些状态对于理解和解决线程问题至关重要。 **四、线程同步** 线程同步是为了避免多个线程对共享资源的不恰当访问导致的数据不一致。常见的同步机制包括锁（互斥量）、信号量、条件变量、死锁预防和检测等。...
Java线程有五种基本状态：新建（New）、可运行（Runnable）、运行（Running）、阻塞（Blocked）和终止（Terminated）。线程从新建到终止会经历这些状态，如通过调用`start()`方法进入可运行状态，而`sleep()`, `wait...
Oracle 死锁问题的排查语句 Oracle 死锁是指在数据库中出现的循环等待资源的情形，从而导致数据库性能下降或系统崩溃。出现死锁的原因有多种，如资源竞争、锁定机制不当等。下面是排查 Oracle 死锁问题的语句： 1....
理解这些状态以及它们之间的转换是分析多线程问题的关键。 4. **同步机制**：Java提供了多种同步机制，包括synchronized关键字、Lock接口（如ReentrantLock）以及volatile关键字。synchronized用于控制对共享资源的...
10. **线程Local变量**：`ThreadLocal`类为每个线程提供独立的变量副本，有效避免了线程安全问题。 以上知识点覆盖了Java线程的基础概念、创建方式、状态管理、同步机制以及高级特性，是Java程序员必须掌握的重要...
### SQL Server 死锁处理详解 #### 一、引言 在 SQL Server 数据库系统中，当两个或多个事务在等待对方释放资源时，就会发生死锁现象。死锁不仅会降低系统的整体性能，还可能导致数据处理异常中断，严重影响业务...
Pintos线程管理是通过优先级调度、线程blocked状态、线程unblock、线程调度、timer_interrupt函数、thread_foreach函数、blocked_thread_check函数、thread_cmp_priority函数、线程yield、线程初始化和测试驱动开发...
4. **多线程卖票问题**： - 这个例子可能模拟了一个售票系统，多个线程代表售票员，每个售票员都有自己的票库存。 - 非同步访问可能导致线程安全问题，例如“售票员卖出负数的票”。因此，必须使用同步机制，如`...
Webuser__AcWebuser__Access_any_blocked_website.pdf cess_any_blocked_website
项目涵盖了多线程编程的核心概念、常见问题及其解决方案，包括线程的创建、启动、停止、生命周期管理、线程安全、死锁预防等。通过本项目，开发者可以学习如何在Java中实现高效、安全的并发编程。 项目的主要特性...
四、线程安全问题 1. 线程不安全的数据访问：共享变量可能引发数据不一致，需要通过同步机制保证一致性。 2. 死锁：多个线程互相等待对方释放资源导致僵局。 3. 活锁：线程不断尝试执行失败的操作，导致资源浪费。 4...