Application redeploy issue

[v.lukoyanov]

Hello, community.

I'm developing web application with seam/jboss. The project is generated with seeam-gen and I use restart target to restart application when necessary. Sometimes jboss just hangs on restart, and remains idle for a long time (no cpu usage).
Last messages are:

16:39:03,281 INFO  [EJBContainer] STOPPED EJB: ru.xbm.vdo.core.ejb.GeneralPlanAction ejbName: GeneralPlanAction
16:39:03,282 WARN  [JmxKernelAbstraction] jboss.j2ee:ear=vdo.ear,jar=vdo.jar,name=GeneralPlanAction,service=EJB3 is not registered
16:39:03,282 INFO  [PersistenceUnitDeployment] Stopping persistence unit persistence.units:ear=vdo.ear,jar=vdo.jar,unitName=vdo
16:39:03,282 INFO  [SessionFactoryImpl] closing
16:39:03,282 INFO  [SchemaExport] Running hbm2ddl schema export
16:39:03,282 INFO  [SchemaExport] exporting generated schema to database 

killall -3 java

"JBoss System Threads(1)-1" daemon prio=10 tid=0x6314ac00 nid=0x5344 runnable [0x62daa000]
   java.lang.Thread.State: RUNNABLE
     at java.net.PlainSocketImpl.socketAccept(Native Method)
     at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)
     - locked <0x7422e9e0> (a java.net.SocksSocketImpl)
     at java.net.ServerSocket.implAccept(ServerSocket.java:453)
     at java.net.ServerSocket.accept(ServerSocket.java:421)
     at org.jboss.web.WebServer.run(WebServer.java:320)
     at org.jboss.util.threadpool.RunnableTaskWrapper.run(RunnableTaskWrapper.java:148)
     at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:756)
     at java.lang.Thread.run(Thread.java:619)

"ScannerThread" daemon prio=10 tid=0x62c3cc00 nid=0x5343 runnable [0x62f5b000]
   java.lang.Thread.State: RUNNABLE
     at java.net.SocketInputStream.socketRead0(Native Method)
     at java.net.SocketInputStream.read(SocketInputStream.java:129)
     at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:135)
     at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:104)
     at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
     at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:259)
     at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1183)
     at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:194)
     - locked <0x75dc76b8> (a org.postgresql.core.v3.QueryExecutorImpl)
     at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:476)
     at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:361)
     at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:307)
     at sun.reflect.GeneratedMethodAccessor104.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.postgresql.ds.jdbc23.AbstractJdbc23PooledConnection$StatementHandler.invoke(AbstractJdbc23PooledConnection.java:477)
     at $Proxy119.executeUpdate(Unknown Source)
     at org.jboss.resource.adapter.jdbc.WrappedStatement.executeUpdate(WrappedStatement.java:249)
     at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:383)
     at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:358)
     at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:258)
     at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:221)
     at org.hibernate.impl.SessionFactoryImpl.close(SessionFactoryImpl.java:839)
     at org.hibernate.ejb.EntityManagerFactoryImpl.close(EntityManagerFactoryImpl.java:46)
     at org.jboss.ejb3.entity.ManagedEntityManagerFactory.destroy(ManagedEntityManagerFactory.java:86)
     at org.jboss.ejb3.entity.PersistenceUnitDeployment.stop(PersistenceUnitDeployment.java:278)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.jboss.ejb3.ServiceDelegateWrapper.stopService(ServiceDelegateWrapper.java:119)
     at org.jboss.system.ServiceMBeanSupport.jbossInternalStop(ServiceMBeanSupport.java:315)
     at org.jboss.system.ServiceMBeanSupport.jbossInternalLifecycle(ServiceMBeanSupport.java:247)
     at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
     at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
     at org.jboss.mx.server.Invocation.invoke(Invocation.java:86)
     at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
     at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
     at org.jboss.system.ServiceController$ServiceProxy.invoke(ServiceController.java:978)
     at $Proxy0.stop(Unknown Source)
     at org.jboss.system.ServiceController.stop(ServiceController.java:508)
     at sun.reflect.GeneratedMethodAccessor454.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
     at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
     at org.jboss.mx.server.Invocation.invoke(Invocation.java:86)
     at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
     at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
     at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:210)
     at $Proxy215.stop(Unknown Source)
     at org.jboss.ejb3.JmxKernelAbstraction.uninstallMBean(JmxKernelAbstraction.java:175)
     at org.jboss.ejb3.JmxKernelAbstraction.uninstall(JmxKernelAbstraction.java:202)
     at org.jboss.ejb3.Ejb3Deployment.stopPersistenceUnits(Ejb3Deployment.java:642)
     at org.jboss.ejb3.Ejb3Deployment.stop(Ejb3Deployment.java:668)
     at org.jboss.ejb3.Ejb3Module.stopService(Ejb3Module.java:107)
     at org.jboss.system.ServiceMBeanSupport.jbossInternalStop(ServiceMBeanSupport.java:315)
     at org.jboss.system.ServiceMBeanSupport.jbossInternalLifecycle(ServiceMBeanSupport.java:247)
     at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
     at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
     at org.jboss.mx.server.Invocation.invoke(Invocation.java:86)
     at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
     at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
     at org.jboss.system.ServiceController$ServiceProxy.invoke(ServiceController.java:978)
     at $Proxy0.stop(Unknown Source)
     at org.jboss.system.ServiceController.stop(ServiceController.java:508)
     at sun.reflect.GeneratedMethodAccessor454.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
     at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
     at org.jboss.mx.server.Invocation.invoke(Invocation.java:86)
     at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
     at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
     at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:210)
     at $Proxy33.stop(Unknown Source)
     at org.jboss.ejb3.EJB3Deployer.stop(EJB3Deployer.java:532)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
     at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
     at org.jboss.mx.interceptor.AbstractInterceptor.invoke(AbstractInterceptor.java:133)
     at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
     at org.jboss.mx.interceptor.ModelMBeanOperationInterceptor.invoke(ModelMBeanOperationInterceptor.java:142)
     at org.jboss.mx.interceptor.DynamicInterceptor.invoke(DynamicInterceptor.java:97)
     at org.jboss.system.InterceptorServiceMBeanSupport.invokeNext(InterceptorServiceMBeanSupport.java:238)
     at org.jboss.wsf.container.jboss42.DeployerInterceptor.stop(DeployerInterceptor.java:98)
     at org.jboss.deployment.SubDeployerInterceptorSupport$XMBeanInterceptor.stop(SubDeployerInterceptorSupport.java:196)
     at org.jboss.deployment.SubDeployerInterceptor.invoke(SubDeployerInterceptor.java:99)
     at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
     at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
     at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
     at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:210)
     at $Proxy34.stop(Unknown Source)
     at org.jboss.deployment.MainDeployer.stop(MainDeployer.java:667)
     at org.jboss.deployment.MainDeployer.stop(MainDeployer.java:659)
     at org.jboss.deployment.MainDeployer.undeploy(MainDeployer.java:638)
     at org.jboss.deployment.MainDeployer.undeploy(MainDeployer.java:632)
     at org.jboss.deployment.MainDeployer.undeploy(MainDeployer.java:615)
     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:597)
     at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
     at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
     at org.jboss.mx.interceptor.AbstractInterceptor.invoke(AbstractInterceptor.java:133)
     at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
     at org.jboss.mx.interceptor.ModelMBeanOperationInterceptor.invoke(ModelMBeanOperationInterceptor.java:142)
     at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
     at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
     at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
     at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:210)
     at $Proxy9.undeploy(Unknown Source)
     at org.jboss.deployment.scanner.URLDeploymentScanner.undeploy(URLDeploymentScanner.java:450)
     at org.jboss.deployment.scanner.URLDeploymentScanner.scan(URLDeploymentScanner.java:604)
     - locked <0x74136b08> (a org.jboss.deployment.scanner.URLDeploymentScanner)
     at org.jboss.deployment.scanner.AbstractDeploymentScanner$ScannerThread.doScan(AbstractDeploymentScanner.java:263)
     at org.jboss.deployment.scanner.AbstractDeploymentScanner$ScannerThread.loop(AbstractDeploymentScanner.java:274)
     at org.jboss.deployment.scanner.AbstractDeploymentScanner$ScannerThread.run(AbstractDeploymentScanner.java:225)

"Timer-0" daemon prio=10 tid=0x62c1a400 nid=0x5342 in Object.wait() [0x62dfb000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
     at java.lang.Object.wait(Native Method)
     - waiting on <0x741aa828> (a java.util.TaskQueue)
     at java.util.TimerThread.mainLoop(Timer.java:509)
     - locked <0x741aa828> (a java.util.TaskQueue)
     at java.util.TimerThread.run(Timer.java:462)

"DestroyJavaVM" prio=10 tid=0x0868a800 nid=0x5322 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Low Memory Detector" daemon prio=10 tid=0x08742800 nid=0x5338 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x08740800 nid=0x5337 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x0873e400 nid=0x5336 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Command Reader" daemon prio=10 tid=0x08731800 nid=0x5333 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Event Helper Thread" daemon prio=10 tid=0x0872f800 nid=0x5331 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Transport Listener: dt_socket" daemon prio=10 tid=0x0872d000 nid=0x5330 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x08725400 nid=0x532c waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x08716400 nid=0x532a in Object.wait() [0x637af000]
   java.lang.Thread.State: WAITING (on object monitor)
     at java.lang.Object.wait(Native Method)
     - waiting on <0x7423d940> (a java.lang.ref.ReferenceQueue$Lock)
     at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
     - locked <0x7423d940> (a java.lang.ref.ReferenceQueue$Lock)
     at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
     at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x08711c00 nid=0x5327 in Object.wait() [0x63800000]
   java.lang.Thread.State: WAITING (on object monitor)
     at java.lang.Object.wait(Native Method)
     - waiting on <0x7422e910> (a java.lang.ref.Reference$Lock)
     at java.lang.Object.wait(Object.java:485)
     at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
     - locked <0x7422e910> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x0870dc00 nid=0x5326 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x08691800 nid=0x5324 runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x08692c00 nid=0x5325 runnable 

"VM Periodic Task Thread" prio=10 tid=0x08744400 nid=0x5339 waiting on condition 

JNI global references: 34540

Heap
 PSYoungGen      total 96512K, used 14058K [0xace80000, 0xb3980000, 0xb4040000)
  eden space 94592K, 12% used [0xace80000,0xada5f448,0xb2ae0000)
  from space 1920K, 99% used [0xb2ee0000,0xb30bb4a8,0xb30c0000)
  to   space 5376K, 0% used [0xb3440000,0xb3440000,0xb3980000)
 PSOldGen        total 233024K, used 110922K [0x74040000, 0x823d0000, 0xace80000)
  object space 233024K, 47% used [0x74040000,0x7ac92bf8,0x823d0000)
 PSPermGen       total 105472K, used 105351K [0x64040000, 0x6a740000, 0x74040000)
  object space 105472K, 99% used [0x64040000,0x6a721c98,0x6a740000)

Jboss 4.2.3.GA
Seam 2.2.0.GA
PostgreSQL 8.3

Any idea how to beat it?  Thanx.

[v.lukoyanov]

It seems to be related to postgres, but I've no idea how to fix it. Psql log is also doesn't provide any clue.

[jkronegg]

It seems that you generate the database schema back to the database (maybe because of hibernate.hbm2ddl.auto set to 'update' in persistence.xml?, see Hibernate configuration).

If this is the case, the update process can simply be very long.

Could you describe more precisely how your ORM mapping is done (i.e. database->entity or the reverse) ?

[v.lukoyanov]

Thank you for reply, Julien.

In persistence.xml file hibernate.hbm2ddl.auto is set to create-drop (for development). I'm using JPA annotation for map entities (I think its database->entity if i got you correctly).

Here is my persistence.xml:

<persistence-unit name="vdo">
      <provider>org.hibernate.ejb.HibernatePersistence</provider>
      <jta-data-source>vdoDatasource</jta-data-source>
      <!-- The <jar-file> element is necessary if you put the persistence.xml in the WAR and the classes in the JAR --> 
      <!--
      <jar-file>../../vehicles.jar</jar-file>
      -->
      <properties>
         <property name="hibernate.dialect" value="org.hibernate.dialect.PostgreSQLDialect"/>
         <property name="hibernate.hbm2ddl.auto" value="create-drop"/>
         <property name="hibernate.show_sql" value="true"/>
         <property name="hibernate.format_sql" value="true"/>
         <property name="jboss.entity.manager.factory.jndi.name" value="java:/vdoEntityManagerFactory"/>
         
         <!-- Envers configuration -->
         <property name="hibernate.ejb.event.post-insert"
             value="org.hibernate.ejb.event.EJB3PostInsertEventListener,org.hibernate.envers.event.AuditEventListener" />
         <property name="hibernate.ejb.event.post-update"
                     value="org.hibernate.ejb.event.EJB3PostUpdateEventListener,org.hibernate.envers.event.AuditEventListener" />
                 <property name="hibernate.ejb.event.post-delete"
                     value="org.hibernate.ejb.event.EJB3PostDeleteEventListener,org.hibernate.envers.event.AuditEventListener" />
                 <property name="hibernate.ejb.event.pre-collection-update"
                     value="org.hibernate.envers.event.AuditEventListener" />
                 <property name="hibernate.ejb.event.pre-collection-remove"
                     value="org.hibernate.envers.event.AuditEventListener" />
                 <property name="hibernate.ejb.event.post-collection-recreate"
                     value="org.hibernate.envers.event.AuditEventListener" />
         <!-- Envers configuration (end) -->
      </properties>
   </persistence-unit>

[jkronegg]

Is there any good reason why you have create-drop?

We usually set

<property name="hibernate.hbm2ddl.auto" value=""/>

to simply map the entities to the database. Therefore, Hibernate do not modify the database when mounting the ORM mappings : this is much faster and ensures that the database structure will not be modified.

[kragoth]

leaving the value blank is not desirable for development. value="" means that hibernate does not touch the database structure at all. For development it is nice to have Hibernate create/modify the schema for you. Unfortunately the create-drop or update options have a few problems with some database and we've never had much sucess with them. We get around this problem by passing the value for the hbm2dll.auto property in when starting our app. If we don't need the schema recreated then just pass in blank, otherwise pass in create.

[jkronegg]

In our case, not touching the database structure at all is exactly what we wanted. We first model the database relations using WinDesign, then generate the database creation scripts. This way, there is only one ground truth for the database: the WinDesign model. This ensures reproducibility when having several deployment environment (test/reception/production).

BTW, we had problems with the update mode: if you add a getter/setter in an entity without a @Transient annotation, Hibernate add a new column for the given getter/setter, which was not the desired effect.

[v.lukoyanov]

Thanks for reply.

Is there any good reason why you have create-drop?

Well, actually no. Create-drop was there because it was convenient when we'd been changing entity classes a lot. Now I think I could leave it blank.

We get around this problem by passing the value for the hbm2dll.auto property in when starting our app. If we don't need the schema recreated then just pass in blank, otherwise pass in create.

It seems a good idea. I'll try it, thanks.