IO Error

Ruby JRuby
1

Has anyone seen an IO Error like this before ?
Nov 7, 2008 2:55:57 AM org.apache.catalina.core.ApplicationContext log
INFO: /!\ FAILSAFE /!\ Fri Nov 07 02:55:57 -0500 2008
Status: 500 Internal Server Error
IO Error

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:420:in
`parse_formatted_request_parameters’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/cgi_process.rb:80:in
`request_parameters’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:307:in
`parameters’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:22:in
`request_method’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:35:in
`method’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/routing/route_set.rb:431:in
`extract_request_environment’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/routing/route_set.rb:384:in
`recognize’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:148:in
`handle_request’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:107:in
`dispatch’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:104:in
`dispatch’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:120:in
`dispatch_cgi’

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:35:in
`dispatch’

file:/usr/local/tomcat/webapps/myapp/WEB-INF/lib/jruby-rack-0.9.1.jar!/rack/adapter/rails.rb:37:in
`serve_rails’

file:/usr/local/tomcat/webapps/myapp/WEB-INF/lib/jruby-rack-0.9.1.jar!/rack/adapter/rails.rb:44:in
`call’

file:/usr/local/tomcat/webapps/myapp/WEB-INF/lib/jruby-rack-0.9.1.jar!/jruby/rack/rails.rb:141:in
`call’

file:/usr/local/tomcat/webapps/myapp/WEB-INF/lib/jruby-rack-0.9.1.jar!/rack/handler/servlet.rb:17:in
`call’
:3

2

Can’t say I have…is that all the information you have?

AD wrote:

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/cgi_process.rb:80:in

`dispatch’
file:/usr/local/tomcat/webapps/myapp/WEB-INF/lib/jruby-rack-0.9.1.jar!/rack/adapter/rails.rb:37:in
:3

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email
3

Pretty much
Is this a Rails, JRuby or Tomcat specific error ?

On Sat, Nov 8, 2008 at 10:15 AM, Charles Oliver N. <

4

It does appear to be a JRuby error; that “IO Error” usually happens when
it can’t load a library or when there’s an unexpected IO problem. Since
in this case it appears to be parsing request parameters, perhaps it’s
hit an end-of-stream or something similar. Can you toss this into a bug
and we’ll try to help you investigate?

AD wrote:

AD wrote:
    `parse_formatted_request_parameters'
     /usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:35:in
     
    `dispatch'
     file:/usr/local/tomcat/webapps/myapp/WEB-INF/lib/jruby-rack-0.9.1.jar!/rack/handler/servlet.rb:17:in

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email
5

Thanks I will do. SOme additional info that we have is that there is
another java application running in the same Tomcat container that
connects
to an ActiveMQ JMS broker as a consumer. We noticed the broker was down
when this error was happening, not sure if or how it could be related
but i
guess something to note. I can try and kill the broker again to see if
I
can reproduce.
Adam

On Sat, Nov 8, 2008 at 9:28 PM, Charles Oliver N. <

6

I saw something like this about a year ago. It turned out that rails was
trying to do a rewind on request.body (i.e. $stdin), which wasn’t
supported the stream that goldspike was assigning to $stdin. Also, it
only happened with multipart forms (e.g. file uploads), IIRC.

It was a pain to debug, from what I remember. We ended up patching
request.rb to avoid the rewind and to pull multipart parameters from
$java_servlet_request instead of from body. An upgrade to jruby (we
started with 1.0.1 and use 1.1.3 now), goldspike (we started with 1.3
and use 1.6.1 now), or rails (we were using a 2.0 RC and use 2.0.1 now)
ended up resolving the problem.

HTH,
Matt

AD wrote:

/usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/cgi_process.rb:80:in

`dispatch’
file:/usr/local/tomcat/webapps/myapp/WEB-INF/lib/jruby-rack-0.9.1.jar!/rack/adapter/rails.rb:37:in
:3

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email
7

so this happened again, here is the trace of when it first occurred
Processing ApplicationController#index (for 172.24.106.10 at 2008-11-11
03:29:19) [POST]
Session ID: 5c2996cfc038ea1633d6ca22e12b1a38
Parameters:
{"\000\000\000\000\000\000\000\000\000\000\000\000\000\000"=>nil}

IOError (IO Error):
/gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:420:in
parse_formatted_request_parameters' /gems/gems/actionpack-2.1.1/lib/action_controller/cgi_process.rb:80:inrequest_parameters’
/gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:307:in
parameters' /gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:22:inrequest_method’
/gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:35:in
`method’

/gems/gems/actionpack-2.1.1/lib/action_controller/routing/route_set.rb:431:in
`extract_request_environment’

/gems/gems/actionpack-2.1.1/lib/action_controller/routing/route_set.rb:384:in
recognize' /gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:148:inhandle_request’
/gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:107:in
dispatch' /gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:104:indispatch’
/gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:120:in
dispatch_cgi' /gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:35:indispatch’
file:/lib/jruby-rack-0.9.1.jar!/rack/adapter/rails.rb:37:in
serve_rails' file:/lib/jruby-rack-0.9.1.jar!/rack/adapter/rails.rb:44:incall’
file:/lib/jruby-rack-0.9.1.jar!/jruby/rack/rails.rb:141:in call' file:/lib/jruby-rack-0.9.1.jar!/rack/handler/servlet.rb:17:incall’
:1

Then later on memory errors :

Nov 11, 2008 3:32:16 AM org.apache.catalina.core.ApplicationContext log
SEVERE: Exception caught
org.jruby.rack.RackInitializationException: library `enumerator’ could
not
be loaded: java.lang.OutOfMemoryError: GC overhead limit exceeded

    at

org.jruby.rack.DefaultRackApplicationFactory.newRuntime(DefaultRackApplicationFactory.java:85)
at
org.jruby.rack.DefaultRackApplicationFactory.createApplication(DefaultRackApplicationFactory.java:146)
at
org.jruby.rack.DefaultRackApplicationFactory.newApplication(DefaultRackApplicationFactory.java:44)
at
org.jruby.rack.DefaultRackApplicationFactory.getApplication(DefaultRackApplicationFactory.java:52)
at
org.jruby.rack.PoolingRackApplicationFactory.getApplication(PoolingRackApplicationFactory.java:92)
at
org.jruby.rack.DefaultRackDispatcher.process(DefaultRackDispatcher.java:31)
at org.jruby.rack.RackFilter.doFilter(RackFilter.java:51)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
at
org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
at
org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
at
org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:773)
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703)
at
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:895)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
at java.lang.Thread.run(Thread.java:619)
Caused by: org.jruby.exceptions.RaiseException: library `enumerator’
could
not be loaded: java.lang.OutOfMemoryError: GC overhead limit exceeded
at (unknown).initialize(:1)
at (unknown).(unknown)(:1)

8

Thanks Matt. We are on rails 2.1.1, Jruby 1.1.4 and latest warbler so
not
sure how much (aside from Jruby 1.1.5 upgrade) we can do there.
I will see if i can sniff the packets themselves for anything
suspicious.

Adam

9

Ahh, so this is probably happening because a memory cap is getting hit.
I would guess the max memory setting in Tomcat is too low for however
many apps/instances you’re running. Can you find what that default is
and possibly try to set it higher?

AD wrote:

/gems/gems/actionpack-2.1.1/lib/action_controller/request.rb:420:in

dispatch'serve_rails’
not be loaded: java.lang.OutOfMemoryError: GC overhead limit exceeded
org.jruby.rack.PoolingRackApplicationFactory.getApplication(PoolingRackApplicationFactory.java:92)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
at
could not be loaded: java.lang.OutOfMemoryError: GC overhead limit exceeded
suspicious.
to $stdin. Also, it only happened with multipart forms (e.g.
HTH,
Status: 500 Internal Server Error

        `recognize'
         /usr/local/tomcat/webapps/myapp/WEB-INF/gems/gems/actionpack-2.1.1/lib/action_controller/dispatcher.rb:120:in
         
    To unsubscribe from this list, please visit:

      http://xircles.codehaus.org/manage_email

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email
10

AD wrote:

jruby.min.runtimes 2 jruby.max.runtimes 8

You want me to increase the HEAP to see if it helps ?

Wow, not if it’s already set to 5GB. Are you possibly hitting max system
memory, forcing JVM to partially swap to disk? The GC message you got
usually means that it’s spending too much time GC’ing, which can mean
the heap is maxed (seems unlikely) or the system doesn’t have enough
free physical memory to hold the heap.

You might also want to try bumping PermSize.

We need more visibility into what the memory situation looks like when
you get this error.

  • Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email
11

Fair enough. We are running a load test this weekend so I will try to
capture this. Any specific information I should capture ? jmap, jinfo
?
vmstat ?

I guess its possible memory is being maxed, but i figured 5Gb Heap on an
8Gb
machine was pretty safe. Should I try lowering the heap ?

Thx
Adam

On Tue, Nov 11, 2008 at 3:06 PM, Charles Oliver N. <

12

Server has 4 CPUs 8GB RAM

Tomcat:
export JAVA_OPTS="-Xms5000m -Xmx5000m -XX:PermSize=256m
-XX:MaxPermSize=384m
-Dcom.sun.management.jmxremote.port=8484
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false"

-and- web.xml:

jruby.min.runtimes 2 jruby.max.runtimes 8

You want me to increase the HEAP to see if it helps ?

Adam

On Tue, Nov 11, 2008 at 1:50 PM, Charles Oliver N. <

13

AD wrote:

Fair enough. We are running a load test this weekend so I will try to
capture this. Any specific information I should capture ? jmap, jinfo
? vmstat ?

I guess its possible memory is being maxed, but i figured 5Gb Heap on an
8Gb machine was pretty safe. Should I try lowering the heap ?

You might try that…you should also be able to connect to the process
with jconsole (might need some command-line flags to enable jmx
management) and see how much heap is actually being used. That could
also show if you’ve topped off permgen.

jmap would be good, but at that size you might have a heck of a time
getting it to dump. Someone recommended an SAP memory leak tool at one
point, and I think jprofiler, while not free, also has a nice tool for
tracking memory and leaks.

Basically whatever you can get will be a big help.

  • Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email
14

Jin L. wrote:

Hi,

For what its worth, I tried using the rack servlet w/ Tomcat and I ran
into similar errors. This was a couple months ago when I was using
warbler. I switched to goldspike (it doesnt use the rack servlet I
believe) and things are much better now. This is on Tomcat 5.5

Wow, that’s not good. We need to get warbler working at least as well as
goldspike, because in general it does other things a lot better.

  • Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email
15

Hi,

For what its worth, I tried using the rack servlet w/ Tomcat and I ran
into
similar errors. This was a couple months ago when I was using warbler. I
switched to goldspike (it doesnt use the rack servlet I believe) and
things
are much better now. This is on Tomcat 5.5

Hope this helps,
Jin

16

Thanks guys. I already have the JMX flags enabled so i will try to get
JConsole running during the load test to see what is happening.
Jin, did you try moving to Glassfish or a newer Tomcat version to see if
the
issue was still there ?

Thanks
Adam

On Tue, Nov 11, 2008 at 5:24 PM, Charles Oliver N. <

17

OK, happened again, here is the jinfo output , looks like PS Young Gen
is
maxed as is PS Old Gen. Could not get jconsole to startup. System mem
seemed ok
Mem: 8177388k total, 7639248k used, 538140k free, 176432k buffers

Attaching to process ID 11503, please wait…

Debugger attached successfully.

Server compiler detected.

JVM version is 10.0-b22

using thread-local object allocation.

Parallel GC with 4 thread(s)

Heap Configuration:

MinHeapFreeRatio = 40

MaxHeapFreeRatio = 70

MaxHeapSize = 5242880000 (5000.0MB)

NewSize = 2686976 (2.5625MB)

MaxNewSize = -65536 (-0.0625MB)

OldSize = 5439488 (5.1875MB)

NewRatio = 2

SurvivorRatio = 8

PermSize = 268435456 (256.0MB)

MaxPermSize = 402653184 (384.0MB)

Heap Usage:

PS Young Generation

Eden Space:

capacity = 1109655552 (1058.25MB)

used = 1109655552 (1058.25MB)

free = 0 (0.0MB)

100.0% used

From Space:

capacity = 318963712 (304.1875MB)

used = 0 (0.0MB)

free = 318963712 (304.1875MB)

0.0% used

To Space:

capacity = 318963712 (304.1875MB)

used = 0 (0.0MB)

free = 318963712 (304.1875MB)

0.0% used

PS Old Generation

capacity = 3495297024 (3333.375MB)

used = 3495296992 (3333.374969482422MB)

free = 32 (3.0517578125E-5MB)

99.9999990844841% used

PS Perm Generation

capacity = 268435456 (256.0MB)

used = 242687160 (231.44451141357422MB)

free = 25748296 (24.55548858642578MB)

90.40801227092743% used

18

AD wrote:

OK, happened again, here is the jinfo output , looks like PS Young Gen
is maxed as is PS Old Gen. Could not get jconsole to startup. System
mem seemed ok

Yeah, this has got to be a leak of some kind. I’d say you need to
monitor the increasing heap size and either use jmap to dump some
results or use some other tool to diff subsequent snapshots to see
what’s sticking around. It sure seems like a leak though; 8 runtimes
should most definitely not take >3GB of memory.

Whether it’s a leak in JRuby or your app, we’ll have to investigate.

You might try loading it down with only a couple runtimes too and see if
it blows the heap max still.

  • Charlie

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email
19

Thanks Charles. I am getting jprofiler right now, anything specific in
JProfiler I should look for? Debugging Java Heaps is unfortunately not
my
strongest point.
Thx
Adam

On Tue, Nov 11, 2008 at 5:18 PM, Charles Oliver N. <

20

AD it would be wonderful if you busted out a wiki page based on your
experience using jprofiler with JRuby as you go. I’m going to need to do
the same thing in a couple days :slight_smile:

Mike

Charles Oliver N. wrote:

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email