I have a strange case where, if I press in the shell where a
certain (non-interactive) program is running under JRuby, that program
apparently hangs for some indeterminate amount of time. Pressing
again somehow allows the program to resume. I was able to to reproduce
the behavior with this example:
while true
puts “before”
ls
puts “after”
sleep 3
end
When I hit during either the first or some subsequent sleep, the
program hangs after printing the next “before”. With the example program
above, it might seem that it’s just a matter of delayed or suppressed
output; but in the real program where this behavior was first noticed,
there are multiple threads (yes, doing backtick-style external commands)
that hang, and the work they are supposed to do goes undone.
But I have only been able to reproduce this on one machine so far, so
it’s probably not a JRuby problem per se. But I thought I’d check here,
if only to find out if someone knows what might be happening.
Some facts:
- This is JRuby 1.7.3 and Java 1.6.0_24.
- On a different machine with the same JRuby & Java: no problem
- On the same machine with MRI 1.9.3p327: no problem
- On the same machine with JRuby 1.7.3 & Java 1.7.0_21: no problem
- Simple Java program doing the same as the Ruby code above: no problem
- IO.popen or Open3.popen3 instead of backtick: no problem
If anyone has any ideas, I’d be grateful. In case it’s useful, I ran
‘jstack -l’ on the ‘hung’ java process and the output, which
unfortunately isn’t enlightening to me, is included below. I do notice
that, if I don’t hit and ‘jstack -l’ the example when it’s
sleeping, the main thread is waiting on ‘a org.jruby.RubyThread’, while
in the hung state, it’s waiting on ‘a
org.jruby.util.ShellLauncher$StreamPumper’.
thanks,
paul
2013-05-09 13:31:23
Full thread dump OpenJDK 64-Bit Server VM (20.0-b12 mixed mode):
“Attach Listener” daemon prio=10 tid=0x00002acd4c001000 nid=0x4bfb
waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
“Thread-6” daemon prio=10 tid=0x00002accc0206000 nid=0x4aaa runnable
[0x00002acccad03000]
java.lang.Thread.State: RUNNABLE
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(FileInputStream.java:236)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
- locked <0x0000000788201dc8> (a java.io.BufferedInputStream)
at org.jruby.util.IOInputStream.read(IOInputStream.java:106)
at
org.jruby.util.ShellLauncher$StreamPumper.run(ShellLauncher.java:1375)
Locked ownable synchronizers:
- None
“Low Memory Detector” daemon prio=10 tid=0x00002accc00b8000 nid=0x4a82
runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
“C2 CompilerThread1” daemon prio=10 tid=0x00002accc00b5800 nid=0x4a81
waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
“C2 CompilerThread0” daemon prio=10 tid=0x00002accc00b2800 nid=0x4a80
waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
“Signal Dispatcher” daemon prio=10 tid=0x00002accc00b1000 nid=0x4a7f
runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
“Finalizer” daemon prio=10 tid=0x00002accc0092800 nid=0x4a7d in
Object.wait() [0x00002acd34228000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007881d8070> (a
java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133) - locked <0x00000007881d8070> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)
Locked ownable synchronizers:
- None
“Reference Handler” daemon prio=10 tid=0x00002accc0090800 nid=0x4a7c in
Object.wait() [0x00002acd34127000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007881d00e0> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133) - locked <0x00000007881d00e0> (a java.lang.ref.Reference$Lock)
Locked ownable synchronizers:
- None
“main” prio=10 tid=0x00002accc0007000 nid=0x4a68 in Object.wait()
[0x00002accbfff3000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000784319e28> (a
org.jruby.util.ShellLauncher$StreamPumper)
at java.lang.Thread.join(Thread.java:1203) - locked <0x0000000784319e28> (a
org.jruby.util.ShellLauncher$StreamPumper)
at java.lang.Thread.join(Thread.java:1256)
at org.jruby.util.ShellLauncher.handleStreams(ShellLauncher.java:1497)
at org.jruby.util.ShellLauncher.runAndWaitPid(ShellLauncher.java:544)
at org.jruby.RubyKernel.backquote(RubyKernel.java:1541)
at
org.jruby.RubyKernel$INVOKER$s$1$0$backquote.call(RubyKernel$INVOKER$s$1$0$backquote.gen)
at
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)
at hang.file(hang.rb:3)
at hang.load(hang.rb)
at org.jruby.Ruby.runScript(Ruby.java:815)
at org.jruby.Ruby.runScript(Ruby.java:808)
at org.jruby.Ruby.runNormally(Ruby.java:679)
at org.jruby.Ruby.runFromMain(Ruby.java:528)
at org.jruby.Main.doRunFromMain(Main.java:390)
at org.jruby.Main.internalRun(Main.java:279)
at org.jruby.Main.run(Main.java:221)
at org.jruby.Main.main(Main.java:201)
Locked ownable synchronizers:
- None
“VM Thread” prio=10 tid=0x00002accc008b800 nid=0x4a7b runnable
“GC task thread#0 (ParallelGC)” prio=10 tid=0x00002accc0011800
nid=0x4a69 runnable
“GC task thread#1 (ParallelGC)” prio=10 tid=0x00002accc0013800
nid=0x4a6a runnable
“GC task thread#2 (ParallelGC)” prio=10 tid=0x00002accc0015800
nid=0x4a6b runnable
“GC task thread#3 (ParallelGC)” prio=10 tid=0x00002accc0017800
nid=0x4a6c runnable
“GC task thread#4 (ParallelGC)” prio=10 tid=0x00002accc0019000
nid=0x4a6d runnable
“GC task thread#5 (ParallelGC)” prio=10 tid=0x00002accc001b000
nid=0x4a6e runnable
“GC task thread#6 (ParallelGC)” prio=10 tid=0x00002accc001d000
nid=0x4a6f runnable
“GC task thread#7 (ParallelGC)” prio=10 tid=0x00002accc001e800
nid=0x4a70 runnable
“GC task thread#8 (ParallelGC)” prio=10 tid=0x00002accc0020800
nid=0x4a71 runnable
“GC task thread#9 (ParallelGC)” prio=10 tid=0x00002accc0022800
nid=0x4a72 runnable
“GC task thread#10 (ParallelGC)” prio=10 tid=0x00002accc0024000
nid=0x4a73 runnable
“GC task thread#11 (ParallelGC)” prio=10 tid=0x00002accc0026000
nid=0x4a74 runnable
“GC task thread#12 (ParallelGC)” prio=10 tid=0x00002accc0028000
nid=0x4a75 runnable
“GC task thread#13 (ParallelGC)” prio=10 tid=0x00002accc0029800
nid=0x4a76 runnable
“GC task thread#14 (ParallelGC)” prio=10 tid=0x00002accc002b800
nid=0x4a77 runnable
“GC task thread#15 (ParallelGC)” prio=10 tid=0x00002accc002d800
nid=0x4a78 runnable
“GC task thread#16 (ParallelGC)” prio=10 tid=0x00002accc002f000
nid=0x4a79 runnable
“GC task thread#17 (ParallelGC)” prio=10 tid=0x00002accc0031000
nid=0x4a7a runnable
“VM Periodic Task Thread” prio=10 tid=0x00002accc00c2800 nid=0x4a83
waiting on condition
JNI global references: 950