System.out.println 最终会阻塞

发布于 2024-11-04 15:17:45 字数 2455 浏览 5 评论 0原文

我有一个应用程序，它将所有日志记录合并到一个单实例类中，以便于选择性调试打印等。该类已经存在一年左右，工作顺利，但最近我碰巧将日志级别提高到它的最高设置（我很少这样做）和标准输出似乎最终会被阻止。这会在下次代码的其他部分调用 println 或尝试使用日志记录类（该类被阻止等待 println 返回）时造成严重破坏。

我的第一个想法是我的日志记录类存在某种并发问题，但是搜索堆栈跟踪让我确信我的同步工作正常，并且在任何给定时间只有一个线程尝试写入控制台。下面是有问题的线程上的示例堆栈跟踪：

Thread [Thread-127] (Suspended) 
    FileOutputStream.writeBytes(byte[], int, int) line: not available [native method] [local variables unavailable] 
    FileOutputStream.write(byte[], int, int) line: 260  
    BufferedOutputStream.flushBuffer() line: 65 
    BufferedOutputStream.flush() line: 123  
    PrintStream.write(byte[], int, int) line: 432   
    StreamEncoder.writeBytes() line: 202    
    StreamEncoder.implFlushBuffer() line: 272   
    StreamEncoder.flushBuffer() line: 85    
    OutputStreamWriter.flushBuffer() line: 168  
    PrintStream.write(String) line: 477 
    PrintStream.print(String) line: 619 
    PrintStream.println(String) line: 756   
    Logger(Logger).LogMessage(String) line: 180 
    RemoteConsoleMonitor$1.run() line: 56   
    Thread.run() line: 662

深入研究本机堆栈跟踪，我发现 JVM 进程在 Windows 本机 ZwWriteFile 调用上阻塞。我最好的猜测是，JVM 正在使用配置为同步读取/写入缓冲数据的命名管道，但读取器已以某种方式停止并让缓冲区填充。同时，写入器被阻塞，等待缓冲区空间变得可用，但这永远不会发生。这是同一线程的本机堆栈跟踪：

    ntdll.dll!_ZwWriteFile@36()  + 0x15 bytes   
    ntdll.dll!_ZwWriteFile@36()  + 0x15 bytes   
    jvm.dll!InterfaceSupport::serialize_memory(JavaThread * thread=0x00000220)  Line 40 + 0x9 bytes C++
    java.dll!writeBytes(const JNINativeInterface_ * * env=0x2ac2b13c, _jobject * this=0x3e00f204, _jobject * bytes=0x3e00f200, long off=0, long len=97, _jfieldID * fid=0x7ecee033)  Line 144 + 0x21 bytes  C
    java.dll!Java_java_io_FileOutputStream_writeBytes(const JNINativeInterface_ * * env=0x2ac2b13c, _jobject * this=0x3e00f204, _jobject * bytes=0x3e00f200, long off=0, long len=97)  Line 73 + 0x20 bytes C
0d8a3826()  
    ...

最终结果是标准输出缓冲区被填满，迟早，东西会停止写入控制台。

问题是：如果我独立运行应用程序而不是从 Apache Ant 构建脚本运行它，则无法重现该问题。所以这可能与 Ant 重定向进程输出的方式有关，但我对提交错误报告犹豫不决，因为似乎其他人之前也遇到过这个问题......而且，因为我无法得到相同的结果孤立地繁殖的行为。

关于我如何进一步追踪这个问题有什么想法或建议吗？

更新：将 Eclipse 从 3.4.2 更新到 Helios (M2) 神奇地解决了这个问题。我还可以通过从命令行而不是 UI 启动集成的 Ant 构建器来继续使用 3.4.2：

java -jar <eclipse directory>\plugins\org.eclipse.equinox.launcher_<version>.jar -application org.eclipse.ant.core.antRunner -buildfile <buildfile>

原文

I have an application that consolidates all of its logging into a single-instance class in order to facilitate selective debug printing etc. The class has been around for a year or so working smoothly, but just recently I happened to turn the log level up to its highest setting (which I rarely do) and the standard output seems to eventually block. This causes havoc the next time some other part of the code calls println, or when it tries to use the logging class (which is blocked waiting for println to return).

My first thought was that I had some sort of concurrency issue with my logging class, but scouring the stack traces reassures me that my synchronization is working correctly and that only a single thread is attempting to write to the console at any given time. Here is a sample stack trace on the offending thread:

Thread [Thread-127] (Suspended) 
    FileOutputStream.writeBytes(byte[], int, int) line: not available [native method] [local variables unavailable] 
    FileOutputStream.write(byte[], int, int) line: 260  
    BufferedOutputStream.flushBuffer() line: 65 
    BufferedOutputStream.flush() line: 123  
    PrintStream.write(byte[], int, int) line: 432   
    StreamEncoder.writeBytes() line: 202    
    StreamEncoder.implFlushBuffer() line: 272   
    StreamEncoder.flushBuffer() line: 85    
    OutputStreamWriter.flushBuffer() line: 168  
    PrintStream.write(String) line: 477 
    PrintStream.print(String) line: 619 
    PrintStream.println(String) line: 756   
    Logger(Logger).LogMessage(String) line: 180 
    RemoteConsoleMonitor$1.run() line: 56   
    Thread.run() line: 662

Digging a little deeper into the native stack traces, I found that the JVM process is blocking on the Windows native ZwWriteFile call. My best guess is that the JVM is using named pipes configured for synchronous reading/writing the buffered data, but that the reader has somehow stopped and let the buffer fill. Meanwhile the writer is blocked waiting for buffer space to become available, but this never happens. Here's the native stack trace of the same thread:

    ntdll.dll!_ZwWriteFile@36()  + 0x15 bytes   
    ntdll.dll!_ZwWriteFile@36()  + 0x15 bytes   
    jvm.dll!InterfaceSupport::serialize_memory(JavaThread * thread=0x00000220)  Line 40 + 0x9 bytes C++
    java.dll!writeBytes(const JNINativeInterface_ * * env=0x2ac2b13c, _jobject * this=0x3e00f204, _jobject * bytes=0x3e00f200, long off=0, long len=97, _jfieldID * fid=0x7ecee033)  Line 144 + 0x21 bytes  C
    java.dll!Java_java_io_FileOutputStream_writeBytes(const JNINativeInterface_ * * env=0x2ac2b13c, _jobject * this=0x3e00f204, _jobject * bytes=0x3e00f200, long off=0, long len=97)  Line 73 + 0x20 bytes C
0d8a3826()  
    ...

The end result is that the stdout buffer is getting filled up and sooner or later, stuff stops writing to the console.

Here's the catch: if I run the application standalone instead of running it from an Apache Ant build script, I can't reproduce the problem. So it might have to do with how Ant redirects the process output, but I'm hesitant to submit a bug report because it seems like someone else would have run into this issue before... and, because I can't get the same behavior to reproduce in isolation.

Any thoughts or advice on how I might go about tracking this down further?

UPDATE: Updating Eclipse from 3.4.2 to Helios (M2) magically solved the problem. I am also able to continue using 3.4.2 by launching the integrated Ant builder from the command line instead of the UI:

java -jar <eclipse directory>\plugins\org.eclipse.equinox.launcher_<version>.jar -application org.eclipse.ant.core.antRunner -buildfile <buildfile>

分享到QQ

分享到微博

如果你对这篇内容有疑问，欢迎到本站社区发帖提问参与讨论，获取更多帮助，或者扫码二维码加入 Web 技术交流群。

发布评论

需要登录才能够评论，你可以免费注册一个本站的账号。

泛滥成性 2024-11-11 15:17:45

好吧，这不是一个解决方案，而是一些供您进一步调查的指南。

根据 Apache Ant 常见问题解答

当 Apache Ant fork 一个新进程时
例如通过使用 ,
或任务，它也会
开始一个新线程读取
标准输入并发送所有内容
它已读取该进程。。 .

在下面几行中，他们提到了类 Unix 系统上的一个问题：

这种行为会导致奇怪的一面
像 Ant 进程一样的效果
当构建分叉新的时暂停
进程作为后台进程运行
在类 Unix 系统上......

请参阅相关的 Bug。

您现在可以采取的步骤：

更新到最新版本的 Apache Ant
更新到最新版本的 Java。
如果可能的话，为您的操作系统应用最新的补丁
检查一下当您使用 Ant 执行应用程序时问题是否仍然存在，
如果否，则微笑:)
否则尝试一种替代方法。尝试通过 Java 的 ProcessBuilder 或 Runtime.getRuntime().exec() 执行您的应用程序，即编写一个小型应用程序启动器代码并通过该代码执行您的应用程序。
如果您的应用程序工作正常，则问题出在 Ant 上。提交错误。
如果应用程序的行为仍然很奇怪，那么您需要进一步研究您的代码，或者可以考虑提交 Java bug。

希望这有帮助。祝你好运。