Mantis Bugtracker
Main | My View | View Issues | Change Log | Docs
  

Viewing Issue Simple Details [ Jump to Notes ] [ View Advanced ] [ Issue History ] [ Print ]
ID Category Severity Reproducibility Date Submitted Last Update
0002161 [Resin] minor always 11-09-07 22:21 12-31-07 09:26
Reporter koreth View Status public  
Assigned To ferg
Priority normal Resolution fixed  
Status closed   Product Version 3.1.4
Summary 0002161: Resin Pro startup very slow
Description Without pro.jar in the classpath:

[22:19:02.329] 'select-manager' requires Resin Professional. See http://www.caucho.com [^] for information and licensing.
[22:19:02.330] Server[id=,cluster=app-tier] starting
[22:19:02.330]
[22:19:02.330] Mac OS X 10.5 i386
[22:19:02.330] Java 1.5.0_13-119, 32, mixed mode, MacRoman, en, Apple Inc.
[22:19:02.331] user.name: sgrimm
[22:19:02.331] resin.home = /Users/sgrimm/resin/git-trunk/
[22:19:02.331] resin.root = /Users/sgrimm/resin/git-trunk/
[22:19:02.331] resin.conf = /Users/sgrimm/resin/git-trunk/conf/resin.conf
[22:19:02.331]
[22:19:02.633] Host[] starting
[22:19:03.847] WebApp[http://localhost:8080] [^] starting
[22:19:04.054] WebApp[http://localhost:8080/ROOT-] [^] starting
[22:19:04.651] WebApp[http://localhost:8080/resin-doc] [^] starting
[22:19:04.881] WebApp[http://localhost:8080/resin-admin] [^] starting
[22:19:05.027] Socket JNI library is not available.
[22:19:05.027] Resin will still run but performance will be slower.
[22:19:05.027] To compile the Socket JNI library on Unix, use ./configure; make; make install.
[22:19:05.089] hmux listening to fvr:6800
[22:19:05.095] http listening to *:8080
[22:19:05.102] Resin started in 4399ms

With pro.jar at the head of the classpath, no other changes:

[22:20:39.858] Server[id=,cluster=app-tier] starting
[22:20:42.197]
[22:20:44.362] Mac OS X 10.5 i386
[22:20:46.478] Java 1.5.0_13-119, 32, mixed mode, MacRoman, en, Apple Inc.
[22:20:48.593] user.name: sgrimm
[22:20:50.703] resin.home = /Users/sgrimm/resin/git-trunk/
[22:20:52.815] resin.root = /Users/sgrimm/resin/git-trunk/
[22:20:54.922] resin.conf = /Users/sgrimm/resin/git-trunk/conf/resin.conf
[22:20:57.031]
[22:20:57.160] Host[] starting
[22:20:59.705] WebApp[http://localhost:8080] [^] starting
[22:21:01.867] WebApp[http://localhost:8080/ROOT-] [^] starting
[22:21:04.250] WebApp[http://localhost:8080/resin-doc] [^] starting
[22:21:06.442] WebApp[http://localhost:8080/resin-admin] [^] starting
[22:21:08.629] Socket JNI library is not available.
[22:21:08.629] Resin will still run but performance will be slower.
[22:21:08.629] To compile the Socket JNI library on Unix, use ./configure; make; make install.
[22:21:10.737] hmux listening to fvr:6800
[22:21:12.840] http listening to *:8080
[22:21:14.942] Resin started in 37149ms

However, once it's started, it seems to run at about the same speed -- this isn't an across-the-board slowdown, just a startup thing.
Additional Information
Attached Files

- Relationships

- Notes
(0002474)
koreth
11-09-07 22:23

 That should have been filed under Resin, not Quercus; sorry.
 
(0002509)
koreth
11-19-07 16:27

 This doesn't happen on Linux, I've discovered, just on OS X.
 
(0002567)
koreth
12-13-07 11:52

 Actually this does happen on Linux too; I just didn't notice because I'm running on a much faster machine.

There seems to be some database stuff happening in Resin's log code. If I kill -QUIT the JVM while Resin is printing its startup messages, the stack trace looks like this:

"main" prio=10 tid=0x0000000040116000 nid=0x2538 runnable [0x0000000040229000..0
x000000004022af70]
   java.lang.Thread.State: RUNNABLE
        at com.caucho.db.store.Store.readBlock(Store.java:466)
        at com.caucho.db.store.Store.readFragment(Store.java:791)
        at com.caucho.db.store.Inode.read(Inode.java:314)
        at com.caucho.db.store.BlobInputStream.read(BlobInputStream.java:114)
        at com.caucho.db.store.BlobInputStream.read(BlobInputStream.java:100)
        at com.caucho.db.table.BlobColumn.getString(BlobColumn.java:225)
        at com.caucho.db.table.TableIterator.getString(TableIterator.java:356)
        at com.caucho.db.sql.IdExpr.evalString(IdExpr.java:161)
        at com.caucho.db.sql.EqExpr.evalBoolean(EqExpr.java:176)
        at com.caucho.db.sql.AndExpr.evalBoolean(AndExpr.java:140)
        at com.caucho.db.sql.Expr.isSelect(Expr.java:209)
        at com.caucho.db.sql.Query.initBlockRow(Query.java:750)
        at com.caucho.db.sql.Query.nextBlock(Query.java:725)
        at com.caucho.db.sql.Query.nextTuple(Query.java:690)
        at com.caucho.db.sql.SelectQuery.execute(SelectQuery.java:196)
        at com.caucho.db.sql.SelectQuery.execute(SelectQuery.java:161)
        at com.caucho.db.jdbc.PreparedStatementImpl.execute(PreparedStatementImp
l.java:335)
        at com.caucho.db.jdbc.PreparedStatementImpl.executeQuery(PreparedStateme
ntImpl.java:302)
        at com.caucho.server.admin.PersistentLog.getNameId(PersistentLog.java:26
4)
        - locked <0x00002aaab207d918> (a com.caucho.server.admin.PersistentLog)
        at com.caucho.server.admin.PersistentLog.log(PersistentLog.java:223)
        at com.caucho.server.admin.PersistentLogHandler.publish(PersistentLogHan
dler.java:48)
        at com.caucho.log.EnvironmentLogger.log(EnvironmentLogger.java:329)
        at java.util.logging.Logger.doLog(Logger.java:494)
        at java.util.logging.Logger.log(Logger.java:517)
        at java.util.logging.Logger.info(Logger.java:1036)
        at com.caucho.server.cluster.Server.start(Server.java:1146)
        at com.caucho.server.cluster.Cluster.startServer(Cluster.java:708)
        - locked <0x00002aaab20a9928> (a com.caucho.server.cluster.Cluster)
        at com.caucho.server.cluster.ClusterServer.startServer(ClusterServer.jav
a:522)
        at com.caucho.server.resin.Resin.start(Resin.java:692)
        at com.caucho.server.resin.Resin.initMain(Resin.java:1113)
        at com.caucho.server.resin.Resin.main(Resin.java:1314)

More importantly, the slowness also seems to affect java.util.logging calls in my application code; it takes a significant fraction of a second to log two messages that should be no more than a millisecond or two apart, and I see a similar stack trace (calling into PersistentLog.getNameId()) when I kill -QUIT the VM in that state.
 
(0002568)
koreth
12-13-07 12:01

 A little more digging revealed that it's accessing files in the Resin admin/log directory. Deleting that directory and letting Resin create a new one from scratch sped things up a ton -- for example, I went from "Resin started in 8396ms" to "Resin started in 2022ms" with no other change on the system. Probably things are just slowing down progressively the bigger the files in there get. I restart Resin a ton on my test machine so maybe this is exacerbated by that.
 

- Issue History
Date Modified Username Field Change
11-09-07 22:21 koreth New Issue
11-09-07 22:23 koreth Note Added: 0002474
11-14-07 09:55 nam Project Quercus => Resin
11-19-07 16:27 koreth Note Added: 0002509
12-13-07 11:52 koreth Note Added: 0002567
12-13-07 12:01 koreth Note Added: 0002568
12-31-07 09:26 ferg Assigned To  => ferg
12-31-07 09:26 ferg Status new => closed
12-31-07 09:26 ferg Resolution open => fixed
12-31-07 09:26 ferg Fixed in Version  => 3.1.5

Mantis 1.0.0rc3[^]
Copyright © 2000 - 2005 Mantis Group
36 total queries executed.
30 unique queries executed.
Powered by Mantis Bugtracker