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