Forum: JRuby apparent external-command hang due to stdin activity

7d56b4e7f599c20e933f6d90ab2c0e21?d=identicon&s=25 Paul Madden (Guest)
on 2013-05-09 16:55
(Received via mailing list)
I have a strange case where, if I press <enter> in the shell where a
certain (non-interactive) program is running under JRuby, that program
apparently hangs for some indeterminate amount of time. Pressing <enter>
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 <enter> 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 <enter> 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
82489be3a67a4ed95d4281efae65110a?d=identicon&s=25 Ikari Shinji (tachikoma)
on 2013-10-11 16:25
I met the same problem.
Refer to http://jira.codehaus.org/browse/JRUBY-4626, I upgrade jre to 7,
and it works.
This topic is locked and can not be replied to.