我有点困惑。
我有两个线程写入System.err（和System.out），最终它们被困在线程锁中。真的不是线程安全的System.err吗？System.out
此时程序的结构是：
- 主线程已经启动了两个
Reader线程来进行一些处理和打印输出，通过ThreadPoolExecutor. - 一个
Reader线程（“s3gp-2”）System.err.format()在IOStats名为IOStats.add(). - 另一个
Reader被（正确）阻塞的线程试图调用IOStats.add()被阻塞的相同方法System.err.format()。
请注意，每个Reader通常都写入System.err和System.out。
我应该有一个单独的单例对象来使用同步方法处理所有输出吗？像往常一样，任何见解都非常感谢。
更新
我意识到我应该提供更多上下文：Greenplum DB 的所有 n 段（通过 a create external web table ... execute prgm）并行调用 java 程序。锁定行为极为罕见，通常一切顺利。当问题发生时，所有n个进程都被阻塞。我只关注其中一个进行调试。
还有一些注意事项：
- 有几分钟，我认为我也使用的事实
log4j.Logger可能会造成麻烦。但是，事实上，该程序没有使用控制台附加程序，所以我不太倾向于认为这是问题所在。 - 使用
lsof以及ls -l /proc/$pid/fd，我观察到java进程的stderr被阻塞在postgres也读取的管道中。正如一位评论者所建议的那样，这个管道可能实际上并没有被 postgres 排干，并且阻止了System.err打印输出。
事实上，这里是相关的行：
% lsof | head -1
COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME
% lsof | grep $pid | grep ' 2w '
java 10047 gpadmin 2w FIFO 0,6 26854739 pipe
% lsof | grep $pid | grep ' 2w '
java 10047 gpadmin 2w FIFO 0,6 26854739 pipe
% node=26854739
% lsof | grep $node
postgres 10028 gpadmin 26r FIFO 0,6 26854739 pipe
sh 10046 gpadmin 2w FIFO 0,6 26854739 pipe
java 10047 gpadmin 2w FIFO 0,6 26854739 pipe
详细信息：堆栈转储（jstack -l pid）给了我：
2012-04-17 12:23:02
Full thread dump Java HotSpot(TM) 64-Bit Server VM (21.0-b17 mixed mode):
"Attach Listener" daemon prio=10 tid=0x00000000061a3800 nid=0x75c5 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"s3gp-2" prio=10 tid=0x00002aaabc207000 nid=0x281f runnable [0x0000000041718000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:318)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
- locked <0x00000000f601c4f8> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:482)
- locked <0x00000000f601c4d8> (a java.io.PrintStream)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
- locked <0x00000000f601c6f0> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
at java.io.PrintStream.write(PrintStream.java:527)
- locked <0x00000000f601c4d8> (a java.io.PrintStream)
at java.io.PrintStream.print(PrintStream.java:669)
at java.io.PrintStream.append(PrintStream.java:1065)
at java.io.PrintStream.append(PrintStream.java:57)
at java.util.Formatter$FixedString.print(Formatter.java:2563)
at java.util.Formatter.format(Formatter.java:2476)
at java.io.PrintStream.format(PrintStream.java:970)
- locked <0x00000000f601c4d8> (a java.io.PrintStream)
at com.foo.serv.util.Loader$IOStats.add(Loader.java:136)
- locked <0x00000000f6015870> (a com.foo.serv.util.Loader$IOStats)
at com.foo.serv.util.Loader$Reader.run(Loader.java:199)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
Locked ownable synchronizers:
- <0x00000000f6024470> (a java.util.concurrent.ThreadPoolExecutor$Worker)
"s3gp-1" prio=10 tid=0x00002aaabc1fa000 nid=0x281e waiting for monitor entry [0x00000000405d9000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.foo.serv.util.Loader$IOStats.add(Loader.java:129)
- waiting to lock <0x00000000f6015870> (a com.foo.serv.util.Loader$IOStats)
at com.foo.serv.util.Loader$Reader.run(Loader.java:199)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
Locked ownable synchronizers:
- <0x00000000f601ea50> (a java.util.concurrent.ThreadPoolExecutor$Worker)
"Service Thread" daemon prio=10 tid=0x00002aaab0054000 nid=0x27e7 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"C2 CompilerThread1" daemon prio=10 tid=0x00002aaab0051800 nid=0x27e6 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"C2 CompilerThread0" daemon prio=10 tid=0x00002aaab004e800 nid=0x27e4 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"Signal Dispatcher" daemon prio=10 tid=0x00002aaab004c000 nid=0x27e3 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"Finalizer" daemon prio=10 tid=0x00002aaab0001000 nid=0x2762 in Object.wait() [0x00000000428cc000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000f6015730> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
- locked <0x00000000f6015730> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)
Locked ownable synchronizers:
- None
"Reference Handler" daemon prio=10 tid=0x0000000005edc800 nid=0x2760 in Object.wait() [0x00000000427cb000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000f603b9c0> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
- locked <0x00000000f603b9c0> (a java.lang.ref.Reference$Lock)
Locked ownable synchronizers:
- None
"main" prio=10 tid=0x0000000005e3f800 nid=0x2744 waiting on condition [0x0000000041abe000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000f61df188> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
at java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1433)
at com.foo.serv.util.Loader.execute(Loader.java:107)
at com.foo.serv.util.Loader.main(Loader.java:571)
Locked ownable synchronizers:
- None
"VM Thread" prio=10 tid=0x0000000005ed5000 nid=0x275e runnable
"GC task thread#0 (ParallelGC)" prio=10 tid=0x0000000005e4a000 nid=0x2745 runnable
"GC task thread#1 (ParallelGC)" prio=10 tid=0x0000000005e4c000 nid=0x2746 runnable
"GC task thread#2 (ParallelGC)" prio=10 tid=0x0000000005e4e000 nid=0x2747 runnable
"GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000005e4f800 nid=0x2748 runnable
"GC task thread#4 (ParallelGC)" prio=10 tid=0x0000000005e51800 nid=0x2749 runnable
"GC task thread#5 (ParallelGC)" prio=10 tid=0x0000000005e53800 nid=0x274a runnable
"GC task thread#6 (ParallelGC)" prio=10 tid=0x0000000005e55000 nid=0x274b runnable
"GC task thread#7 (ParallelGC)" prio=10 tid=0x0000000005e57000 nid=0x274c runnable
"GC task thread#8 (ParallelGC)" prio=10 tid=0x0000000005e59000 nid=0x274d runnable
"GC task thread#9 (ParallelGC)" prio=10 tid=0x0000000005e5b000 nid=0x274e runnable
"GC task thread#10 (ParallelGC)" prio=10 tid=0x0000000005e5c800 nid=0x274f runnable
"GC task thread#11 (ParallelGC)" prio=10 tid=0x0000000005e5e800 nid=0x2750 runnable
"GC task thread#12 (ParallelGC)" prio=10 tid=0x0000000005e60800 nid=0x2751 runnable
"VM Periodic Task Thread" prio=10 tid=0x00002aaab005e800 nid=0x27eb waiting on condition
JNI global references: 207