Hi Vivek,
I noticed something interesting in the production.log file. I'd said before
that the RoR application froze after a lengthy idle time, and it seems this
isn't correct. What's happening is that the first request after idle takes
a very long time to execute. Here's the 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)
And here's a snippet from database.yml:
production:
adapter: <%= jdbc %>mysql
encoding: utf8
database: myapp_production
host: 172.0.0.223
username: myacct
password: mypass
reconnect: true
pool: 100
Any suggestions?
Thanks,
Mark
On Mon, Nov 16, 2009 at 2:51 PM, Vivek Pandey <Vivek.Pandey_at_sun.com> wrote:
> Mark Westling wrote:
>
>> Hi Vivek,
>>
>> I've opened an issue on RubyForge as you suggested. gfrake didn't help;
>> in fact, I can reproduce the errors using a newly created rails app. So, I
>> suspect it's some kind of configuration problem. (I did check and I'm using
>> rubygem 1.3.5).
>>
>> I just posted on your bug. I see you are using jdk 6 u18 EA. The
> exception is form xml parser which is part of jdk 6. Can you try with jdk6
> u17.
>
> Going back to the original problem (connection freezing after a long
>> idle), should I paste a thread dump (from 0.9.5, obviously) here on the list
>> or open another issue?
>>
>> You can paste it here.
>
> -vivek.
>
> Thanks!
>> Mark
>>
>>
>>
>> On Thu, Nov 12, 2009 at 2:13 PM, Vivek Pandey <Vivek.Pandey_at_sun.com<mailto:
>> Vivek.Pandey_at_sun.com>> wrote:
>>
>> I double checked the tests and see everything working just fine.
>>
>> I am not doubting this as an issue at your end but will mention it
>> anyway, since 0.9.6.dev has (dev) suffix, which gem treats as
>> pre-release version. There are issues using the prerelease
>> versions with rubygem < 1.3.5. So I would recommend doing
>>
>> gem update --system
>>
>> This will update your rubygem to 1.3.5 and 0.9.6.dev after
>> installed will be identified as the latest version.
>>
>> You can open an issue ticket at
>> http://rubyforge.org/projects/glassfishgem/. Also provide steps on
>> how I can reproduce it.
>>
>> -vivek.
>>
>>
>> Vivek Pandey wrote:
>>
>> Hmm. Our tests are running fine with this gem. I guess I know
>> what might be happening.
>>
>> Can you try
>>
>> $ gfrake clean
>>
>> and then run your application. This new glassfish gem is
>> supposed to cleanup previous tmp/.glassfish left from previous
>> gem run maybe there is some bug and thats what is causing this
>> failure.
>>
>> I will spend some time tomorrow to investigate whats going on
>> with daemon mode. Some resource injection seem to be failing.
>>
>> -vivek.
>>
>> Mark Westling wrote:
>>
>> Thanks Vivek, I installed the build#120 version of the gem
>> (0.9.6.dev) but now I'm running into other problems.
>>
>> When I set the glassfish.yml configuration to run in
>> daemon mode (enable: true), I get the following in the
>> production.log file:
>>
>> Nov 12, 2009 4:05:53 AM
>> com.sun.enterprise.v3.server.SystemTasks
>> setSystemPropertiesFromEnv
>> SEVERE: cannot determine host name, will use localhost
>> exclusively
>> java.net.UnknownHostException:
>> mobileadapp02.myclient-domain.com
>> <http://mobileadapp02.myclient-domain.com>
>> <http://mobileadapp02.myclient-domain.com>: mobileadapp02.
>> myclient-domain.com <http://myclient-domain.com>
>> <http://myclient-domain.com>
>> at
>> java.net.InetAddress.getLocalHost(InetAddress.java:1353)
>> at
>>
>> com.sun.enterprise.util.net.NetUtils.getCanonicalHostName(NetUtils.java:95)
>>
>> at
>>
>> com.sun.enterprise.v3.server.SystemTasks.setSystemPropertiesFromEnv(SystemTasks.java:152)
>>
>> [...]
>> at org.jruby.Main.run(Main.java:117)
>> at org.jruby.Main.main(Main.java:97)
>> Nov 12, 2009 4:24:35 AM
>> com.sun.enterprise.v3.server.AppServerStartup run
>> INFO: GlassFish v3 startup time : Embedded(200ms) startup
>> services(161ms) total(361ms)
>> Nov 12, 2009 4:24:35 AM AppServerStartup run
>> INFO: [Thread[GlassFish Kernel Main Thread,5,main]] started
>> Nov 12, 2009 4:24:35 AM
>> org.hibernate.validator.util.Version <clinit>
>> INFO: Hibernate Validator null
>> Nov 12, 2009 4:24:35 AM
>> com.sun.enterprise.v3.services.impl.GrizzlyProxy$2$1 onReady
>> INFO: Grizzly Framework 1.9.18-e started in: 81ms
>> listening on port 80
>> Nov 12, 2009 4:24:35 AM
>> com.sun.enterprise.v3.server.ApplicationLifecycle
>> startContainers
>> SEVERE: Cannot start container jruby
>> java.lang.NullPointerException
>> ser.java:104)
>> at
>>
>> org.glassfish.scripting.jruby.JRubyContainer.postConstruct(JRubyContainer.java:97)
>>
>> at
>>
>> com.sun.hk2.component.AbstractWombImpl.inject(AbstractWombImpl.java:174)
>> at
>>
>> com.sun.hk2.component.ConstructorWomb$1.run(ConstructorWomb.java:87)
>> at
>> java.security.AccessController.doPrivileged(Native Method)
>> at
>>
>> com.sun.hk2.component.ConstructorWomb.initialize(ConstructorWomb.java:84)
>>
>> [...]
>> at org.jruby.Main.run(Main.java:272)
>> at org.jruby.Main.run(Main.java:117)
>> at org.jruby.Main.main(Main.java:97)
>> Nov 12, 2009 4:24:35 AM org.glassfish.api.ActionReport failure
>> SEVERE: Aborting, Failed to start container
>> org.glassfish.scripting.jruby.JRubyContainer
>> Nov 12, 2009 4:24:35 AM org.glassfish.api.ActionReport failure
>> SEVERE: Exception while deploying the app
>> java.lang.Exception: Aborting, Failed to start container
>> org.glassfish.scripting.jruby.JRubyContainer
>> at
>>
>> com.sun.enterprise.v3.server.ApplicationLifecycle.setupContainerInfos(ApplicationLifecycle.java:448)
>>
>> at
>>
>> com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:246)
>>
>> at
>>
>> org.glassfish.kernel.embedded.EmbeddedDeployerImpl.deploy(EmbeddedDeployerImpl.java:206)
>>
>> at
>>
>> org.glassfish.kernel.embedded.EmbeddedDeployerImpl.deploy(EmbeddedDeployerImpl.java:146)
>>
>> at
>>
>> org.glassfish.scripting.gem.GlassFishMain.startGlassFishEmbedded(GlassFishMain.java:145)
>>
>> [...]
>>
>>
>> If I change it to non-daemon mode (enable: false), I get
>> the following on the console:
>>
>> [root_at_mobileadapp02 sched2]# jruby -S glassfish
>> Parsing config file:
>> /usr/local/sigma/sched2/config/glassfish.yml
>> Starting GlassFish server at: 0.0.0.0:80
>> <http://0.0.0.0:80> <http://0.0.0.0:80> in production
>>
>> environment...
>> Writing log messages to:
>> /usr/local/sigma/sched2/log/production.log.
>> Press Ctrl+C to stop.
>> java.lang.UnsupportedOperationException: Cannot create
>> XMLStreamReader or XMLEventReader from a
>> javax.xml.transform.stream.StreamSource
>> at
>>
>> com.sun.xml.internal.stream.XMLInputFactoryImpl.jaxpSourcetoXMLInputSource(XMLInputFactoryImpl.java:285)
>>
>> at
>>
>> com.sun.xml.internal.stream.XMLInputFactoryImpl.createXMLStreamReader(XMLInputFactoryImpl.java:145)
>>
>> at
>> org.jvnet.hk2.config.ConfigParser.parse(ConfigParser.java:102)
>> at
>>
>> org.glassfish.kernel.config.DefaultConfigParser$2.run(DefaultConfigParser.java:93)
>>
>> [...]
>>
>>
>> Any suggestions?
>>
>> Thanks,
>> Mark
>>
>>
>> On Wed, Nov 11, 2009 at 9:46 AM, Vivek Pandey
>> <Vivek.Pandey_at_sun.com <mailto:Vivek.Pandey_at_sun.com>
>> <mailto:Vivek.Pandey_at_sun.com
>> <mailto:Vivek.Pandey_at_sun.com>>> wrote:
>>
>> Mark,
>>
>> Just looking at the warning message I can say what
>> really might be
>> going on. Perhaps someone from grizzly team can comment
>> on this
>> particular issue.
>>
>> In the meantime can you give the latest glassfish gem (not
>> released yet) a try? It will be released soon after
>> more testing
>> but it has latest stable Grizzly and glassfish v3
>> kernel bits. I
>> think its worth a try. Get build#120 from
>> http://hudson.glassfish.org/job/glassfish-gem-build/.
>>
>> If the latest gem does not fix your problem, can you
>> send the
>> thread dump? kill -QUIT pid or ctrl + \
>>
>> -vivek.
>>
>>
>>
>> Mark Westling wrote:
>>
>> I'm running my Rails project using the Glassfish v3
>> gem and if
>> there's no activity for an hour or two hours, the
>> next request
>> hangs and logs the following error:
>>
>> Nov 11, 2009 3:15:44 AM
>> com.sun.grizzly.config.GrizzlyServiceListener
>> WARNING: Interrupting idle Thread:
>> http80-WorkerThread(0)
>>
>> I'm using the default parameters in the glassfish.yml
>> configuration file. This occurs in both daemon and
>> non-daemon
>> mode. The only unusual thing I might be doing is
>> creating (and
>> closing) several processing threads during some
>> requests to
>> take advantage of multiple cores for lengthy
>> computations, but
>> the problem seems to occur even if I don't run any
>> thread-creation processes after a restart. In
>> other words, I
>> can restart glassfish, wait a few hours with no
>> requests, and
>> see the same error.
>>
>> Configuration:
>> jruby 1.4.0 (ruby 1.8.7 patchlevel 174) (2009-11-02
>> 69fbfa3)
>> (Java HotSpot(TM) Client VM 1.6.0_18-ea) [i386-java]
>> rails 2.3.3
>> glassfish gem 0.9.5
>> database adapter: jdbcmysql
>> Linux version 2.6.18-164.el5PAE
>> (mockbuild_at_x86-002.build.bos.redhat.com
>> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>
>> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
>> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>>
>> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
>> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>
>> <mailto:mockbuild_at_x86-002.build.bos.redhat.com
>> <mailto:mockbuild_at_x86-002.build.bos.redhat.com>>>) (gcc
>> version
>> 4.1.2 20080704 (Red Hat 4.1.2-46)) #1 SMP
>>
>> Any suggestions?
>>
>> --Mark
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail:
>> webtier-unsubscribe_at_glassfish.dev.java.net
>> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>
>> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net
>> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>>
>> For additional commands, e-mail:
>> webtier-help_at_glassfish.dev.java.net
>> <mailto:webtier-help_at_glassfish.dev.java.net>
>> <mailto:webtier-help_at_glassfish.dev.java.net
>> <mailto:webtier-help_at_glassfish.dev.java.net>>
>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail:
>> webtier-unsubscribe_at_glassfish.dev.java.net
>> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>
>> For additional commands, e-mail:
>> webtier-help_at_glassfish.dev.java.net
>> <mailto:webtier-help_at_glassfish.dev.java.net>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: webtier-unsubscribe_at_glassfish.dev.java.net
>> <mailto:webtier-unsubscribe_at_glassfish.dev.java.net>
>> For additional commands, e-mail:
>> webtier-help_at_glassfish.dev.java.net
>> <mailto:webtier-help_at_glassfish.dev.java.net>
>>
>>
>>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: webtier-unsubscribe_at_glassfish.dev.java.net
> For additional commands, e-mail: webtier-help_at_glassfish.dev.java.net
>
>