那些遇到过的问题

混合使用Log4j和commons-logging会导致"类加载死锁"？

ski*_*sch 10 java multithreading deadlock log4j apache-commons-logging

我认为我发现了一种情况,即混合使用log4j a)直接和b)通过commons-logging导致某种类加载死锁.我不确定这种情况是否可行(JVM是否应该检测到这种情况？)以及如何处理它.

问题

在我们的构建系统中,我们目前正在按顺序运行单元测试 - 为了使构建更快,我们显然可以改变它以并行运行我们的单元测试.但是,如果我们这样做,一些构建会遇到执行超时.在分析这种"悬挂构建"的线程转储时,我们发现自己处于不同的模块中,大多数时间都涉及不同的测试.但它总是归结为两个线程尝试初始化一个Logger:一个用Logger.getLogger(直接使用log4j),另一个用LogFactory.getLog(使用commons-logging).

我的分析

所以我们在这个地方有一个线程(直接使用log4j的线程):

"pool-1-thread-3" prio=10 tid=0x00007f6528ca6000 nid=0x6f8f in Object.wait() [0x00007f64d9ca6000]
  java.lang.Thread.State: RUNNABLE
at org.apache.log4j.LogManager.<clinit>(LogManager.java:82)
at org.apache.log4j.Logger.getLogger(Logger.java:117)
at de.is24.platform.contacts.domain.PhoneNumberFormat.<clinit>(PhoneNumberFormat.java:21)
Run Code Online (Sandbox Code Playgroud)

不幸的是,这是一个相当"拥挤"的路线:

Hierarchy h = new Hierarchy(new RootLogger((Level) Level.DEBUG));
Run Code Online (Sandbox Code Playgroud)

另一个线程(使用commons-logging)在这里等待:

"pool-1-thread-2" prio=10 tid=0x00007f6528bf9800 nid=0x6f8e in Object.wait() [0x00007f64d9da7000]
  java.lang.Thread.State: RUNNABLE
at org.apache.log4j.Priority.<clinit>(Priority.java:45)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:171)
at org.apache.commons.logging.impl.Log4JLogger.class$(Log4JLogger.java:37)
at org.apache.commons.logging.impl.Log4JLogger.<clinit>(Log4JLogger.java:45)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:529)
at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:235)
at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:209)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:351)
Run Code Online (Sandbox Code Playgroud)

这很简单:

final static public Priority FATAL = new Level(FATAL_INT, "FATAL", 0);
Run Code Online (Sandbox Code Playgroud)

所以对我来说,似乎第二个线程正在初始化类Priority并等待加载Level类.第一个线程可能尝试加载Level类(该行中的其他内容似乎无关),并且随着Level类的扩展Priority,等待Priority加载类.
我们陷入困境.

那么,你能告诉我这个分析是否正确吗？还是我错过了什么？

更新我

我写了一些测试用例,你可以在这里找到它们:https://github.com/sebastiankirsch/classloading

有几个测试用例证明了这个问题:

  1. TestLoadingByClassForName 应该很快造成死锁(我的机器每三次运行)
  2. TestLoadingMixed表示问题的一个版本被剥离到观察到的堆栈跟踪的最小值; 这个很少失败(大致因为4)
  3. TestMixedLoggerInstantiation模仿行为:一个类使用log4j实例化记录器,另一个使用commons-logging实例化.这里的死锁难以捕捉,因为涉及的代码要多得多 - 我需要添加随机睡眠,这当然需要适应你的机器

这是TestMixedLoggerInstantiation测试用例挂起的堆栈跟踪.

Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.1-b02 mixed mode):

"UseLog4JLogger" prio=10 tid=0x00007fa1f017d800 nid=0x7bd8 in Object.wait() [0x00007fa1e5ba4000]
   java.lang.Thread.State: RUNNABLE
    at org.apache.log4j.LogManager.<clinit>(LogManager.java:82)
    at org.apache.log4j.Logger.getLogger(Logger.java:117)
    at net.tcc.classloading.UseLog4JLogger.run(UseLog4JLogger.java:23)

"UseCommonsLoggingLogFactory" prio=10 tid=0x00007fa1f00e5000 nid=0x7bd7 in Object.wait() [0x00007fa1e5ca4000]
   java.lang.Thread.State: RUNNABLE
    at org.apache.log4j.Priority.<clinit>(Priority.java:45)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:169)
    at org.apache.commons.logging.impl.Log4JLogger.class$(Log4JLogger.java:37)
    at org.apache.commons.logging.impl.Log4JLogger.<clinit>(Log4JLogger.java:45)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
    at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:529)
    at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:235)
    at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:209)
    at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:351)
    at net.tcc.classloading.UseCommonsLoggingLogFactory.run(UseCommonsLoggingLogFactory.java:13)

"ReaderThread" prio=10 tid=0x00007fa1f00ed000 nid=0x7bd6 runnable [0x00007fa1e5da6000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:129)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)
    - locked <0x00000007d7088a00> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:167)
    at java.io.BufferedReader.fill(BufferedReader.java:136)
    at java.io.BufferedReader.readLine(BufferedReader.java:299)
    - locked <0x00000007d7088a00> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:362)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner$ReaderThread.run(RemoteTestRunner.java:140)

"Low Memory Detector" daemon prio=10 tid=0x00007fa1f009d800 nid=0x7bd4 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x00007fa1f009b800 nid=0x7bd3 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x00007fa1f0098800 nid=0x7bd2 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00007fa1f0096800 nid=0x7bd1 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00007fa1f007a000 nid=0x7bd0 in Object.wait() [0x00007fa1e6c54000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000007d7001300> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
    - locked <0x00000007d7001300> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00007fa1f0078000 nid=0x7bcf in Object.wait() [0x00007fa1e6d55000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000007d70011d8> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:485)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
    - locked <0x00000007d70011d8> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x00007fa1f000c000 nid=0x7bc5 in Object.wait() [0x00007fa1f50b0000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000007d730dfd8> (a net.tcc.classloading.UseCommonsLoggingLogFactory)
    at java.lang.Thread.join(Thread.java:1186)
    - locked <0x00000007d730dfd8> (a net.tcc.classloading.UseCommonsLoggingLogFactory)
    at java.lang.Thread.join(Thread.java:1239)
    at net.tcc.classloading.TestMixedLoggerInstantiation.test(TestMixedLoggerInstantiation.java:21)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
    at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
    at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)

"VM Thread" prio=10 tid=0x00007fa1f0071800 nid=0x7bce runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007fa1f001f000 nid=0x7bc6 runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007fa1f0021000 nid=0x7bc7 runnable 

"GC task thread#2 (ParallelGC)" prio=10 tid=0x00007fa1f0022800 nid=0x7bc8 runnable 

"GC task thread#3 (ParallelGC)" prio=10 tid=0x00007fa1f0024800 nid=0x7bc9 runnable 

"GC task thread#4 (ParallelGC)" prio=10 tid=0x00007fa1f0026800 nid=0x7bca runnable 

"GC task thread#5 (ParallelGC)" prio=10 tid=0x00007fa1f0028000 nid=0x7bcb runnable 

"GC task thread#6 (ParallelGC)" prio=10 tid=0x00007fa1f002a000 nid=0x7bcc runnable 

"GC task thread#7 (ParallelGC)" prio=10 tid=0x00007fa1f002c000 nid=0x7bcd runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007fa1f00a8800 nid=0x7bd5 waiting on condition 

JNI global references: 1168
Run Code Online (Sandbox Code Playgroud)

再现僵局

从https://github.com/sebastiankirsch/classloading下载代码.
TestLoadingByClassForName应该很容易导致死锁(只运行几次),这是系统/ JVM最终会遇到复杂场景死锁的先决条件.

现在运行TestMixedLoggerInstantiation几次.注意平均运行时间,打开UseLog4JLogger并将睡眠定时器总和设置为略低于平均运行时间.这最终会导致死锁,但很少发生.

因此,在命令行上运行它,如下所示:

for (( ; ; )) do
  testExectution
done
Run Code Online (Sandbox Code Playgroud)

而不是testExecution手动组合,只需在测试中设置break boint,调试,键入ps -ef | grep TestMixedLoggerInstantiationshell,然后复制IDE使用的命令.

ski*_*sch 7

我终于在Java语言规范中找到了答案,特别是在第12.4.2章详细初始化过程中.
它说

[...]
2)如果C的Class对象指示某个其他线程正在对C进行初始化,则阻止当前线程,直到通知正在进行的初始化已完成,[.. .]
7)接下来,如果C是一个类而不是一个接口,并且其超类SC尚未初始化,则递归执行SC的整个过程
10)如果初始化程序的执行正常完成,[...]将C的Class对象标记为完全初始化,通知所有等待的线程,[...]

因此,观察到的行为与JLS指定的完全一致.我仍然有点困惑,没有办法发现这种僵局.为什么线程被标记为RUNNABLE - 但我想这不是你要执行的典型字节码,所以谁知道......

如何解决问题

问题的解决方案是摆脱commons-logging.正如@Robert Johnson指出的那样,这可以通过改为使用来轻松完成org.slf4j:jcl-over-slf4j.我还检查了SLF代码:它没有"利用"不幸的log4j设计.

归档时间：

查看次数：

2300 次

最近记录：

12 年，10 月 前
Java:<init>和<clinit>有什么区别？ 87
如何使用带eclipse的maven2添加apache commons日志记录？ 8
更多相关链接
相关归档
Scala相当于Java java.lang.Class <T> Object 181
向IntelliJ项目添加Gradle支持的最佳方法 156
你可以将@Autowired与静态字段一起使用吗？ 129
在java中复制一个2d数组 48
为什么一个线程比Java中的main方法更长？ 32
如何等到File.Exists？ 14
睡眠功能是睡眠所有线程还是只调用它的人？ 7
如何检查所有任务是否已正确完成？ 7
有没有简单的方法来判断等待Python GIL花了多少时间？ 6
尝试使用主线程时不明确使用DispatchQueue 6
难疑归档
如何从JavaScript中删除数组中的特定元素？ 7655
"px","dip","dp"和"sp"之间有什么区别？ 5676
URI,URL和URN有什么区别？ 4217
什么是NullReferenceException,我该如何解决？ 1876
如何在JavaScript中将数字格式化为美元货币字符串？ 1711
方法和函数之间有什么区别？ 1665
重命名pandas中的列 1601
将文件从主机复制到Docker容器 1391
什么是右值,左值,x值,glvalues和prvalues？ 1291
对JavaScript对象数组进行排序 1233