Apparent external-command hang due to stdin activity

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

I met the same problem.
Refer to http://jira.codehaus.org/browse/JRUBY-4626, I upgrade jre to 7,
and it works.

This forum is not affiliated to the Ruby language, Ruby on Rails framework, nor any Ruby applications discussed here.

| Privacy Policy | Terms of Service | Remote Ruby Jobs