Page rendering in Long Conversation scope very slow
Hi, I have this big problem with my page in Seam 2.0.2.CR1. It is one one xhtml file with size 36kB and uses RichFaces 3.2.0.SR1 rich:tabpanel. I have 6 tabs there with about 10 h:inputText tags and 4 h:commandButtons on each tab. For tab switching I tried ajax and server mode. I have one backing bean for this page. The bean is SFSB in Long Conversation scope. When I access my page the rendering is very slow. It takes more than 15 seconds to render the page always. No matter if it is first time or after clicking on submit button and redisplay the page. If I change my bean to Session scope then rendering is super fast.
I have tried to isolate the problem but so far no luck. I have tried to gradually remove all components from my xhtml and in the end the only difference is that the more components I remove the faster it renders. I also tried to remove all code from backing bean - again no relevant results.
So far my conclusion is that my page renders fast in session scope and extremely slowly in conversation scope and I have no way to influence except for removing all components. I'm not even sure if the problem is caused by rich faces or not.
I'm not posting all the sources because they are too big for now. I include my log where you can see there are long delays between each JNDI Initial Context lines. This does not necessaarily mean that JNDI is the problem but that there is something happening between these lines which I can't see. I was fiddling with jboss log4j settings for 3 hrs and I can tell so far that hibernate is not the cause.
20:21:12,612 DEBUG [VerbunddatenProcess] #create
20:21:12,612 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:12,894 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:13,034 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:13,159 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:13,331 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:13,472 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:13,612 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:13,753 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:13,862 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:14,003 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:14,144 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:14,284 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:14,644 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:14,784 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:14,909 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:15,175 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:15,425 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:15,550 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:15,675 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:15,815 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:15,956 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:16,081 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:16,237 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:16,378 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:16,503 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:16,644 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:16,800 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:16,925 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:17,065 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:17,190 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:17,331 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:17,456 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:17,597 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:17,722 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:17,862 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:18,003 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:18,144 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:18,284 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:18,440 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:19,034 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:19,315 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:19,456 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:19,690 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:19,831 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:19,972 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:20,128 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:20,253 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:20,394 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:20,534 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:20,659 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:20,784 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:21,003 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:21,128 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:21,284 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:21,425 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:21,565 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:21,690 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:21,831 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:21,956 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:22,097 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:22,237 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:22,378 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:22,519 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:22,706 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:22,847 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:23,409 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:23,409 DEBUG [SeamPhaseListener] committing transaction after phase: RENDER_RESPONSE 6
20:21:23,409 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:23,409 DEBUG [UTTransaction] committing JTA transaction
20:21:23,409 DEBUG [EjbSynchronizations] afterBegin
20:21:23,409 DEBUG [EjbSynchronizations] beforeCompletion
20:21:23,409 DEBUG [EjbSynchronizations] beforeCompletion
20:21:23,409 DEBUG [EjbSynchronizations] beforeCompletion
20:21:23,409 DEBUG [EjbSynchronizations] afterCompletion
20:21:23,409 DEBUG [EjbSynchronizations] afterCompletion
20:21:23,409 DEBUG [EjbSynchronizations] afterCompletion
20:21:23,409 DEBUG [Manager] Discarding conversation state: 1
20:21:23,409 DEBUG [FacesLifecycle] After render response, destroying contexts
20:21:23,409 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:23,409 DEBUG [Naming] JNDI InitialContext properties:{java.naming.factory.initial=org.jnp.interfaces.NamingContextFactory, java.naming.factory.url.pkgs=org.jboss.naming:org.jnp.interfaces}
20:21:23,409 DEBUG [ManagedPersistenceContext] destroying seam managed persistence context for persistence unit: java:/vcgenEntityManagerFactory
20:21:23,409 DEBUG [VerbunddatenProcess] #destroy
My current log4j settings are default except the following:
<appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
<errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
<param name="Target" value="System.out"/>
<param name="Threshold" value="DEBUG"/>
<layout class="org.apache.log4j.PatternLayout">
<!-- The default pattern: Date Priority [Category] Message\n -->
<param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
</layout>
</appender>
<category name="org.jboss">
<priority value="INFO" />
</category>
<category name="org.jboss.seam">
<priority value="DEBUG" />
</category>
<category name="org.jboss.seam.Component">
<priority value="INFO" />
</category>
<category name="org.jboss.seam.core.Events">
<priority value="INFO" />
</category>
<category name="org.jboss.seam.core.Contexts">
<priority value="INFO" />
</category>
<category name="org.jboss.seam.contexts.Contexts">
<priority value="INFO" />
</category>
<category name="org.jboss.seam.core.ResourceLoader">
<priority value="INFO" />
</category>
<category name="org.jboss.seam.faces.ResourceLoader">
<priority value="INFO" />
</category>
<category name="org.hibernate">
<priority value="INFO" />
</category>
<!-- Hibernate got a bit too verbose in JBoss AS 4.2.1.GA -->
<category name="org.hibernate.engine.loading.LoadContexts">
<priority value="ERROR"/>
</category>
<!-- JBoss Cache likes to talk a lot -->
<category name="org.jboss.cache.interceptors.CacheLoaderInterceptor">
<priority value="ERROR"/>
</category>
<category name="org.ajax4jsf">
<priority value="INFO" />
</category>
<category name="com.arjuna">
<priority value="INFO" />
</category>
<category name="org.richfaces">
<priority value="INFO" />
</category>
When I change to Session scope these JNDI call don't have such long delays between them and there is less of them. I also tried changing between client and server side state saving with no changes in resulting speed.
I would really appreciate if somebody could suggest a way to look, any clues etc.
