0002161: Resin Pro startup very slow

Mantis - Resin
Viewing Issue Advanced Details

ID:	Category:	Severity:	Reproducibility:	Date Submitted:	Last Update:
2161		minor	always	11-09-07 22:21	12-31-07 09:26

Reporter:	koreth	Platform:
Assigned To:	ferg	OS:
Priority:	normal	OS Version:
Status:	closed	Product Version:	3.1.4
Product Build:		Resolution:	fixed
Projection:	none
ETA:	none	Fixed in Version:	3.1.5

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.
Steps To Reproduce:
Additional Information:
Relationships
Attached Files:

Notes

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.