CODEWITHSUNDEEP
javajvmcpu-usageinfinite-loop
Esko Luontola
Esko Luontola

Reputation: 73645

Infinite 100% CPU usage at java.io.FileInputStream.readBytes(Native Method)

I'm right now debugging a program which has two threads per one external process, and those two threads keep on reading Process.getErrorStream() and Process.getInputStream() using a while ((i = in.read(buf, 0, buf.length)) >= 0) loop.

Sometimes when the external process crashes due to a JVM crash (see these hs_err_pid.log files), those threads which read the stdout/stderr of that external process begin consuming 100% CPU and never exit. The loop body is not being executed (I've added a logging statement there), so the infinite loop appears to be inside the native method java.io.FileInputStream.readBytes.

I've reproduced this on both Windows 7 64-bit (jdk1.6.0_30 64-bit, jdk1.7.0_03 64-bit), and Linux 2.6.18 (jdk1.6.0_21 32-bit). The code in question is here and it is used like this. See those links for the full code - here are the interesting bits:

private final byte[]              buf = new byte[256];
private final InputStream         in;
...    

int i;
while ((i = this.in.read(this.buf, 0, this.buf.length)) >= 0) {
    ...
}

The stack traces look like

"PIT Stream Monitor" daemon prio=6 tid=0x0000000008869800 nid=0x1f70 runnable [0x000000000d7ff000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:220)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:258)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
    - locked <0x00000007c89d6d90> (a java.io.BufferedInputStream)
    at org.pitest.util.StreamMonitor.readFromStream(StreamMonitor.java:38)
    at org.pitest.util.StreamMonitor.process(StreamMonitor.java:32)
    at org.pitest.util.AbstractMonitor.run(AbstractMonitor.java:19)
   Locked ownable synchronizers:
    - None

or 

"PIT Stream Monitor" daemon prio=6 tid=0x0000000008873000 nid=0x1cb8 runnable [0x000000000e3ff000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:220)
    at org.pitest.util.StreamMonitor.readFromStream(StreamMonitor.java:38)
    at org.pitest.util.StreamMonitor.process(StreamMonitor.java:32)
    at org.pitest.util.AbstractMonitor.run(AbstractMonitor.java:19)
   Locked ownable synchronizers:
    - None

With the Sysinternals Process Explorer I was able to get native stack traces of those threads. Most often, over 80% of the time, the stack trace looks like this:

ntdll.dll!NtReadFile+0xa
KERNELBASE.dll!ReadFile+0x7a
kernel32.dll!ReadFile+0x59
java.dll!handleRead+0x2c
java.dll!VerifyClassCodesForMajorVersion+0x1d1
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

This also happens quite often:

ntdll.dll!RtlNtStatusToDosErrorNoTeb+0x52
ntdll.dll!RtlNtStatusToDosError+0x23
KERNELBASE.dll!GetCurrentThreadId+0x2c
KERNELBASE.dll!CreatePipe+0x21a
kernel32.dll!ReadFile+0x59
java.dll!handleRead+0x2c
java.dll!VerifyClassCodesForMajorVersion+0x1d1
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

ntdll.dll!RtlNtStatusToDosErrorNoTeb+0x42
ntdll.dll!RtlNtStatusToDosError+0x23
KERNELBASE.dll!GetCurrentThreadId+0x2c
KERNELBASE.dll!CreatePipe+0x21a
kernel32.dll!ReadFile+0x59
java.dll!handleRead+0x2c
java.dll!VerifyClassCodesForMajorVersion+0x1d1
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

And sometimes it's executing this part of the code:

java.dll!VerifyClassCodesForMajorVersion+0xc3
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

java.dll!Java_sun_io_Win32ErrorMode_setErrorMode+0x847c
java.dll!VerifyClassCodesForMajorVersion+0xd7
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

jvm.dll!JNI_GetCreatedJavaVMs+0x1829f
java.dll!VerifyClassCodesForMajorVersion+0x128
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

jvm.dll+0x88c1
jvm.dll!JNI_GetCreatedJavaVMs+0x182a7
java.dll!VerifyClassCodesForMajorVersion+0x128
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

java.dll!VerifyClassCodesForMajorVersion+0x10b
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

jvm.dll!JNI_CreateJavaVM+0x1423
java.dll!VerifyClassCodesForMajorVersion+0x190
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

jvm.dll+0x88bf
jvm.dll!JNI_CreateJavaVM+0x147d
java.dll!VerifyClassCodesForMajorVersion+0x190
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

java.dll!VerifyClassCodesForMajorVersion+0x1aa
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

java.dll!VerifyClassCodesForMajorVersion+0x1c3
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

java.dll!VerifyClassCodesForMajorVersion+0x224
java.dll!Java_java_io_FileInputStream_readBytes+0x1d

Any ideas how to solve this problem? Is this a known problem with the JVM? Is there a workaround?

Upvotes: 24

Views: 6143

Answers (1)

henry
henry

Reputation: 6106

I've not yet been able to reproduce this locally, but the two possible workarounds might be

  • Play around with in.available().

  • Redirect stout and stderr in the external process to a socket and read this from the controlling process instead.

Upvotes: 1

Related Questions