I configured JBoss to log in debug mode.
I copy above the log registered while the user login. The user name is mantis.
As you said, it last less than 1 minute because it was not the first login, but
it last 45 seconds, too much I think.
It is very strange, because if I logged in with an administrator user it last 5
seconds, the problem is with common user whose first page after login is
Dashboards.
Here is the log resitered in debug mode, with some comments of mine:
+*- 4 seconds to authenticate against LDAP. This is ok -*+
2009-07-10 10:54:09,580 DEBUG [org.jboss.logging.Log4jService] Installed
System.out adapter
2009-07-10 10:54:09,581 DEBUG [org.jboss.logging.Log4jService] Installed
System.err adapter
2009-07-10 10:54:13,685 DEBUG
[org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter]
remote=128.0.54.216,principal=none,uri=/nuxeo/nxstartup.faces,session=B2E4FECF54FACCC02989EB856DF20658,thread=http-0.0.0.0-8080-5,info=Entering
NuxeoRequestControler filter
2009-07-10 10:54:13,685 DEBUG
[org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter]
remote=128.0.54.216,principal=none,uri=/nuxeo/nxstartup.faces,session=B2E4FECF54FACCC02989EB856DF20658,thread=http-0.0.0.0-8080-5,info=Existing
NuxeoRequestControler filter : nothing to be done
2009-07-10 10:54:13,686 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
NXLoginModule initialized
2009-07-10 10:54:13,688 DEBUG [org.nuxeo.ecm.directory.ldap.LDAPSession]
LDAPSession.getLdapEntry(mantis, false): LDAP search
base='ou=internos,dc=bcu,dc=gub,dc=uy'
filter='(&(uid={0})(&(objectClass=person)(uid=*)))' args='mantis' scope='1'
[LDAPSession '7273689667403253263' for directory userDirectory]
2009-07-10 10:54:13,813 DEBUG [org.nuxeo.ecm.directory.ldap.LDAPSession] LDAP
bind dn='uid=mantis,ou=Internos,dc=bcu,dc=gub,dc=uy'
2009-07-10 10:54:13,814 DEBUG [org.nuxeo.ecm.directory.ldap.LDAPSession] Bind
succeeded, authentication ok
+*- 1 more second for this -*+
2009-07-10 10:54:13,814 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
createIdentity: mantis
2009-07-10 10:54:13,833 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
getRoleSets
2009-07-10 10:54:13,833 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
Getting roles for user=mantis
2009-07-10 10:54:13,834 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
Found role=regular
2009-07-10 10:54:13,834 DEBUG
[org.nuxeo.ecm.core.event.tx.PostCommitSynchronousRunner] Starting sync
executor from Thread 126
2009-07-10 10:54:13,835 DEBUG
[org.nuxeo.ecm.core.event.tx.PostCommitSynchronousRunner] Start post commit
sync execution in Thread 622
2009-07-10 10:54:13,835 DEBUG
[org.nuxeo.ecm.core.event.tx.PostCommitSynchronousRunner] End of all post
commit sync executions : 0ms
2009-07-10 10:54:13,835 DEBUG
[org.nuxeo.ecm.core.event.tx.PostCommitSynchronousRunner] Terminated sync
executor from Thread 126
2009-07-10 10:54:13,836 DEBUG
[org.nuxeo.ecm.webengine.login.WebEngineSessionManager] Creating Stateful
UserSession
2009-07-10 10:54:13,836 DEBUG [org.nuxeo.ecm.webengine.session.UserSession]
Installing user session
2009-07-10 10:54:13,836 DEBUG
[org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Async listener executed,
commiting tx
2009-07-10 10:54:13,837 DEBUG
[org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Async listener executed,
commiting tx
2009-07-10 10:54:13,838 DEBUG
[org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Async listener executed,
commiting tx
2009-07-10 10:54:13,845 DEBUG
[org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Async listener executed,
commiting tx
2009-07-10 10:54:13,846 DEBUG
[org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Async listener executed,
commiting tx
2009-07-10 10:54:13,846 DEBUG
[org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Async listener executed,
commiting tx
2009-07-10 10:54:13,849 DEBUG
[javax.enterprise.resource.webcontainer.jsf.timing] [TIMING] - [12ms] :
Execution time for phase (including any PhaseListeners) -> RESTORE_VIEW 1
2009-07-10 10:54:13,849 DEBUG
[org.nuxeo.ecm.core.event.impl.AsyncEventExecutor] Async listener executed,
commiting tx
2009-07-10 10:54:13,857 DEBUG
[org.nuxeo.ecm.webapp.context.NavigationContextBean] <init>
2009-07-10 10:54:13,868 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
NXLoginModule initialized
2009-07-10 10:54:13,868 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
UserIdentificationInfoCallback is not supported
2009-07-10 10:54:13,869 DEBUG [org.nuxeo.ecm.directory.ldap.LDAPSession]
LDAPSession.getLdapEntry(mantis, false): LDAP search
base='ou=internos,dc=bcu,dc=gub,dc=uy'
filter='(&(uid={0})(&(objectClass=person)(uid=*)))' args='mantis' scope='1'
[LDAPSession '7273690449087301145' for directory userDirectory]
2009-07-10 10:54:13,892 DEBUG [org.nuxeo.ecm.directory.ldap.LDAPSession] LDAP
bind dn='uid=mantis,ou=Internos,dc=bcu,dc=gub,dc=uy'
2009-07-10 10:54:13,893 DEBUG [org.nuxeo.ecm.directory.ldap.LDAPSession] Bind
succeeded, authentication ok
+*- I don't know why it repeats the user authentication, but doesn't matter it
last less than 1 second -*+
2009-07-10 10:54:13,893 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
createIdentity: mantis
2009-07-10 10:54:13,909 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
getRoleSets
2009-07-10 10:54:13,909 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
Getting roles for user=mantis
2009-07-10 10:54:13,909 DEBUG [org.nuxeo.ecm.platform.login.NuxeoLoginModule]
Found role=regular
2009-07-10 10:54:13,910 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean]
URI: default
2009-07-10 10:54:13,910 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean]
Add caller principal to the session context....
2009-07-10 10:54:13,910 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean]
Initializing session for repository: default
2009-07-10 10:54:13,911 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] getConnection:
org.nuxeo.ecm.core.storage.sql.ra.managedconnectioni...@1355839
2009-07-10 10:54:13,911 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] addConnection:
org.nuxeo.ecm.core.storage.sql.ra.connectioni...@55c91
2009-07-10 10:54:13,912 DEBUG
[org.nuxeo.ecm.webapp.delegate.DocumentManagerBusinessDelegate] Opened session
for repository default
2009-07-10 10:54:13,920 DEBUG
[org.nuxeo.ecm.core.storage.sql.PersistenceContext] Saving persistence context
2009-07-10 10:54:13,920 DEBUG
[org.nuxeo.ecm.core.storage.sql.PersistenceContext] End of save
2009-07-10 10:54:13,920 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closeConnections:
org.nuxeo.ecm.core.storage.sql.ra.managedconnectioni...@1355839
2009-07-10 10:54:13,920 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closing connection:
org.nuxeo.ecm.core.storage.sql.ra.connectioni...@55c91
2009-07-10 10:54:13,929 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] cleanup:
org.nuxeo.ecm.core.storage.sql.ra.managedconnectioni...@1355839
2009-07-10 10:54:13,934 DEBUG
[javax.enterprise.resource.webcontainer.jsf.timing] [TIMING] - [84ms] :
Execution time for phase (including any PhaseListeners) -> RENDER_RESPONSE 6
2009-07-10 10:54:13,939 DEBUG
[org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter]
remote=128.0.54.216,principal=none,uri=/nuxeo/user_dashboard.faces,session=B2E4FECF54FACCC02989EB856DF20658,thread=http-0.0.0.0-8080-5,info=Entering
NuxeoRequestControler filter
2009-07-10 10:54:13,940 DEBUG
[org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter]
remote=128.0.54.216,principal=none,uri=/nuxeo/user_dashboard.faces,session=B2E4FECF54FACCC02989EB856DF20658,thread=http-0.0.0.0-8080-5,info=Existing
NuxeoRequestControler filter : nothing to be done
2009-07-10 10:54:13,947 DEBUG
[javax.enterprise.resource.webcontainer.jsf.timing] [TIMING] - [6ms] :
Execution time for phase (including any PhaseListeners) -> RESTORE_VIEW 1
2009-07-10 10:54:13,962 DEBUG
[org.nuxeo.ecm.webapp.pagination.ResultsProvidersCacheBean] Initializing...
2009-07-10 10:54:13,963 DEBUG
[org.nuxeo.ecm.webapp.pagination.ResultsProvidersCacheBean] Constructing a new,
empty cache
2009-07-10 10:54:14,222 DEBUG
[org.nuxeo.ecm.platform.userworkspace.api.UserWorkspaceManagerActions]
Initializing user workspace manager actions bean
*+- I think here is the problem, it last 7 seconds bettwen "bulding provider
'USER_xxx'" and "building query model 'USER_xxx'"+*
*+There are 5 buildings (USER_WORKSPACES, USER_SITES, USER_DOCUMENTS,
DOMAIN_DOCUMENTS, DOMAIN_PUBLISHED_DOCUMENTS), so 7*5=35 seconds.+*
*+This is the problem -+*
2009-07-10 10:54:14,265 DEBUG
[org.nuxeo.ecm.webapp.pagination.ResultsProvidersCacheBean] (Re)building
provider 'USER_WORKSPACES'
2009-07-10 10:54:14,267 DEBUG [org.nuxeo.ecm.core.api.ejb.DocumentManagerBean]
Initializing session for repository: default
2009-07-10 10:54:14,269 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] getConnection:
org.nuxeo.ecm.core.storage.sql.ra.managedconnectioni...@1355839
2009-07-10 10:54:14,269 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] addConnection:
org.nuxeo.ecm.core.storage.sql.ra.connectioni...@135e2ca
2009-07-10 10:54:21,261 DEBUG
[org.nuxeo.ecm.webapp.querymodel.QueryModelActionsBean] (Re)building query
model USER_WORKSPACES
2009-07-10 10:54:21,262 DEBUG
[org.nuxeo.ecm.core.search.api.client.querymodel.QueryModel] execute query:
SELECT * FROM Workspace WHERE ecm:mixinType != 'HiddenInNavigation' AND
ecm:currentLifeCycleState != 'deleted' AND NOT ecm:path STARTSWITH
'/tipem/templates' ORDER BY dc:title
2009-07-10 10:54:21,999 DEBUG
[org.nuxeo.ecm.webapp.pagination.ResultsProvidersCacheBean] (Re)building
provider 'USER_SITES'
2009-07-10 10:54:28,757 DEBUG
[org.nuxeo.ecm.webapp.querymodel.QueryModelActionsBean] (Re)building query
model USER_SITES
2009-07-10 10:54:28,758 DEBUG
[org.nuxeo.ecm.core.search.api.client.querymodel.QueryModel] execute query:
SELECT * FROM Document WHERE ecm:mixinType = 'WebView' AND
ecm:currentLifeCycleState != 'deleted' AND webc:isWebContainer = 1
AND NOT ecm:path STARTSWITH '/tipem/templates' ORDER BY webc:name
2009-07-10 10:54:29,694 DEBUG
[org.nuxeo.ecm.webapp.pagination.ResultsProvidersCacheBean] (Re)building
provider 'USER_DOCUMENTS'
2009-07-10 10:54:36,516 DEBUG
[org.nuxeo.ecm.webapp.querymodel.QueryModelActionsBean] (Re)building query
model USER_DOCUMENTS
2009-07-10 10:54:36,517 DEBUG
[org.nuxeo.ecm.core.search.api.client.querymodel.QueryModel] execute query:
SELECT * FROM Document WHERE dc:contributors = 'mantis' AND
ecm:mixinType != 'Folderish' AND ecm:mixinType != 'HiddenInNavigation' AND
ecm:isCheckedInVersion = 0 AND ecm:isProxy = 0 AND
ecm:currentLifeCycleState != 'deleted' ORDER BY dc:modified DESC
2009-07-10 10:54:36,632 DEBUG
[org.nuxeo.ecm.webapp.pagination.ResultsProvidersCacheBean] (Re)building
provider 'DOMAIN_DOCUMENTS'
2009-07-10 10:54:43,746 DEBUG
[org.nuxeo.ecm.webapp.querymodel.QueryModelActionsBean] (Re)building query
model DOMAIN_DOCUMENTS
2009-07-10 10:54:43,747 DEBUG
[org.nuxeo.ecm.core.search.api.client.querymodel.QueryModel] execute query:
SELECT * FROM Document WHERE ecm:path STARTSWITH '/tipem' AND NOT
ecm:path STARTSWITH '/tipem/templates' AND ecm:mixinType != 'Folderish'
AND ecm:mixinType != 'HiddenInNavigation' AND ecm:isCheckedInVersion =
0 AND ecm:isProxy = 0 AND ecm:currentLifeCycleState != 'deleted' ORDER
BY dc:modified DESC
2009-07-10 10:54:43,961 DEBUG
[org.nuxeo.ecm.webapp.pagination.ResultsProvidersCacheBean] (Re)building
provider 'DOMAIN_PUBLISHED_DOCUMENTS'
2009-07-10 10:54:51,287 DEBUG
[org.nuxeo.ecm.webapp.querymodel.QueryModelActionsBean] (Re)building query
model DOMAIN_PUBLISHED_DOCUMENTS
2009-07-10 10:54:51,288 DEBUG
[org.nuxeo.ecm.core.search.api.client.querymodel.QueryModel] execute query:
SELECT * FROM Document WHERE ecm:path STARTSWITH '/tipem' AND
ecm:mixinType != 'Folderish' AND ecm:mixinType != 'HiddenInNavigation' AND
ecm:isCheckedInVersion = 0 AND ecm:isProxy = 1 ORDER BY dc:modified DESC
2009-07-10 10:54:54,912 DEBUG
[org.nuxeo.ecm.core.storage.sql.PersistenceContext] Saving persistence context
2009-07-10 10:54:54,913 DEBUG
[org.nuxeo.ecm.core.storage.sql.PersistenceContext] End of save
2009-07-10 10:54:54,913 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closeConnections:
org.nuxeo.ecm.core.storage.sql.ra.managedconnectioni...@1355839
2009-07-10 10:54:54,913 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] closing connection:
org.nuxeo.ecm.core.storage.sql.ra.connectioni...@135e2ca
2009-07-10 10:54:54,926 DEBUG
[org.nuxeo.ecm.core.storage.sql.ra.ManagedConnectionImpl] cleanup:
org.nuxeo.ecm.core.storage.sql.ra.managedconnectioni...@1355839
2009-07-10 10:54:54,935 DEBUG
[javax.enterprise.resource.webcontainer.jsf.timing] [TIMING] - [40988ms] :
Execution time for phase (including any PhaseListeners) -> RENDER_RESPONSE 6
2009-07-10 10:54:55,134 DEBUG
[org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter]
remote=128.0.54.216,principal=none,uri=/nuxeo/nxthemes-css/,session=B2E4FECF54FACCC02989EB856DF20658,thread=http-0.0.0.0-8080-5,info=Entering
NuxeoRequestControler filter
2009-07-10 10:54:55,134 DEBUG
[org.nuxeo.ecm.platform.web.common.requestcontroller.filter.NuxeoRequestControllerFilter]
remote=128.0.54.216,principal=none,uri=/nuxeo/nxthemes-css/,session=B2E4FECF54FACCC02989EB856DF20658,thread=http-0.0.0.0-8080-5,info=Existing
NuxeoRequestControler filter : nothing to be done
I hope this can be helpfull, what do you think, it could be a bug?
Thanks.
--
Posted by "jisi" at Nuxeo Discussions <http://nuxeo.org/discussions>
View the complete thread:
<http://www.nuxeo.org/discussions/thread.jspa?threadID=2651#7512>
_______________________________________________
ECM mailing list
[email protected]
http://lists.nuxeo.com/mailman/listinfo/ecm
To unsubscribe, go to http://lists.nuxeo.com/mailman/options/ecm
