System.out.println eventually blocks

Question

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>

Answer 1

Well this is not a solution but some guidelines for you to investigate further.

As per Apache Ant FAQ

When Apache Ant forks a new process for example by using the , or tasks, it will also start a new thread reading from standard input and sending everything that it has read to that process. . .

In the following lines they have mentioned an issue on Unix-like systems:

This behaviour leads to strange side effects like the Ant process being suspended when a build forking new process is run as a background process on Unix-like systems.....

See the associated Bug.

Steps you can take now:

1. Update to latest version of Apache Ant
2. Update to latest version of Java.
3. If possible apply the latest patches for your OS
4. Check once whether the problem still exist when you execute application using Ant
5. If No then smile :)
6. Else try one alternative way. Try to execute your application via Java's ProcessBuilder or Runtime.getRuntime().exec() i.e. write a small application launcher code and execute your application via that.
7. If your application works then the problem is with Ant. File a bug.
8. If the application still behaves oddly then you need to further investigate your code or can think of filing Java bug.

Hope this helps. Good luck.