Deployment and Startup very slow on Wildfly 20

726 views
Skip to first unread message

Massimo Furnari

unread,
Mar 28, 2023, 5:26:42 PM3/28/23
to WildFly
Hi, I'm using
  1. centos 7
  2. OpenJDK 11
  3. Wildfly-20.0.1.Final
  4. Application (Deployed as WAR of 60Mb in Wildfly) with two databases, PostgreSQL and MongoDB
Starting wildfly (or deploying on a clean wildfy already started) is very slow; with a log at the INFO level, it quickly reaches the "Registered web context" but then stays still for almost 11 minutes

2023-03-28 20:00:21,651 INFO [org.jboss.as] (MSC service thread 1-2) WFLYSRV0049: WildFly Full 20.0.1.Final (WildFly Core 12.0.3.Final) starting
....
2023-03-28 20:00:48,166 INFO [org.wildfly.extension.undertow] (ServerService Thread Pool -- 80) WFLYUT0021: Registered web context: '/siact' for server 'default-server'
2023-03-28 20:11:03,780 INFO [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: WildFly Full 20.0.1.Final (WildFly Core 12.0.3.Final) started in 643797ms - Started 1191 of 1407 services (382 services are lazy, passive or on-demand)

I added
            <logger category="org.jboss">
                <level name="TRACE"/>
            </logger>
but I can't understand why it takes me all this time.
It doesn't seem to me that there are connection problems with the database servers and, in fact, after the application has started, everything responds perfectly
In my development environment startup takes about two minutes ( databases on the same machine )
I attach the log. server.log
any help will be appreciated. thank you in advance


James Perkins

unread,
Mar 30, 2023, 2:03:52 PM3/30/23
to WildFly
That is a massive log file. How big is your deployment? Do you have some startup tasks in your deployment?

Massimo Furnari

unread,
Mar 31, 2023, 2:48:04 AM3/31/23
to WildFly
Hi, to my knowledge I have 
  • two scheduled job timer at startup ( @Startup annotation) 
  • two class with @ApplicationScoped ( MongoProducer that create instance of MongoClient AND JwtManager)
  • one entity with @Cacheable annotation
Datasource is 

        <subsystem xmlns="urn:jboss:domain:datasources:6.0">
            <datasources>
                <datasource jndi-name="java:jboss/datasources/ExampleDS" pool-name="ExampleDS" enabled="true" use-java-context="true">
                    <connection-url>jdbc:h2:mem:test;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=FALSE</connection-url>
                    <driver>h2</driver>
                    <security>
                        <user-name>sa</user-name>
                        <password>sa</password>
                    </security>
                </datasource>
                <datasource jndi-name="java:/PostgresDS" pool-name="PostgresDS">
                    <connection-url>jdbc:postgresql://localhost:5432/siact</connection-url>
                    <driver>postgres</driver>
                    <security>
                        <user-name>siact</user-name>
                        <password>xxxxx</password>
                    </security>
                    <validation>
                        <valid-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.postgres.PostgreSQLValidConnectionChecker"/>
                        <check-valid-connection-sql>select 1</check-valid-connection-sql>
                    </validation>
                </datasource>
                <drivers>
                    <driver name="h2" module="com.h2database.h2">
                        <xa-datasource-class>org.h2.jdbcx.JdbcDataSource</xa-datasource-class>
                    </driver>
                    <driver name="postgres" module="org.postgresql.Driver">
                        <driver-class>org.postgresql.Driver</driver-class>
                    </driver>
                </drivers>
            </datasources>
        </subsystem>
Message has been deleted

Massimo Furnari

unread,
Mar 31, 2023, 3:04:27 AM3/31/23
to WildFly
if you think better, i can remove "org.jboss" from category logger and add something else ?

and my war is 60Mb

James Perkins

unread,
Mar 31, 2023, 11:15:09 AM3/31/23
to WildFly
I don't really know what the best category is. It would just depend. Depending on what the startup EJB's do, that could be part of the issue. It's really hard to say though. 60MB is larger, but not huge. You might want to make sure you're not including libraries you don't need like the ones provided by the container.

Massimo Furnari

unread,
Mar 31, 2023, 11:28:51 AM3/31/23
to WildFly
is very strange, because i don't add library from years

after the line 

2023-03-28 20:00:48,166 INFO [org.wildfly.extension.undertow] (ServerService Thread Pool -- 80) WFLYUT0021: Registered web context: '/siact' for server 'default-server'

there are billions of operation like below

2023-03-28 20:05:54,988 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (MSC service thread 1-4) supplying ManagedConnection from pool: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7ffecb98[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@ae5afe5 connection handles=0 lastReturned=1680026754986 lastValidated=1680026426032 lastCheckedOut=1680026754975 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54468585 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@329bcc1b[pool=PostgresDS] xaResource=LocalXAResourceImpl@2ac88357[connectionListener=7ffecb98 connectionManager=5ed7893c warned=false currentXid=null productName=PostgreSQL productVersion=10.10 jndiName=java:/PostgresDS] txSync=null]
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.core.tracer.Tracer] (MSC service thread 1-4) IJTRACER-PostgresDS-329bcc1b-30-0-1145983844785560-7ffecb98--
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (MSC service thread 1-4) Got connection from pool: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7ffecb98[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@ae5afe5 connection handles=0 lastReturned=1680026754986 lastValidated=1680026426032 lastCheckedOut=1680026754988 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54468585 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@329bcc1b[pool=PostgresDS] xaResource=LocalXAResourceImpl@2ac88357[connectionListener=7ffecb98 connectionManager=5ed7893c warned=false currentXid=null productName=PostgreSQL productVersion=10.10 jndiName=java:/PostgresDS] txSync=null]
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (MSC service thread 1-4) No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7ffecb98[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@ae5afe5 connection handles=0 lastReturned=1680026754986 lastValidated=1680026426032 lastCheckedOut=1680026754988 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54468585 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@329bcc1b[pool=PostgresDS] xaResource=LocalXAResourceImpl@2ac88357[connectionListener=7ffecb98 connectionManager=5ed7893c warned=false currentXid=null productName=PostgreSQL productVersion=10.10 jndiName=java:/PostgresDS] txSync=null]
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.core.tracer.Tracer] (MSC service thread 1-4) IJTRACER-PostgresDS-329bcc1b-30-40-1145983844837759-7ffecb98-7cf6222f-
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (MSC service thread 1-4) [TxConnectionListener@7ffecb98] registerConnection: org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@7cf6222f [size=1] ([org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@7cf6222f])
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (MSC service thread 1-4) registering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl@5ed7893c, connection : org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@7cf6222f, key: null
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Lock: HeldByCurrentThread: No, Locked: No, HoldCount: 0, QueueLength: 0
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Unlock: HeldByCurrentThread: Yes, Locked: Yes, HoldCount: 1, QueueLength: 0
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Owner: Thread[MSC service thread 1-4,5,main]
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Lock: HeldByCurrentThread: No, Locked: No, HoldCount: 0, QueueLength: 0
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Unlock: HeldByCurrentThread: Yes, Locked: Yes, HoldCount: 1, QueueLength: 0
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Owner: Thread[MSC service thread 1-4,5,main]
2023-03-28 20:05:54,988 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Lock: HeldByCurrentThread: No, Locked: No, HoldCount: 0, QueueLength: 0
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Unlock: HeldByCurrentThread: Yes, Locked: Yes, HoldCount: 1, QueueLength: 0
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Owner: Thread[MSC service thread 1-4,5,main]
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Lock: HeldByCurrentThread: No, Locked: No, HoldCount: 0, QueueLength: 0
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Unlock: HeldByCurrentThread: Yes, Locked: Yes, HoldCount: 1, QueueLength: 0
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Owner: Thread[MSC service thread 1-4,5,main]
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Lock: HeldByCurrentThread: No, Locked: No, HoldCount: 0, QueueLength: 0
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Unlock: HeldByCurrentThread: Yes, Locked: Yes, HoldCount: 1, QueueLength: 0
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Owner: Thread[MSC service thread 1-4,5,main]
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Lock: HeldByCurrentThread: No, Locked: No, HoldCount: 0, QueueLength: 0
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Unlock: HeldByCurrentThread: Yes, Locked: Yes, HoldCount: 1, QueueLength: 0
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (MSC service thread 1-4) Owner: Thread[MSC service thread 1-4,5,main]
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (MSC service thread 1-4) connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@ae5afe5
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (MSC service thread 1-4) unregistering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl@5ed7893c, connection: org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@7cf6222f, key: null
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.tracer.Tracer] (MSC service thread 1-4) IJTRACER-PostgresDS-329bcc1b-30-41-1145983860990960-7ffecb98-7cf6222f-
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (MSC service thread 1-4) [TxConnectionListener@7ffecb98] unregisterConnection: 0 handles left ([])
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (MSC service thread 1-4) [TxConnectionListener@7ffecb98] isManagedConnectionFree: true
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (MSC service thread 1-4) delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7ffecb98[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@ae5afe5 connection handles=0 lastReturned=1680026754986 lastValidated=1680026426032 lastCheckedOut=1680026754988 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54468585 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@329bcc1b[pool=PostgresDS] xaResource=LocalXAResourceImpl@2ac88357[connectionListener=7ffecb98 connectionManager=5ed7893c warned=false currentXid=null productName=PostgreSQL productVersion=10.10 jndiName=java:/PostgresDS] txSync=null]
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (MSC service thread 1-4) [TxConnectionListener@7ffecb98] isManagedConnectionFree: true
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (MSC service thread 1-4) delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7ffecb98[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@ae5afe5 connection handles=0 lastReturned=1680026754986 lastValidated=1680026426032 lastCheckedOut=1680026754988 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54468585 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@329bcc1b[pool=PostgresDS] xaResource=LocalXAResourceImpl@2ac88357[connectionListener=7ffecb98 connectionManager=5ed7893c warned=false currentXid=null productName=PostgreSQL productVersion=10.10 jndiName=java:/PostgresDS] txSync=null]
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (MSC service thread 1-4) isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@ae5afe5
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.tracer.Tracer] (MSC service thread 1-4) IJTRACER-PostgresDS-329bcc1b-30-10-1145983861127213-7ffecb98--
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (MSC service thread 1-4) returnConnection(7ffecb98, false)
Method: returnConnection(7ffecb98, false)
  Subject: null
  CRI: 340bf88a
ManagedConnectionPool:
  Class: org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool
  Object: 329bcc1b
ManagedConnectionFactory:
  Class: org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory
  Object: 2c0c14be
ConnectionManager:
  Class: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl
  Object: 5ed7893c
Pool:
  Name: PostgresDS
  Class: org.jboss.jca.core.connectionmanager.pool.strategy.OnePool
  Object: 54468585
  FIFO: false
PoolConfiguration:
  MinSize: 0
  InitialSize: 0
  MaxSize: 20
  BlockingTimeout: 30000
  IdleTimeoutMinutes: 30
  ValidateOnMatch: true
  BackgroundValidation: false
  BackgroundValidationMillis: 0
  StrictMin: false
  UseFastFail: false
  Decrementer: org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutDecrementer
Available (1):
  7a4a19e (NORMAL) (Returned: 1680026446506) (Validated: 1680026446408) (Pool: 308498)
InUse (1):
  7ffecb98 (NORMAL) (CheckedOut: 1680026754988) (Validated: 1680026426032) (Usage: 16)
Statistics:
  ActiveCount: 0
  AvailableCount: 0
  AverageBlockingTime: 0
  AverageCreationTime: 0
  AverageGetTime: 0
  AveragePoolTime: 0
  AverageUsageTime: 0
  BlockingFailureCount: 0
  CreatedCount: 0
  DestroyedCount: 0
  IdleCount: 0
  InUseCount: 0
  MaxCreationTime: 0
  MaxGetTime: 0
  MaxPoolTime: 0
  MaxUsageTime: 0
  MaxUsedCount: 0
  MaxWaitTime: 0
  TimedOut: 0
  TotalBlockingTime: 0
  TotalCreationTime: 0
  TotalGetTime: 0
  TotalPoolTime: 0
  TotalUsageTime: 0
  WaitCount: 0
XAResource:
  CommitCount: 0
  CommitTotalTime: 0
  CommitAverageTime: 0
  CommitMaxTime: 0
  EndCount: 0
  EndTotalTime: 0
  EndAverageTime: 0
  EndMaxTime: 0
  ForgetCount: 0
  ForgetTotalTime: 0
  ForgetAverageTime: 0
  ForgetMaxTime: 0
  PrepareCount: 0
  PrepareTotalTime: 0
  PrepareAverageTime: 0
  PrepareMaxTime: 0
  RecoverCount: 0
  RecoverTotalTime: 0
  RecoverAverageTime: 0
  RecoverMaxTime: 0
  RollbackCount: 0
  RollbackTotalTime: 0
  RollbackAverageTime: 0
  RollbackMaxTime: 0
  StartCount: 0
  StartTotalTime: 0
  StartAverageTime: 0
  StartMaxTime: 0
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (MSC service thread 1-4) Returning connection to pool org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7ffecb98[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@ae5afe5 connection handles=0 lastReturned=1680026755004 lastValidated=1680026426032 lastCheckedOut=1680026754988 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@54468585 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@329bcc1b[pool=PostgresDS] xaResource=LocalXAResourceImpl@2ac88357[connectionListener=7ffecb98 connectionManager=5ed7893c warned=false currentXid=null productName=PostgreSQL productVersion=10.10 jndiName=java:/PostgresDS] txSync=null]
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (MSC service thread 1-4) Subject: null
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.TxConnectionManager] (MSC service thread 1-4) getManagedConnection interleaving=false , tx=null
2023-03-28 20:05:55,004 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (MSC service thread 1-4) getConnection(null, WrappedConnectionRequestInfo@340bf88a[userName=siact])

i don't understand....

seems that do somethings on Postgres

James Perkins

unread,
Mar 31, 2023, 11:31:38 AM3/31/23
to WildFly
Ah, okay. I'm not a JCA expert, but it looks like something is attempting to make a database connection. Do your startup EJB's make any kind of DB calls? That could be a potential as to why it's slow.

Massimo Furnari

unread,
Mar 31, 2023, 11:53:06 AM3/31/23
to WildFly
I think found a problem!

in wildfly i use batch module, jberet and its repository is on postegres ( tables JOB_EXECUTION and JOB_INSTANCE ); seems that wildlfy at startup make a single query for each job

in fact i see in postgres session this query "SELECT * FROM JOB_EXECUTION WHERE JOBINSTANCEID=$1 ORDER BY JOBEXECUTIONID"

i have about 20k of job executed in tables.... not huge number, but if i delete all records from tables.... wildfly speed up

Now the question is... what strategy is better ?? There is some configuration for clean up ?
Reply all
Reply to author
Forward
0 new messages