search

OpenLiberty / open-liberty

Open Liberty is a highly composable, fast to start, dynamic application server runtime environment
https://openliberty.io
Eclipse Public License 2.0
1.15k stars 591 forks source link

startup with jpa in liberty app using eclipselink taking over 20 seconds to start #11606

Closed dettmoney closed 1 year ago

dettmoney commented 4 years ago

Startup of the application is taking over 20 seconds. Javacores show code in the following stack: 3XMTHREADINFO "Default Executor-thread-7" J9VMThread:0x0000000001AAE800, omrthread_t:0x00007FC7CC010E08, java/lang/Thread:0x00000000F939DB00, state:CW, prio=5 3XMJAVALTHREAD (java/lang/Thread getId:0x71, isDaemon:true) 3XMTHREADINFO1 (native thread ID:0x37DEB, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000481) 3XMTHREADINFO2 (native stack address range from:0x00007FC95588E000, to:0x00007FC9558CF000, size:0x41000) 3XMCPUTIME CPU usage total: 0.698283012 secs, current category="Application" 3XMHEAPALLOC Heap bytes allocated since last GC cycle=9985232 (0x985CD0) 3XMTHREADINFO3 Java callstack: 4XESTACKTRACE at java/lang/Thread.sleep(Native Method) 4XESTACKTRACE at java/lang/Thread.sleep(Thread.java:951) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/AbstractSession.retryQuery(AbstractSession.java:1967) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/DatabaseSessionImpl.retryQuery(DatabaseSessionImpl.java:1072) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/AbstractSession.executeQuery(AbstractSession.java:1935) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/AbstractSession.retryQuery(AbstractSession.java:1969) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/DatabaseSessionImpl.retryQuery(DatabaseSessionImpl.java:1072) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/AbstractSession.executeQuery(AbstractSession.java:1935) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/AbstractSession.retryQuery(AbstractSession.java:1969) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/DatabaseSessionImpl.retryQuery(DatabaseSessionImpl.java:1072) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/AbstractSession.executeQuery(AbstractSession.java:1935) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/AbstractSession.executeQuery(AbstractSession.java:1880) 4XESTACKTRACE at org/eclipse/persistence/internal/sessions/AbstractSession.executeQuery(AbstractSession.java:1830) 4XESTACKTRACE at org/eclipse/persistence/internal/databaseaccess/DatabasePlatform.checkTableExists(DatabasePlatform.java:3792) 4XESTACKTRACE at org/eclipse/persistence/tools/schemaframework/SchemaManager.checkTableExists(SchemaManager.java:467) 4XESTACKTRACE at org/eclipse/persistence/tools/schemaframework/SchemaManager.checkTableExists(SchemaManager.java:480) 4XESTACKTRACE at org/eclipse/persistence/tools/schemaframework/TableCreator.createTables(TableCreator.java:168) 4XESTACKTRACE at org/eclipse/persistence/tools/schemaframework/TableCreator.createTables(TableCreator.java:150) 4XESTACKTRACE at org/eclipse/persistence/tools/schemaframework/TableCreator.createTables(TableCreator.java:142) 4XESTACKTRACE at org/eclipse/persistence/tools/schemaframework/SchemaManager.createDefaultTables(SchemaManager.java:1030) 4XESTACKTRACE at org/eclipse/persistence/internal/jpa/EntityManagerFactoryProvider.generateDefaultTables(EntityManagerFactoryProvider.java:110) 4XESTACKTRACE at org/eclipse/persistence/internal/jpa/EntityManagerSetupImpl.writeDDLToDatabase(EntityManagerSetupImpl.java:4436) 4XESTACKTRACE at org/eclipse/persistence/internal/jpa/EntityManagerSetupImpl.writeMetadataDDLToDatabase(EntityManagerSetupImpl.java:4503) 4XESTACKTRACE at org/eclipse/persistence/internal/jpa/EntityManagerSetupImpl.writeDDL(EntityManagerSetupImpl.java:4407) 4XESTACKTRACE at org/eclipse/persistence/internal/jpa/EntityManagerSetupImpl.writeDDL(EntityManagerSetupImpl.java:4282) 4XESTACKTRACE at org/eclipse/persistence/internal/jpa/EntityManagerSetupImpl.deploy(EntityManagerSetupImpl.java:819) 4XESTACKTRACE at org/eclipse/persistence/internal/jpa/EntityManagerFactoryDelegate.getAbstractSession(EntityManagerFactoryDelegate.java:222) 5XESTACKTRACE (entered lock: org/eclipse/persistence/internal/jpa/EntityManagerFactoryDelegate@0x00000000FF019538, entry count: 1) 4XESTACKTRACE at org/eclipse/persistence/internal/jpa/EntityManagerFactoryDelegate.getDatabaseSession(EntityManagerFactoryDelegate.java:200) 4XESTACKTRACE at org/eclipse/persistence/internal/jpa/EntityManagerFactoryImpl.getDatabaseSession(EntityManagerFactoryImpl.java:542) 4XESTACKTRACE at org/eclipse/persistence/jpa/PersistenceProvider.createContainerEntityManagerFactoryImpl(PersistenceProvider.java:388) 4XESTACKTRACE at org/eclipse/persistence/jpa/PersistenceProvider.createContainerEntityManagerFactory(PersistenceProvider.java:316) 4XESTACKTRACE at com/ibm/ws/jpa/management/JPAPUnitInfo.createEMFactory(JPAPUnitInfo.java:919) 4XESTACKTRACE at com/ibm/ws/jpa/management/JPAPUnitInfo.initialize(JPAPUnitInfo.java:766) 4XESTACKTRACE at com/ibm/ws/jpa/management/JPAPxmlInfo.extractPersistenceUnits(JPAPxmlInfo.java:183) 4XESTACKTRACE at com/ibm/ws/jpa/management/JPAScopeInfo.processPersistenceUnit(JPAScopeInfo.java:89) 5XESTACKTRACE (entered lock: java/util/HashMap@0x00000000F939DB98, entry count: 1) 4XESTACKTRACE at com/ibm/ws/jpa/management/JPAApplInfo.addPersistenceUnits(JPAApplInfo.java:120) 4XESTACKTRACE at com/ibm/ws/jpa/container/osgi/internal/JPAComponentImpl.processWebModulePersistenceXml(JPAComponentImpl.java:517) 4XESTACKTRACE at com/ibm/ws/jpa/container/osgi/internal/JPAComponentImpl.applicationStarting(JPAComponentImpl.java:304) 4XESTACKTRACE at com/ibm/ws/container/service/state/internal/ApplicationStateManager.fireStarting(ApplicationStateManager.java:51) 4XESTACKTRACE at com/ibm/ws/container/service/state/internal/StateChangeServiceImpl.fireApplicationStarting(StateChangeServiceImpl.java:50) 4XESTACKTRACE at com/ibm/ws/app/manager/module/internal/SimpleDeployedAppInfoBase.preDeployApp(SimpleDeployedAppInfoBase.java:547) 4XESTACKTRACE at com/ibm/ws/app/manager/module/internal/SimpleDeployedAppInfoBase.installApp(SimpleDeployedAppInfoBase.java:508) 4XESTACKTRACE at com/ibm/ws/app/manager/module/internal/DeployedAppInfoBase.deployApp(DeployedAppInfoBase.java:347) 4XESTACKTRACE at com/ibm/ws/app/manager/war/internal/WARApplicationHandlerImpl.install(WARApplicationHandlerImpl.java:65) 4XESTACKTRACE at com/ibm/ws/app/manager/internal/statemachine/StartAction.execute(StartAction.java:140) 4XESTACKTRACE at com/ibm/ws/app/manager/internal/statemachine/ApplicationStateMachineImpl.enterState(ApplicationStateMachineImpl.java:1286) 4XESTACKTRACE at com/ibm/ws/app/manager/internal/statemachine/ApplicationStateMachineImpl.run(ApplicationStateMachineImpl.java:884) 4XESTACKTRACE at com/ibm/ws/threading/internal/ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:239) 4XESTACKTRACE at java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149(Compiled Code)) 4XESTACKTRACE at java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) 4XESTACKTRACE at java/lang/Thread.run(Thread.java:821)

JPA=all trace shows GenericDataSource.getConnection being called multiple times with 5 second gaps between. I will attach trace.log as well as the app and repro instructions. This has been happening for months, so it's not related to a specific liberty level

dettmoney commented 4 years ago

crudServer.zip

dettmoney commented 4 years ago

Unzip the crudServer.zip into a liberty wlp/usr/servers directory, execute the run-docker-db.sh script to start the postgres db in docker, then start the crudServer. It should startup successfully after approximately 20 seconds

jgrassel commented 2 years ago

It looks to me like there's a 20s hangup with eclipselink trying to get a connection from the GenericDataSource (which of course, it cannot -- it's fake datasource we give the primordial EMF in order to bootstrap it so we can get a class transformer from it when the persistence unit uses a java:comp/env named datasource -- we have to do this because at this point, resource ref bindings have not yet been established.). Eventually after trying enough times it gives up.

[4/25/22 8:16:12:899 CDT] 00000033 JPAPUnitInfo  <  getJPADataSource : GenericDataSource@2e8e0301[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource] Exit 
[4/25/22 8:16:12:899 CDT] 00000033 JPAPUnitInfo  >  getJPADataSource : null, PuId=rest-http-crud#rest-http-crud.war#MyPU Entry 
[4/25/22 8:16:12:899 CDT] 00000033 JPAPUnitInfo  <  getJPADataSource : null Exit 
[4/25/22 8:16:12:901 CDT] 00000033 properties    3   [eclipselink.properties] property=eclipselink.allow-null-max-min; value=false
[4/25/22 8:16:12:901 CDT] 00000033 properties    3   [eclipselink.properties] property=eclipselink.sql.allow-convert-result-to-boolean; value=false
[4/25/22 8:16:12:908 CDT] 00000033 eclipselink   I   CWWJP9990I: [eclipselink] EclipseLink, version: Eclipse Persistence Services - 2.7.10.v20211216-fe64cd39c3
[4/25/22 8:16:12:915 CDT] 00000033 GenericDataSo >  getConnection : PuId=rest-http-crud#rest-http-crud.war#MyPU Entry 
[4/25/22 8:16:12:944 CDT] 00000033 GenericConnec >  <init> : PuId=rest-http-crud#rest-http-crud.war#MyPU, dataSourceName = java:comp/DefaultDataSource Entry 
[4/25/22 8:16:12:944 CDT] 00000033 GenericConnec <  <init> Exit 
[4/25/22 8:16:12:944 CDT] 00000033 GenericDataSo <  getConnection : GenericConnection@3ee7f0e5[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource] Exit 
[4/25/22 8:16:12:945 CDT] 00000033 GenericConnec 3   isClosed : GenericConnection@3ee7f0e5[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource], false
[4/25/22 8:16:12:945 CDT] 00000033 GenericConnec 3   close : GenericConnection@3ee7f0e5[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource]
[4/25/22 8:16:12:945 CDT] 00000033 GenericDataSo >  getConnection : PuId=rest-http-crud#rest-http-crud.war#MyPU Entry 
[4/25/22 8:16:12:945 CDT] 00000033 GenericConnec >  <init> : PuId=rest-http-crud#rest-http-crud.war#MyPU, dataSourceName = java:comp/DefaultDataSource Entry 
[4/25/22 8:16:12:945 CDT] 00000033 GenericConnec <  <init> Exit 
[4/25/22 8:16:12:945 CDT] 00000033 GenericDataSo <  getConnection : GenericConnection@49a09844[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource] Exit 
[4/25/22 8:16:12:945 CDT] 00000033 GenericConnec 3   isClosed : GenericConnection@49a09844[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource], false
[4/25/22 8:16:12:945 CDT] 00000033 GenericConnec 3   close : GenericConnection@49a09844[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource]
[4/25/22 8:16:13:127 CDT] 00000033 GenericDataSo >  getConnection : PuId=rest-http-crud#rest-http-crud.war#MyPU Entry 
[4/25/22 8:16:13:127 CDT] 00000033 GenericConnec >  <init> : PuId=rest-http-crud#rest-http-crud.war#MyPU, dataSourceName = java:comp/DefaultDataSource Entry 
[4/25/22 8:16:13:127 CDT] 00000033 GenericConnec <  <init> Exit 

[4/25/22 8:16:33:179 CDT] 00000033 GenericConnec >  <init> : PuId=rest-http-crud#rest-http-crud.war#MyPU, dataSourceName = java:comp/DefaultDataSource Entry 
[4/25/22 8:16:33:179 CDT] 00000033 GenericConnec <  <init> Exit 
[4/25/22 8:16:33:179 CDT] 00000033 GenericDataSo <  getConnection : GenericConnection@4dd057d2[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource] Exit 
[4/25/22 8:16:33:179 CDT] 00000033 GenericConnec 3   isClosed : GenericConnection@4dd057d2[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource], false
[4/25/22 8:16:33:179 CDT] 00000033 GenericConnec 3   close : GenericConnection@4dd057d2[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource]
[4/25/22 8:16:33:179 CDT] 00000033 GenericDataSo >  getConnection : PuId=rest-http-crud#rest-http-crud.war#MyPU Entry 
[4/25/22 8:16:33:179 CDT] 00000033 GenericConnec >  <init> : PuId=rest-http-crud#rest-http-crud.war#MyPU, dataSourceName = java:comp/DefaultDataSource Entry 
[4/25/22 8:16:33:179 CDT] 00000033 GenericConnec <  <init> Exit 
[4/25/22 8:16:33:179 CDT] 00000033 GenericDataSo <  getConnection : GenericConnection@6702437e[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource] Exit 
[4/25/22 8:16:33:179 CDT] 00000033 GenericConnec 3   isClosed : GenericConnection@6702437e[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource], false
[4/25/22 8:16:33:179 CDT] 00000033 GenericConnec 3   close : GenericConnection@6702437e[PuId=rest-http-crud#rest-http-crud.war#MyPU, java:comp/DefaultDataSource]
[4/25/22 8:16:33:180 CDT] 00000033 JPAPUnitInfo  3   reverting class loader to org.eclipse.osgi.internal.framework.ContextFinder@758f0979

I didn't find any eclipselink configuration option which we could change the default connection retry count/retry wait, otherwise an easy fix would have been to just add a "retries=0" property only on the primordial emf only (for emfs using java:comp/env datasources only). Looking through the documentation, it sounds like the only way to override it is to use a SessionCustomer, which isn't a real solution here.

jgrassel commented 2 years ago

Digging a little deeper, it's a bit more complicated than one might expect. It tries to connect to the database 21 times during the bootstrap phase. At first one might think that it's just trying to connect to the database to determine what type of database it is, so that it can load the proper dictionary (of course, this isn't going to work, with GenericDataSource, it doesn't connect to a real database. It just exists to satisfy not returning a null DataSource with PersistenceUnitInfo.getDataSource().)

The first two connection attempts are from Eclipselink trying to set up the connection pool (I'm going to snip a lot of irrelevent stack frames out in order to keep this short, I've also modded Eclipselink to stack dump when DatasourceLogin.connectToDatasource() is entered).

The first two attempts are when the EMF is trying to initialize, and look like as follows:

[4/25/22 16:18:35:505 CDT] 0000002b com.ibm.ws.jpa.AbstractJPAProviderIntegration                I CWWJP0053I: EclipseLink is used as a third-party JPA provider. Version information is: 2.7.11.qualifier. 
[4/25/22 16:18:36:438 CDT] 0000002b SystemOut                                                    O JAG: EntityManagerSetupImpl : deploy()
[4/25/22 16:18:36:456 CDT] 0000002b SystemOut                                                    O JAG: ConnectionPool.buildConnection()
[4/25/22 16:18:36:465 CDT] 0000002b SystemOut                                                    O JAG: DatasourceLogin: Connecting to DataSource ...
[4/25/22 16:18:36:466 CDT] 0000002b SystemErr                                                    R java.lang.Exception: Stack trace
[4/25/22 16:18:36:466 CDT] 0000002b SystemErr                                                    R  at java.lang.Thread.dumpStack(Thread.java:1336)
[4/25/22 16:18:36:494 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:173)
<snip>
[4/25/22 16:18:36:497 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.jpa.EntityManagerFactoryProvider.login(EntityManagerFactoryProvider.java:263)
[4/25/22 16:18:36:498 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.deploy(EntityManagerSetupImpl.java:774)

Then the next five attempts to connect appear to be involving the attempt to honor the persistence unit's drop-tables configuration:

[4/25/22 16:18:36:756 CDT] 0000002b SystemOut                                                    O JAG: DatasourceLogin: Connecting to DataSource ...
[4/25/22 16:18:36:756 CDT] 0000002b SystemErr                                                    R java.lang.Exception: Stack trace
[4/25/22 16:18:36:757 CDT] 0000002b SystemErr                                                    R  at java.lang.Thread.dumpStack(Thread.java:1336)
[4/25/22 16:18:36:757 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:173)
<snip>
[4/25/22 16:18:36:763 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.dropTables(TableCreator.java:233)
[4/25/22 16:18:36:764 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.dropDefaultTables(SchemaManager.java:1069)
[4/25/22 16:18:36:764 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.jpa.EntityManagerFactoryProvider.generateDefaultTables(EntityManagerFactoryProvider.java:115)

Following that, is an attempt to connect which appear to be involved with trying to drop sequence definitions:

[4/25/22 16:18:36:841 CDT] 0000002b SystemOut                                                    O JAG: DatasourceLogin: Connecting to DataSource ...
[4/25/22 16:18:36:842 CDT] 0000002b SystemErr                                                    R java.lang.Exception: Stack trace
[4/25/22 16:18:36:842 CDT] 0000002b SystemErr                                                    R  at java.lang.Thread.dumpStack(Thread.java:1336)
[4/25/22 16:18:36:842 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:173)
<snip>
[4/25/22 16:18:36:848 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.dropSequences(SchemaManager.java:302)
[4/25/22 16:18:36:848 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.dropDefaultTables(SchemaManager.java:1072)
[4/25/22 16:18:36:848 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.jpa.EntityManagerFactoryProvider.generateDefaultTables(EntityManagerFactoryProvider.java:115)

Then the next four connection attempts are to check if tables exist in the database (presumably, to update their schema if they need it):

[4/25/22 16:18:36:858 CDT] 0000002b SystemOut                                                    O JAG: DatasourceLogin: Connecting to DataSource ...
[4/25/22 16:18:36:859 CDT] 0000002b SystemErr                                                    R java.lang.Exception: Stack trace
[4/25/22 16:18:36:859 CDT] 0000002b SystemErr                                                    R  at java.lang.Thread.dumpStack(Thread.java:1336)
[4/25/22 16:18:36:859 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:173)
<snip>
[4/25/22 16:18:36:864 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.databaseaccess.DatabasePlatform.checkTableExists(DatabasePlatform.java:3811)
[4/25/22 16:18:36:864 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.checkTableExists(SchemaManager.java:467)
[4/25/22 16:18:36:864 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.checkTableExists(SchemaManager.java:480)
[4/25/22 16:18:36:864 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.createTables(TableCreator.java:169)
[4/25/22 16:18:36:864 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.createTables(TableCreator.java:151)
[4/25/22 16:18:36:865 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.createTables(TableCreator.java:143)
[4/25/22 16:18:36:865 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.createDefaultTables(SchemaManager.java:1030)
[4/25/22 16:18:36:865 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.jpa.EntityManagerFactoryProvider.generateDefaultTables(EntityManagerFactoryProvider.java:113)

Then the next attempt is to try and create tables:

[4/25/22 16:18:46:949 CDT] 0000002b SystemOut                                                    O JAG: DatasourceLogin: Connecting to DataSource ...
[4/25/22 16:18:46:950 CDT] 0000002b SystemErr                                                    R java.lang.Exception: Stack trace
[4/25/22 16:18:46:950 CDT] 0000002b SystemErr                                                    R  at java.lang.Thread.dumpStack(Thread.java:1336)
[4/25/22 16:18:46:950 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:173)
<snip>
4/25/22 16:18:46:955 CDT] 0000002b SystemErr                                                    R   at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeNoSelect(DatasourceCallQueryMechanism.java:286)
[4/25/22 16:18:46:955 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.queries.DataModifyQuery.executeDatabaseQuery(DataModifyQuery.java:87)
[4/25/22 16:18:46:955 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:911)
[4/25/22 16:18:46:956 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.sessions.AbstractSession.internalExecuteQuery(AbstractSession.java:3367)
[4/25/22 16:18:46:956 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1898)
[4/25/22 16:18:46:956 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1880)
[4/25/22 16:18:46:956 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1830)
[4/25/22 16:18:46:957 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.sessions.AbstractSession.priviledgedExecuteNonSelectingCall(AbstractSession.java:5234)
[4/25/22 16:18:46:957 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.DatabaseObjectDefinition.createOnDatabase(DatabaseObjectDefinition.java:204)
[4/25/22 16:18:46:957 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.createObject(SchemaManager.java:223)
[4/25/22 16:18:46:958 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.createTables(TableCreator.java:174)
[4/25/22 16:18:46:958 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.createTables(TableCreator.java:151)
[4/25/22 16:18:46:958 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.createTables(TableCreator.java:143)
[4/25/22 16:18:46:958 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.createDefaultTables(SchemaManager.java:1030)

The next five attempts appearsto be involved in trying to create a sequence:

[4/25/22 16:18:46:989 CDT] 0000002b SystemOut                                                    O JAG: DatasourceLogin: Connecting to DataSource ...
[4/25/22 16:18:46:989 CDT] 0000002b SystemErr                                                    R java.lang.Exception: Stack trace
[4/25/22 16:18:46:989 CDT] 0000002b SystemErr                                                    R  at java.lang.Thread.dumpStack(Thread.java:1336)
[4/25/22 16:18:46:990 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:173)
<snip>
                                    R   at org.eclipse.persistence.sequencing.QuerySequence.updateAndSelectSequence(QuerySequence.java:270)
[4/25/22 16:18:46:994 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.sequencing.StandardSequence.getGeneratedVector(StandardSequence.java:75)
[4/25/22 16:18:46:994 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.sequencing.Sequence.getGeneratedVector(Sequence.java:267)
[4/25/22 16:18:46:994 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SequenceObjectDefinition.checkIfExist(SequenceObjectDefinition.java:101)
[4/25/22 16:18:46:995 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SequenceDefinition.createOnDatabase(SequenceDefinition.java:86)
[4/25/22 16:18:46:995 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.createObject(SchemaManager.java:223)
[4/25/22 16:18:46:995 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.processSequenceDefinition(SchemaManager.java:361)
[4/25/22 16:18:46:995 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.processSequenceDefinitions(SchemaManager.java:417)
[4/25/22 16:18:46:995 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.createOrReplaceSequences(SchemaManager.java:295)
[4/25/22 16:18:46:996 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.createTables(TableCreator.java:188)
[4/25/22 16:18:46:996 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.createTables(TableCreator.java:151)
[4/25/22 16:18:46:996 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.TableCreator.createTables(TableCreator.java:143)
[4/25/22 16:18:46:996 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.tools.schemaframework.SchemaManager.createDefaultTables(SchemaManager.java:1030)
[4/25/22 16:18:46:996 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.jpa.EntityManagerFactoryProvider.generateDefaultTables(EntityManagerFactoryProvider.java:113)

Then it attempts three times to, from what I'm guessing by appearance, trying to execute a sql script against the database:

[4/25/22 16:18:57:071 CDT] 0000002b SystemOut                                                    O JAG: DatasourceLogin: Connecting to DataSource ...
[4/25/22 16:18:57:071 CDT] 0000002b SystemErr                                                    R java.lang.Exception: Stack trace
[4/25/22 16:18:57:071 CDT] 0000002b SystemErr                                                    R  at java.lang.Thread.dumpStack(Thread.java:1336)
[4/25/22 16:18:57:072 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:173)
<snip>
[4/25/22 16:18:57:075 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.sessions.AbstractSession.executeNonSelectingSQL(AbstractSession.java:1606)
[4/25/22 16:18:57:075 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.writeSourceScriptToDatabase(EntityManagerSetupImpl.java:4836)
[4/25/22 16:18:57:075 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.writeDDL(EntityManagerSetupImpl.java:4571)
[4/25/22 16:18:57:075 CDT] 0000002b SystemErr                                                    R  at org.eclipse.persistence.internal.jpa.EntityManagerSetupImpl.deploy(EntityManagerSetupImpl.java:821)

The nature of these connection attempts are rather widespread, so I do not believe that there will be a simple solution to this problem. It is an unfortunte side effect of an application choosing to use resource-ref datasources combined with activating drop-and-create table creation (something that you should not be doing in production).

jgrassel commented 2 years ago

TLDR: The system is working as designed. When bootstrapping JPA with java:comp/env datasources, we need to get a Class Transformer registered early in the application start process, before any application classes are loaded. This has to take place before resource references are bound to their actual resources, so it is impossible at this point to get a real database connection -- we have to resort to a GenericDataSource which we give to the EMF that we instantiate for the sole purpose of harvesting Class Transformers from -- it is an EMF that will never be used by any application component (because it doesn't connect to anything, and every application component may bind the same resource ref name to a completely different resource). Because Eclipselink was instructed to drop-and-create-tables, it tries to do that very hard, and each time it results in a connection failure, with a timeout period before trying again. Overall, a total of 21 connection attempts are made when trying to honor this configuration, with retry delays which adds a considerable about of time to the EMF start time.

JPA's support for dropping and creating tables was never meant to be used for serious production environments, it's intended to help with unit testing, and to generate DDLs for which DBAs use as a starting point for setting up their databases. A production system not enabling "drop-and-create" (really, you don't want to delete your customer database every time you start a node) thus would not encounter the vast majority of these startup delays.

jgrassel commented 1 year ago

After picking this up again, I noticed that I could no longer replicate the performance issue. It seems that Will's change in #22865 took advantage of some performance improvements. The commit before his PR had demonstrated the 26 second start time, which was reduced to 5 seconds after Will's change.

Therefore, I don't believe that my original plan of having the JPA runtime integration strip out schema management properties for the ClassTransformer-harvester EMF is necessary.