Log4j1.2 — 死結

為嘛死結無處不在啊？出問題的這個進程是做後台計算的，三十個左右的NodeThread，基本上在執行相同的http請求時，依賴的服務沒有及時響應，等待一段時間後逾時，於是線程們開始寫日誌。基本上等於三十個線程同時開始記日誌，要求擷取aorg.apache.log4j.spi.RootCategory 對象的鎖。多線程環境下，真是啥都不牢靠。

眾網友反映這個問題在log4j 1.2*版的古老bug。至今還沒解決...  apache說1.3是個不連續的版本，2.0是實驗性質的版本，唉，不靠譜。

還有同學說有些死結是有些應用程式層日誌api調用得有問題，不是人log4j的問題，那同學代碼確實寫的很bt，但是和我碰到的問題不是一個問題，就不深入討論了。 http://mail-archives.apache.org/mod_mbox/logging-log4j-user/200810.mbox/%3C48FC8556.7020804@corporater.com%3E

 

 

-----------------------------------------------------------------------------------------------------------------------------------------------------------

 

有stack有真相。

一個線程

 "Thread-2174" daemon prio=10 tid=0x00000000506a3000 nid=0x7a2 runnable [0x00000000452f8000]
   java.lang.Thread.State: RUNNABLE
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:260)
        at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105)
        - locked <0x00002aaab3611fb0> (a java.io.BufferedOutputStream)
        at java.io.PrintStream.write(PrintStream.java:430)
        - locked <0x00002aaab3611f78> (a java.io.PrintStream)
        at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)
        at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)
        at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276)
        at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)
        - locked <0x00002aaab589f280> (a java.io.OutputStreamWriter)
        at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
        at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:49)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:306)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
        - locked <0x00002aaab589e658> (a org.apache.log4j.ConsoleAppender)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
        at org.apache.log4j.Category.callAppenders(Category.java:187)
        - locked <0x00002aaab5838af0> (a org.apache.log4j.spi.RootCategory)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.info(Category.java:674)
        at com.wps.www.oaas.ftr.dispatcher.task.XLiveIndexWorker_Optimize.doIndex(XLiveIndexWorker_Optimize.java:278)
        at com.wps.www.oaas.ftr.dispatcher.task.XLiveIndexWorker_Optimize.doIndexes(XLiveIndexWorker_Optimize.java:185)
        at com.wps.www.oaas.ftr.dispatcher.task.XLiveTaskWorker.doWork(XLiveTaskWorker.java:23)
        at com.wps.www.oaas.ftr.dispatcher.node.NodeThread.doWork(NodeThread.java:256)
        at com.wps.www.oaas.ftr.dispatcher.node.NodeThread.run(NodeThread.java:185)

 

其它線程：

"Thread-2169" daemon prio=10 tid=0x0000000050ba0000 nid=0x6480 waiting for monitor entry [0x0000000044bf1000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:185)
        - waiting to lock <0x00002aaab5838af0> (a org.apache.log4j.spi.RootCategory)
        at org.apache.log4j.Category.forcedLog(Category.java:372)
        at org.apache.log4j.Category.info(Category.java:674)
        at com.wps.www.oaas.ftr.dispatcher.task.XLiveIndexWorker_Optimize.doIndex(XLiveIndexWorker_Optimize.java:278)
        at com.wps.www.oaas.ftr.dispatcher.task.XLiveIndexWorker_Optimize.doIndexes(XLiveIndexWorker_Optimize.java:185)
        at com.wps.www.oaas.ftr.dispatcher.task.XLiveTaskWorker.doWork(XLiveTaskWorker.java:23)
        at com.wps.www.oaas.ftr.dispatcher.node.NodeThread.doWork(NodeThread.java:256)
        at com.wps.www.oaas.ftr.dispatcher.node.NodeThread.run(NodeThread.java:185)