MySQL connection extremely slow to respond after firewall disconnect

I’m running into a problem with a RoR application (using glassfish v3
gem)
that seems to be related to a firewall disconnecting inactive MySQL
connections. For the first request after a long period of inactivity,
glassfish logs an error and then the original request shows up in the
logs
with a DB time of about 15 minutes (which should be more like 15ms).

Here’s the production.log:

Nov 24, 2009 8:12:47 AM com.sun.grizzly.config.GrizzlyServiceListener
WARNING: Interrupting idle Thread: http80-WorkerThread(3)
Nov 24, 2009 8:20:07 AM com.sun.grizzly.config.GrizzlyServiceListener
INFO:

Processing HomeController#index (for at 2009-11-24 08:20:07) [GET]
Redirected to http://202.140.96.154/user_sessions/new
Filter chain halted as [:require_user] rendered_or_redirected.
Completed in 11ms (DB: 1) | 302 Found [http://202.140.96.154/]

Nov 24, 2009 8:23:12 AM com.sun.grizzly.config.GrizzlyServiceListener
INFO:

Processing HomeController#index (for at 2009-11-24 08:07:46) [GET]
Rendering template within layouts/application
Rendering home/index
Completed in 925705ms (View: 11, DB: 925676) | 200 OK [
http://202.140.96.154/]

Note the DB time of 925s. The customer has advised me that all database
queries go through a firewall that terminates idle connections but I
didn’t
think anything of this, figuring that I’d either see a DB connection
error
or there would be a reconnect that would automatically fix it.

I did a thread dump during this 925s wait period and found this thread:

“http80-WorkerThread(3)” daemon prio=10 tid=0xb31cf400 nid=0x5d25
runnable
[0xb2ff1000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
at
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
at
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
- locked <0x760a3548> (a
com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1910)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2304)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2803)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
at com.mysql.jdbc.Connection.execSQL(Connection.java:3170)
- locked <0x7609fd38> (a java.lang.Object)
at com.mysql.jdbc.Connection.execSQL(Connection.java:3099)
at com.mysql.jdbc.Statement.executeQuery(Statement.java:1169)
- locked <0x7609fd38> (a java.lang.Object)
at
jdbc_adapter.RubyJdbcConnection$6.call(RubyJdbcConnection.java:254)
at
jdbc_adapter.RubyJdbcConnection.withConnectionAndRetry(RubyJdbcConnection.java:1072)
at
jdbc_adapter.RubyJdbcConnection.executeQuery(RubyJdbcConnection.java:247)
at
jdbc_adapter.RubyJdbcConnection.execute_query(RubyJdbcConnection.java:234)
at
jdbc_adapter.RubyJdbcConnection$i_method_multi$RUBYINVOKER$execute_query.call(jdbc_adapter/RubyJdbcConnection$i_method_multi$RUBYINVOKER$execute_query.gen)
at
org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:310)
at
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:149)
at
ruby.jit.ruby.usr.local.jruby_minus_1_dot_4_dot_0.lib.ruby.gems.$1_dot_8.gems.activerecord_minus_jdbc_minus_adapter_minus_0_dot_9_dot_2.lib.active_record.connection_adapters.jdbc_adapter._execute9030225_18734324.file(jdbc_adapter.rb:569)
at
ruby.jit.ruby.usr.local.jruby_minus_1_dot_4_dot_0.lib.ruby.gems.$1_dot_8.gems.activerecord_minus_jdbc_minus_adapter_minus_0_dot_9_dot_2.lib.active_record.connection_adapters.jdbc_adapter._execute9030225_18734324.file(jdbc_adapter.rb)
at
org.jruby.ast.executable.AbstractScript.file(AbstractScript.java:51)
at
org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:187)
at
org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:330)
at
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:189)
at
ruby.jit.ruby.usr.local.jruby_minus_1_dot_4_dot_0.lib.ruby.gems.$1_dot_8.gems.activerecord_minus_jdbc_minus_adapter_minus_0_dot_9_dot_2.lib.active_record.connection_adapters.jdbc_adapter.execute5048333_18734324.block_0$RUBY$block(jdbc_adapter.rb:560)
[…]

Here are my MySQL-related gems:

activerecord-jdbc-adapter (0.9.2)
activerecord-jdbcmysql-adapter (0.9.2)
jdbc-mysql (5.0.4)

Any ideas?

–Mark

Looks like there is a known bug in MYSQL driver that does not properly
timeout connections. What happens is the MySQL server side of the
connection
times out and closes, but the MySQL client doesn’t detect this and just
sits
there…

Checkout
http://mongrel.rubyforge.org/wiki/FAQ#Q:Mongrelstopsworkingifitsleftaloneforalongtime,
maybe the workaround work for you.

-vivek.

Thanks, Vivek, but I think that’s an old bug that’s been fixed. Setting
a
value for ActiveRecord::Base.verification_timeout, which was suggested
in
the Mongrel FAQ, was removed here:
http://github.com/rails/rails/commit/7ba28726150f5d4ee3b3cb676d6b73cc3b62e186

http://github.com/rails/rails/commit/7ba28726150f5d4ee3b3cb676d6b73cc3b62e186
–Mark

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