RoR on Jruby hangs

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Critical Critical
  • Resolution: Fixed
  • Affects Version/s: JRuby 0.9.1
  • Fix Version/s: JRuby 0.9.2
  • Component/s: None
  • Labels:
    None
  • Environment:
    Solaris 10, rails-module 0.1, java 1.5

Description

Download rails-module 0.1 from
http://recompile.net/2006/11/how_to_deploy_jruby_on_rails_a.html

java -Xint -Xmx256M -classpath ${CLASSPATH} com.sun.grizzly.rails.standalone.Main <rails-config>

Access the RoR app an pefrom and update operation - see the stack trace during the hang below.

Another issue I have seen that might be similar is that jruby/RoR app becomes extremely slow
during an the update operation and consumes excessive CPU(90+%) resources during that time.
The stack trace in that case is pretty similar to the one below.

Full thread dump Java HotSpot(TM) Server VM (1.5.0_08-b03 interpreted mode):

"Timer-2" daemon prio=10 tid=0x0030fd60 nid=0x18 in Object.wait() [0xe2c7f000..0xe2c7fc70]
at java.lang.Object.wait(Native Method)

  • waiting on <0xef4c9fd8> (a java.util.TaskQueue)
    at java.lang.Object.wait(Object.java:474)
    at java.util.TimerThread.mainLoop(Timer.java:483)
  • locked <0xef4c9fd8> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:462)

"Timer-1" daemon prio=10 tid=0x004bc6e8 nid=0x15 in Object.wait() [0xe2d7f000..0xe2d7f9f0]
at java.lang.Object.wait(Native Method)

  • waiting on <0xeed1df78> (a java.util.TaskQueue)
    at java.lang.Object.wait(Object.java:474)
    at java.util.TimerThread.mainLoop(Timer.java:483)
  • locked <0xeed1df78> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:462)

"Timer-0" daemon prio=10 tid=0x004315c0 nid=0x12 in Object.wait() [0xe2e7f000..0xe2e7f970]
at java.lang.Object.wait(Native Method)

  • waiting on <0xee551de8> (a java.util.TaskQueue)
    at java.lang.Object.wait(Object.java:474)
    at java.util.TimerThread.mainLoop(Timer.java:483)
  • locked <0xee551de8> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:462)

"httpWorkerThread-3000-4" daemon prio=10 tid=0x0030c2a8 nid=0xf in Object.wait() [0xe307f000..0xe307faf0]
at java.lang.Object.wait(Native Method)

  • waiting on <0xee552348> (a com.sun.enterprise.web.connector.grizzly.LinkedListPipeline)
    at java.lang.Object.wait(Object.java:474)
    at com.sun.enterprise.web.connector.grizzly.LinkedListPipeline.getTask(LinkedListPipeline.java:278)
  • locked <0xee552348> (a com.sun.enterprise.web.connector.grizzly.LinkedListPipeline)
    at com.sun.enterprise.web.connector.grizzly.WorkerThreadImpl.run(WorkerThreadImpl.java:101)

"httpWorkerThread-3000-3" daemon prio=10 tid=0x00244300 nid=0xe runnable [0xe317a000..0xe317fb70]
at sun.nio.ch.FileDispatcher.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
at sun.nio.ch.IOUtil.read(IOUtil.java:206)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:207)

  • locked <0xef4ca0a8> (a java.lang.Object)
    at org.jruby.util.IOHandlerNio.fillInBuffer(IOHandlerNio.java:196)
    at org.jruby.util.IOHandlerNio.read(IOHandlerNio.java:264)
    at org.jruby.RubyIO.read(RubyIO.java:975)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at org.jruby.internal.runtime.methods.ReflectedMethod.internalCall(ReflectedMethod.java:103)
    at org.jruby.internal.runtime.methods.AbstractMethod.call(AbstractMethod.java:58)
    at org.jruby.RubyObject.callMethod(RubyObject.java:379)
    at org.jruby.RubyObject.callMethod(RubyObject.java:331)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:305)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:1070)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:869)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:222)
    at org.jruby.RubyObject.eval(RubyObject.java:453)
    at org.jruby.internal.runtime.methods.DefaultMethod.internalCall(DefaultMethod.java:112)
    at org.jruby.internal.runtime.methods.AbstractMethod.call(AbstractMethod.java:58)
    at org.jruby.RubyObject.callMethod(RubyObject.java:379)
    at org.jruby.RubyObject.callMethod(RubyObject.java:331)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:1318)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:358)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.RubyObject.eval(RubyObject.java:453)
    at org.jruby.internal.runtime.methods.DefaultMethod.internalCall(DefaultMethod.java:112)
    at org.jruby.internal.runtime.methods.AbstractMethod.call(AbstractMethod.java:58)
    at org.jruby.RubyObject.callMethod(RubyObject.java:379)
    at org.jruby.RubyObject.callMethod(RubyObject.java:331)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:679)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:1070)
    at org.jruby.evaluator.EvaluationState.setupArgs(EvaluationState.java:1539)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:296)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:818)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:222)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:812)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:222)
    at org.jruby.RubyObject.eval(RubyObject.java:453)
    at org.jruby.internal.runtime.methods.DefaultMethod.internalCall(DefaultMethod.java:112)
    at org.jruby.internal.runtime.methods.AbstractMethod.call(AbstractMethod.java:58)
    at org.jruby.RubyObject.callMethod(RubyObject.java:379)
    at org.jruby.RubyObject.callMethod(RubyObject.java:331)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:679)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:812)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:222)
    at org.jruby.RubyObject.eval(RubyObject.java:453)
    at org.jruby.internal.runtime.methods.DefaultMethod.internalCall(DefaultMethod.java:112)
    at org.jruby.internal.runtime.methods.AbstractMethod.call(AbstractMethod.java:58)
    at org.jruby.RubyObject.callMethod(RubyObject.java:379)
    at org.jruby.RubyObject.callMethod(RubyObject.java:323)
    at org.jruby.RubyObject.callInit(RubyObject.java:461)
    at org.jruby.RubyClass.newInstance(RubyClass.java:174)
    at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at org.jruby.runtime.callback.ReflectionCallback.execute(ReflectionCallback.java:140)
    at org.jruby.internal.runtime.methods.CallbackMethod.internalCall(CallbackMethod.java:79)
    at org.jruby.internal.runtime.methods.AbstractMethod.call(AbstractMethod.java:58)
    at org.jruby.RubyObject.callMethod(RubyObject.java:379)
    at org.jruby.RubyObject.callMethod(RubyObject.java:331)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:305)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.internal.runtime.methods.EvaluateCallable.internalCall(EvaluateCallable.java:67)
    at org.jruby.internal.runtime.methods.AbstractCallable.call(AbstractCallable.java:64)
    at org.jruby.runtime.ThreadContext.yieldInternal(ThreadContext.java:552)
    at org.jruby.runtime.ThreadContext.yieldCurrentBlock(ThreadContext.java:499)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:1365)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:1106)
    at org.jruby.RubyObject.eval(RubyObject.java:453)
    at org.jruby.internal.runtime.methods.DefaultMethod.internalCall(DefaultMethod.java:112)
    at org.jruby.internal.runtime.methods.AbstractMethod.call(AbstractMethod.java:58)
    at org.jruby.RubyObject.callMethod(RubyObject.java:379)
    at org.jruby.RubyObject.callMethod(RubyObject.java:331)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:679)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:841)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.RubyObject.eval(RubyObject.java:453)
    at org.jruby.internal.runtime.methods.DefaultMethod.internalCall(DefaultMethod.java:112)
    at org.jruby.internal.runtime.methods.AbstractMethod.call(AbstractMethod.java:58)
    at org.jruby.RubyObject.callMethod(RubyObject.java:379)
    at org.jruby.RubyObject.callMethod(RubyObject.java:331)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:679)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:869)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:1006)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:807)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:1106)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:648)
    at org.jruby.RubyObject.eval(RubyObject.java:453)
    at org.jruby.internal.runtime.methods.DefaultMethod.internalCall(DefaultMethod.java:112)
    at org.jruby.internal.runtime.methods.AbstractMethod.call(AbstractMethod.java:58)
    at org.jruby.RubyObject.callMethod(RubyObject.java:379)
    at org.jruby.RubyObject.callMethod(RubyObject.java:331)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:305)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:933)
    at org.jruby.evaluator.EvaluationState.eval(EvaluationState.java:222)
    at org.jruby.RubyObject.eval(RubyObject.java:453)
    at org.jruby.Ruby.loadScript(Ruby.java:863)
    at org.jruby.runtime.load.ExternalScript.load(ExternalScript.java:50)
    at org.jruby.runtime.load.LoadService.load(LoadService.java:180)
    at com.sun.grizzly.rails.RailsAdapter2.serviceRails(RailsAdapter2.java:174)
    at com.sun.grizzly.rails.RailsAdapter2.service(RailsAdapter2.java:75)
    at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.invokeAdapter(DefaultProcessorTask.java:618)
    at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.processNonBlocked(DefaultProcessorTask.java:549)
    at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.process(DefaultProcessorTask.java:790)
    at com.sun.enterprise.web.connector.grizzly.DefaultReadTask.executeProcessorTask(DefaultReadTask.java:329)
    at com.sun.enterprise.web.connector.grizzly.DefaultReadTask.doTask(DefaultReadTask.java:251)
    at com.sun.enterprise.web.connector.grizzly.DefaultReadTask.doTask(DefaultReadTask.java:205)
    at com.sun.enterprise.web.connector.grizzly.TaskBase.run(TaskBase.java:252)
    at com.sun.enterprise.web.connector.grizzly.WorkerThreadImpl.run(WorkerThreadImpl.java:103)

"httpWorkerThread-3000-2" daemon prio=10 tid=0x000d6418 nid=0xd in Object.wait() [0xe327f000..0xe327f9f0]
at java.lang.Object.wait(Native Method)

  • waiting on <0xee552348> (a com.sun.enterprise.web.connector.grizzly.LinkedListPipeline)
    at java.lang.Object.wait(Object.java:474)
    at com.sun.enterprise.web.connector.grizzly.LinkedListPipeline.getTask(LinkedListPipeline.java:278)
  • locked <0xee552348> (a com.sun.enterprise.web.connector.grizzly.LinkedListPipeline)
    at com.sun.enterprise.web.connector.grizzly.WorkerThreadImpl.run(WorkerThreadImpl.java:101)

"httpWorkerThread-3000-1" daemon prio=10 tid=0x000d5910 nid=0xc in Object.wait() [0xe337f000..0xe337fa70]
at java.lang.Object.wait(Native Method)

  • waiting on <0xee552348> (a com.sun.enterprise.web.connector.grizzly.LinkedListPipeline)
    at java.lang.Object.wait(Object.java:474)
    at com.sun.enterprise.web.connector.grizzly.LinkedListPipeline.getTask(LinkedListPipeline.java:278)
  • locked <0xee552348> (a com.sun.enterprise.web.connector.grizzly.LinkedListPipeline)
    at com.sun.enterprise.web.connector.grizzly.WorkerThreadImpl.run(WorkerThreadImpl.java:101)

"httpWorkerThread-3000-0" daemon prio=10 tid=0x001ee730 nid=0xb in Object.wait() [0xe44ff000..0xe44ff8f0]
at java.lang.Object.wait(Native Method)

  • waiting on <0xee552348> (a com.sun.enterprise.web.connector.grizzly.LinkedListPipeline)
    at java.lang.Object.wait(Object.java:474)
    at com.sun.enterprise.web.connector.grizzly.LinkedListPipeline.getTask(LinkedListPipeline.java:278)
  • locked <0xee552348> (a com.sun.enterprise.web.connector.grizzly.LinkedListPipeline)
    at com.sun.enterprise.web.connector.grizzly.WorkerThreadImpl.run(WorkerThreadImpl.java:101)

"Low Memory Detector" daemon prio=10 tid=0x00106080 nid=0x9 runnable [0x00000000..0x00000000]

"CompilerThread1" daemon prio=10 tid=0x00104fc0 nid=0x8 waiting on condition [0x00000000..0x00000000]

"CompilerThread0" daemon prio=10 tid=0x001040b0 nid=0x7 waiting on condition [0x00000000..0x00000000]

"AdapterThread" daemon prio=10 tid=0x001032d0 nid=0x6 waiting on condition [0x00000000..0x00000000]

"Signal Dispatcher" daemon prio=10 tid=0x001025c8 nid=0x5 waiting on condition [0x00000000..0x00000000]

"Finalizer" daemon prio=10 tid=0x000f5558 nid=0x4 in Object.wait() [0xfb17f000..0xfb17fa70]
at java.lang.Object.wait(Native Method)

  • waiting on <0xea181df0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
  • locked <0xea181df0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x000f4958 nid=0x3 in Object.wait() [0xfb27f000..0xfb27f8f0]
at java.lang.Object.wait(Native Method)

  • waiting on <0xea181e70> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:474)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
  • locked <0xea181e70> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x00036cc8 nid=0x1 runnable [0xffbfd000..0xffbfe358]
at sun.nio.ch.DevPollArrayWrapper.poll0(Native Method)
at sun.nio.ch.DevPollArrayWrapper.poll(DevPollArrayWrapper.java:164)
at sun.nio.ch.DevPollSelectorImpl.doSelect(DevPollSelectorImpl.java:68)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)

  • locked <0xee553830> (a sun.nio.ch.Util$1)
  • locked <0xee553840> (a java.util.Collections$UnmodifiableSet)
  • locked <0xee5537e8> (a sun.nio.ch.DevPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at com.sun.enterprise.web.connector.grizzly.SelectorThread.doSelect(SelectorThread.java:1164)
    at com.sun.enterprise.web.connector.grizzly.SelectorThread.startListener(SelectorThread.java:1145)
    at com.sun.enterprise.web.connector.grizzly.SelectorThread.startEndpoint(SelectorThread.java:1108)
    at com.sun.grizzly.rails.standalone.Main2.main(Main2.java:19)

"VM Thread" prio=10 tid=0x000e9a70 nid=0x2 runnable

"VM Periodic Task Thread" prio=10 tid=0x00107238 nid=0xa waiting on condition

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Charles Oliver Nutter added a comment -

The problem is not in JRuby, but in the way the Rails/Glassfish adapter is written. It binds a RubyIO object to the channel associated with the request, but that channel does not appear to be readable. As a result, for any post requests, Rails will block indefinitely waiting for data that never arrives.

Tom will add information about our temporary fix to the Rails adapter which should help those more knowledgeable about Grizzly/NIO come up with a better solution.

Show
Charles Oliver Nutter added a comment - The problem is not in JRuby, but in the way the Rails/Glassfish adapter is written. It binds a RubyIO object to the channel associated with the request, but that channel does not appear to be readable. As a result, for any post requests, Rails will block indefinitely waiting for data that never arrives. Tom will add information about our temporary fix to the Rails adapter which should help those more knowledgeable about Grizzly/NIO come up with a better solution.
Hide
Permalink
Thomas E Enebo added a comment -

Here is a dump of how far I got in making rails_module work with posts. Here is a more detailed breakdown:

RailsAdapter.serviceRails does a getChannel(res) which:

SocketChannelOutputBuffer buffer = (SocketChannelOutputBuffer) res.getOutputBuffer();
SocketChannel channel = buffer.getChannel();

It then creates a RubyIO based on this channel then uses it for both stdin and stdout. As far as I can tell this does not work. If you try to read on this object it endlessly returns 0 and never returns 1 (EOF). In trying to figure this out I ended up Request.doRead(ByteChunk) but I noticed that if I did this after the response channel is created then it only returns -1 and no data. If I do it above getting the response channel then doRead works. This ended up being the work-around I did. BTW This is consistent with how the servlet programming API works....not sure if Grizzly works the same way or not.

So what I have works with HTTP POSTS. I ended up stopping once I realized that This adapter is not setting status correctly on redirects. This is because in java we need to specify the return status. In my jsr223 rails demo the only solution I figured out for this was to capture the entire rails response into something then parse the response apart...then call the approriate servlet methods (like setStatus and setHeader). Doing this particular solution probably defeats the reason why you would use grizzly so I am at a loss (and I have a bunch of other stuff I need to get to).

I have included my whole modified version of rails_module as an attachment.

PS- It seems that there is another bug which I should mention. Regardless of runtimes or listeners configured it appears we end up getting five seperate sessions captured. This does not happen with webrick so it seems like it is some issue related to the interation of grizzly, rails_module, and rails/dispatch. If you run OReilley's depot application and just add the same book six times at a leisurely pace you will see what I mean...the first five adds will only show one book in the cart on sixth one ... 2 books

Show
Thomas E Enebo added a comment - Here is a dump of how far I got in making rails_module work with posts. Here is a more detailed breakdown: RailsAdapter.serviceRails does a getChannel(res) which: SocketChannelOutputBuffer buffer = (SocketChannelOutputBuffer) res.getOutputBuffer(); SocketChannel channel = buffer.getChannel(); It then creates a RubyIO based on this channel then uses it for both stdin and stdout. As far as I can tell this does not work. If you try to read on this object it endlessly returns 0 and never returns 1 (EOF). In trying to figure this out I ended up Request.doRead(ByteChunk) but I noticed that if I did this after the response channel is created then it only returns -1 and no data. If I do it above getting the response channel then doRead works. This ended up being the work-around I did. BTW This is consistent with how the servlet programming API works....not sure if Grizzly works the same way or not. So what I have works with HTTP POSTS. I ended up stopping once I realized that This adapter is not setting status correctly on redirects. This is because in java we need to specify the return status. In my jsr223 rails demo the only solution I figured out for this was to capture the entire rails response into something then parse the response apart...then call the approriate servlet methods (like setStatus and setHeader). Doing this particular solution probably defeats the reason why you would use grizzly so I am at a loss (and I have a bunch of other stuff I need to get to). I have included my whole modified version of rails_module as an attachment. PS- It seems that there is another bug which I should mention. Regardless of runtimes or listeners configured it appears we end up getting five seperate sessions captured. This does not happen with webrick so it seems like it is some issue related to the interation of grizzly, rails_module, and rails/dispatch. If you run OReilley's depot application and just add the same book six times at a leisurely pace you will see what I mean...the first five adds will only show one book in the cart on sixth one ... 2 books

People

  • Assignee:
    Thomas E Enebo
    Reporter:
    Ashish Sahni
Vote (0)
Watch (1)

Dates

  • Created:
    Updated:
    Resolved: