使用logback会产生的死锁问题（转）
案例一：
在sn遇到的生产线上日志死锁问题：  
发现有大量的线程都出现等待日志锁，
从业务逻辑讲：这就解释了为什么从redis获取的值消耗了最高49秒的时长，，也就解释了在等待锁的同时，超大字符串json，如这些的引用得不到及时的释放，，导致cpu一直爆满，，从数据库查出的大对象也是个问题，，，，看了下加锁地方的源码，我们仓库使用的是
1.1.2版本的logback JAR包，这个写日志问题，我之前也遇到过，，后来查了资料，，
低版本采用公平锁，性能低于非公平锁，，且业务层日志打印地方较多，，属偶发性，，建议升级logback版本或者使用异步类来写入日志。AsyncAppender（异步写，是放入有界数组阻塞队列里面，实现异步，）。
sn的WIKI上面对于logback的使用过程
logback 配置文件：
从生产服务器抓的java core信息：
Found one Java-level deadlock:
=============================
"hpThreadPoolExecutor-thread-26":
waiting to lock monitor 0x0000000001d24fb8 (object 0x00000000cb6fe578, a java.io.PrintStream),
which is held by "hpThreadPoolExecutor-thread-24"
"hpThreadPoolExecutor-thread-24":
waiting for ownable synchronizer 0x00000000ce2d5858, (a java.util.concurrent.locks.ReentrantLock$FairSync),
which is held by "hpThreadPoolExecutor-thread-26"
根据上面的信息，可以画出死锁的示意图：
再来根据具体的堆栈信息来分析：
先来看logback的源码，实际写文件的时候，会先使用ReentrantLock对象加锁，然后再获取java.io.PrintStream实例的监视权（可以简单地理解为对控制台文件加锁），这是因为配置文件中加了STDOUT的Appender。
然后看jboss的源码，当调用AbstractLoggingWriter.write的时候，方法里面会使用java.util.logging API去记录日志，由于依赖了jul-to-slf4j桥接器，使用java.util.logging API记录日志的地方，底层都会交给logback来记录日志。
由于在业务代码中使用了System.out.println()这种写法来记录日志，会先获取java.io.PrintStream实例的监视权，再去获取ReentrantLock，获取这两把锁的顺序刚好和使用logback来记录日志的获取锁的顺序相反，引起了死锁。
解决办法：
1、在代码中避免使用System.out.println()的写法，而应该使用类似logger.info()的写法
2、配置logback的时候，应该把业务日志打印到自定义的文件中，而不需要再打印到控制台（控制台，指的是jboss容器的/opt/jboss/domain/servers/fserver1/log/server.log）
案例二：
先说下项目背景，为了统一公司的schedule job，做了一个job的框架，定时任务统一接入到这个框架里面。
job框架用java开发，原理很简单，解析用户输入的crontab表达式，到了schedule的时间，用ProcessBuilder把用户的程序给带起来。
今天有同事反应，程序在本地可以正常运行，接入job框架后出现大量的SOA远程调用timeout。
第一反应是资源文件加载路径的问题，怀疑是不是读错了配置文件，再三检查发现一切无误。
打印线程堆栈后发现，所有的线程都卡死在了logback记日志的地方，大家都在等待一把锁，堆栈里面没能发现谁持有了这个锁对象。
从以下几点着手排查：
1. 怀疑是jar包冲突，job框架本身使用的logback版本和用户程序使用的logback版本冲突。于是一番折腾，无果。
2. 怀疑是SOA框架里面记日志的地方有冲突，再三check，还是无果。
然后发现用户的log配置，除了写磁盘以外，还会输出到console，于是改了下配置文件，不再输出到console，发现不再死锁。
于是赶紧的查了下jdk里面关于process的描述，摘录如下：
By default, the created subprocess does not have its own terminal or console. All its standard I/O (i.e. stdin, stdout, stderr) operations will be redirected to the parent process, where they can be accessed via the streams obtained using the methods getOutputStream(), getInputStream(), and getErrorStream(). The parent process uses these streams to feed input to and get output from the subprocess. Because some native platforms only provide limited buffer size for standard input and output streams, failure to promptly write the input stream or read the output stream of the subprocess may cause the subprocess to block, or even deadlock.
子进程是没有自己的console的，标准输出会redirect给自己的父进程。子进程输出到操作系统的buffer里面，等待着父进程从inputstream里面读出数据，如果父进程没有读，那么一旦buffer满了，子进程就会处于waiting状态，等待buffer清空，造成死锁。
看了这段描述后，真相大白了，job框架不会去读用户输出到ocnsole的信息，从而导致了死锁。
解决方法后很简单，禁止用户输出到console，日志直接写磁盘。
使用log4j产生的死锁（）转
这个死锁的原因：一个动作需要两个临界对象。
静态同步方法，就是一个临界对象。
这种场景，静态同步方法每次只能有一个线程持有。
如果存在另一个临界对象，静态同步方法中也需要获取这个临界对象。即一个动作需要两个临界对象。
We are experiencing deadlocks on our server.
We have tested with log4j version 1.2.8 up to and including 1.2.15
We have identified that cause to be a log statement inside a
synchronized block,
which is called from different threads.
We have attached to very simplified classes, to reproduce the deadlock.
Our framework is a lot more complex, where log4j can be called
indirectly with reflection, not neccessarily by us, but from third party
libraries etc.
The deadlock can be reproduced always.
Is our usage (or library usage) of log4j faulty, or is it a bug?
import org.apache.log4j.Logger;
public class FindDeadLock {
public static void main(String[] args) {
new Thread(new Runnable() {
public void run() {
Logger.getLogger(getClass()).info(new FindDeadLock());
}
}).start();
DeadLockingObject.getInstance();//lineNO:13
}
public String toString() {
/* now we are inside log4j, try to create a DeadLockingObject */
DeadLockingObject.getInstance();
return "Created DeadlockObject, returning string";
}
}
import org.apache.log4j.Logger;
public final class DeadLockingObject {
private static final Logger LOG = Logger.getLogger(DeadLockingObject.class
.getName());
private static DeadLockingObject singleton = new DeadLockingObject();
private DeadLockingObject() {
}
public synchronized static DeadLockingObject getInstance() {
try {
// to make the deadlock occur
Thread.sleep(100);
} catch (InterruptedException e) {
LOG.error(e);
}
LOG.info("Returning nice singleton");//lineNO:20
return singleton;
}
}
Here is our log4j configuration:
# Set root logger level to DEBUG and its only appender to A1.
log4j.rootLogger=INFO, A1
# A1 is set to be a ConsoleAppender.
log4j.appender.A1=org.apache.log4j.ConsoleAppender
# A1 uses PatternLayout.
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n
Analyse:
"main" - Thread t@1
java.lang.Thread.State: BLOCKED
at org.apache.log4j.Category.callAppenders(Category.java:205)
- waiting to lock <341960> (a org.apache.log4j.spi.RootLogger) owned by "Thread-0" t@8
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at loggerlock.DeadLockingObject.getInstance(DeadLockingObject.java:20)
- locked <105738> (a java.lang.Class)
at loggerlock.FindDeadLock.main(FindDeadLock.java:13)
Locked ownable synchronizers:
- None
main线程:
(1)DeadLockingObject.getInstance();//获取DeadLockingObject class级别的锁
(2)LOG.info("Returning nice singleton");//打印日志需要依次获取class org.apache.log4j.spi.RootLogger、org.apache.log4j.ConsoleAppender的锁
"Thread-0" - Thread t@8
java.lang.Thread.State: BLOCKED
at loggerlock.DeadLockingObject.getInstance(DeadLockingObject.java:16)
- waiting to lock <105738> (a java.lang.Class) owned by "main" t@1
at loggerlock.FindDeadLock.toString(FindDeadLock.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 <81aa7a> (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 <341960> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
at loggerlock.FindDeadLock$1.run(FindDeadLock.java:10)
at java.lang.Thread.run(Unknown Source)
Locked ownable synchronizers:
- None
Thread-0线程：
(1)Logger.getLogger(getClass()).info(。。。//
//获取Class org.apache.log4j.spi.RootLogger的锁
//获取Class org.apache.log4j.ConsoleAppender的锁
(3)new FindDeadLock()的toString方法中
DeadLockingObject.getInstance();//需要获取Class DeadLockingObject锁
http://apache-logging.6191.n7.nabble.com/Log4j-1-2-x-deadlock-bug-or-faulty-usage-td7658.html
Tips:
(1)线程状态 waiting for monitor entry 表示目前线程正在等待去锁住一个对象（其它线程可能正拥有该对象锁）。该现象会发生在当多线程同时去执行同步代码块或方法时。注意锁是对对象而言的，而不是单个的方法，也就是说当一个线程去执行某个对象的同步方法时，它须先锁住那个对象。
(2)
要找出所有Thread栈信息，并且分类排序，比如：
因为log4j等待Logger的而阻塞的有多少条线程，这种：
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:204)
- waiting to lock <0x00002aab2f555948> (a org.apache.log4j.spi.RootLogger)
因为JDBC操作等待数据库返回的有多少条线程，这种：
ava.lang.Thread.State: BLOCKED (on object monitor)
at oracle.jdbc.driver.T4CMAREngine.unmarshalDALC(T4CMAREngine.java:2347)
at oracle.jdbc.driver.T4C8TTIuds.unmarshal(T4C8TTIuds.java:134)
at oracle.jdbc.driver.T4CTTIdcb.receiveCommon(T4CTTIdcb.java:155)
然后根据数量规模排序，来判断瓶颈可能发生的位置。
http://bbs.csdn.net/topics/390033107?page=1#post-398824236
扫一扫
8748
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
