Hi,
We are having a spring boot application and using hibernate ORM.
The initial startup alone took 2133.91 seconds (around 35 minutes), which is a long period.
We did more analysis on the startup debug logs and found there are a lot of hibernate related logs. More than 90% of the entire logs are from hibernate. This application contains 300+ ORM file’s.
We have also found some sets of logs are repeating . Following are the sample set for reference.
Set1 :
2020-10-15 16:36:26,138 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.AbstractPropertyHolder - Attempting to locate auto-apply AttributeConverter for property [com.suntecgroup.xelerate.assets.be.compatibilityassociationbe.de.CompatibilityAssociationBEDE:compAsstnEntityVersion]
2020-10-15 16:36:26,138 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - building SimpleValue for compAsstnEntityVersion
2020-10-15 16:36:26,138 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.annotations.PropertyBinder - Building property compAsstnEntityVersion
2020-10-15 16:36:26,138 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.Ejb3Column - Binding column: Ejb3Column{table=org.hibernate.mapping.Table(CompatibilityAssociation), mappingColumn=createdAt, insertable=true, updatable=true, unique=false}
2020-10-15 16:36:26,138 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.annotations.PropertyBinder - MetadataSourceProcessor property createdAt with lazy=false
Set2:
2020-10-15 16:36:26,753 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - Starting fillSimpleValue for accountIban
2020-10-15 16:36:26,753 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - Starting fillSimpleValue for accountNumber
Set3:
2020-10-15 16:36:26,901 [WrapperSimpleAppMain] DEBUG org.hibernate.mapping.PrimaryKey - Forcing column [pkid] to be non-null as it is part of the primary key for table [vw_mashreq_uaq]
2020-10-15 16:36:26,901 [WrapperSimpleAppMain] DEBUG org.hibernate.mapping.PrimaryKey - Forcing column [pkid] to be non-null as it is part of the primary key for table [paybydatedefn]
Set4 :
2020-10-15 16:45:20,490 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.annotations.PropertyBinder - Building property computationModel
2020-10-15 16:45:20,490 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.Ejb3Column - Binding column: Ejb3Column{table=org.hibernate.mapping.Table(XCatalogueChargeHierarchyBE_customBusinessTransactionList), mappingColumn=externalTransactionReferenceId, insertable=true, updatable=true, unique=false}
2020-10-15 16:45:20,490 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.annotations.PropertyBinder - MetadataSourceProcessor property externalTransactionReferenceId with lazy=false
2020-10-15 16:45:20,490 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.AbstractPropertyHolder - Attempting to locate auto-apply AttributeConverter for property [com.suntecgroup.xelerate.assets.be.xcataloguechargehierarchybe.de.XCatalogueChargeHierarchyBEDE.customBusinessTransactionList.collection&&element:externalTransactionReferenceId]
2020-10-15 16:45:20,490 [WrapperSimpleAppMain] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - building SimpleValue for externalTransactionReferenceId
Set 5:
2020-10-15 16:45:23,623 [WrapperSimpleAppMain] DEBUG org.hibernate.boot.internal.ClassLoaderAccessImpl - No temp ClassLoader provided; using live ClassLoader for loading potentially unsafe class : com.suntecgroup.xelerate.assets.be.turnoverdata.de.TurnoverDataDE
2020-10-15 16:45:23,627 [WrapperSimpleAppMain] DEBUG org.hibernate.boot.internal.ClassLoaderAccessImpl - Not known whether passed class name [com.suntecgroup.xelerate.assets.be.loyaltyrewarddailybalancelrdbdailybalancedatm.de.LoyaltyRewardDailyBalanceLrdbDailyBalanceDATMDE] is safe
2020-10-15 16:45:23,627 [WrapperSimpleAppMain] DEBUG org.hibernate.boot.internal.ClassLoaderAccessImpl - No temp ClassLoader provided; using live ClassLoader for loading potentially unsafe class : com.suntecgroup.xelerate.assets.be.loyaltyrewarddailybalancelrdbdailybalancedatm.de.LoyaltyRewardDailyBalanceLrdbDailyBalanceDATMDE
Set 6:
2020-10-15 16:45:36,687 [WrapperSimpleAppMain] DEBUG org.hibernate.persister.entity.AbstractEntityPersister - Snapshot select: /* get current state com.suntecgroup.xelerate.assets.be.loyaltycustomerbalancxe.de.LoyaltyCustomerBalancxeDE / select loyaltycus_.pkId, loyaltycus_.createdAt as createdAt2_113_, loyaltycus_.createdBy as createdBy3_113_, loyaltycus_.lcb_last_bal_update_date as lcb_last_bal_updat4_113_, loyaltycus_.lcb_last_earned_quantity as lcb_last_earned_qu5_113_, loyaltycus_.lcb_last_redeemed_quantity as lcb_last_redeemed_6_113_, loyaltycus_.lcb_last_redeemed_date as lcb_last_redeemed_7_113_, loyaltycus_.lcb_last_earned_date as lcb_last_earned_da8_113_, loyaltycus_.lastUpdateAt as lastUpdateAt9_113_, loyaltycus_.lastUpdatedBy as lastUpdatedBy10_113_, loyaltycus_.lcb_balance_date as lcb_balance_date11_113_, loyaltycus_.lcb_cri_id as lcb_cri_id12_113_, loyaltycus_.lcb_cust_no as lcb_cust_no13_113_, loyaltycus_.lcb_deducted_sum as lcb_deducted_sum14_113_, loyaltycus_.lcb_expired_sum as lcb_expired_sum15_113_, loyaltycus_.lcb_groupoprn_bucket_key as lcb_groupoprn_buc16_113_, loyaltycus_.lcb_hash_key as lcb_hash_key17_113_, loyaltycus_.lcb_hashcode as lcb_hashcode18_113_, loyaltycus_.lcb_hold_sum as lcb_hold_sum19_113_, loyaltycus_.lcb_last_activity_date as lcb_last_activity20_113_, loyaltycus_.lcb_rec_count as lcb_rec_count21_113_, loyaltycus_.lcb_redeemed_sum as lcb_redeemed_sum22_113_, loyaltycus_.lcb_reward_balance as lcb_reward_balanc23_113_, loyaltycus_.lcb_reward_id as lcb_reward_id24_113_, loyaltycus_.lcb_reward_sum as lcb_reward_sum25_113_, loyaltycus_.lcb_seq_no as lcb_seq_no26_113_, loyaltycus_.lcb_status as lcb_status27_113_, loyaltycus_.lcb_transferred_in_sum as lcb_transferred_i28_113_, loyaltycus_.lcb_transferred_out_sum as lcb_transferred_o29_113_, loyaltycus_.version as version30_113_ from LYTY_CUSTOMER_BALANCE loyaltycus_ where loyaltycus_.pkId=?
2020-10-15 16:45:36,687 [WrapperSimpleAppMain] DEBUG org.hibernate.persister.entity.AbstractEntityPersister - Insert 0: / insert com.suntecgroup.xelerate.assets.be.loyaltycustomerbalancxe.de.LoyaltyCustomerBalancxeDE / insert into LYTY_CUSTOMER_BALANCE (createdAt, createdBy, lcb_last_bal_update_date, lcb_last_earned_quantity, lcb_last_redeemed_quantity, lcb_last_redeemed_date, lcb_last_earned_date, lastUpdateAt, lastUpdatedBy, lcb_balance_date, lcb_cri_id, lcb_cust_no, lcb_deducted_sum, lcb_expired_sum, lcb_groupoprn_bucket_key, lcb_hash_key, lcb_hashcode, lcb_hold_sum, lcb_last_activity_date, lcb_rec_count, lcb_redeemed_sum, lcb_reward_balance, lcb_reward_id, lcb_reward_sum, lcb_seq_no, lcb_status, lcb_transferred_in_sum, lcb_transferred_out_sum, version, pkId) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
2020-10-15 16:45:36,687 [WrapperSimpleAppMain] DEBUG org.hibernate.persister.entity.AbstractEntityPersister - Update 0: / update com.suntecgroup.xelerate.assets.be.loyaltycustomerbalancxe.de.LoyaltyCustomerBalancxeDE / update LYTY_CUSTOMER_BALANCE set createdAt=?, createdBy=?, lcb_last_bal_update_date=?, lcb_last_earned_quantity=?, lcb_last_redeemed_quantity=?, lcb_last_redeemed_date=?, lcb_last_earned_date=?, lastUpdateAt=?, lastUpdatedBy=?, lcb_balance_date=?, lcb_cri_id=?, lcb_cust_no=?, lcb_deducted_sum=?, lcb_expired_sum=?, lcb_groupoprn_bucket_key=?, lcb_hash_key=?, lcb_hashcode=?, lcb_hold_sum=?, lcb_last_activity_date=?, lcb_rec_count=?, lcb_redeemed_sum=?, lcb_reward_balance=?, lcb_reward_id=?, lcb_reward_sum=?, lcb_seq_no=?, lcb_status=?, lcb_transferred_in_sum=?, lcb_transferred_out_sum=?, version=? where pkId=?
2020-10-15 16:45:36,687 [WrapperSimpleAppMain] DEBUG org.hibernate.persister.entity.AbstractEntityPersister - Delete 0: / delete com.suntecgroup.xelerate.assets.be.loyaltycustomerbalancxe.de.LoyaltyCustomerBalancxeDE */ delete from LYTY_CUSTOMER_BALANCE where pkId=?
set 7
2020-10-15 16:45:37,165 [WrapperSimpleAppMain] DEBUG org.hibernate.persister.walking.spi.MetamodelGraphWalker - Visiting attribute path : createdBy
2020-10-15 16:45:37,165 [WrapperSimpleAppMain] DEBUG org.hibernate.persister.walking.spi.MetamodelGraphWalker - Visiting attribute path : lastUpdateAt
2020-10-15 16:45:37,165 [WrapperSimpleAppMain] DEBUG org.hibernate.persister.walking.spi.MetamodelGraphWalker - Visiting attribute path : lastUpdatedBy
2020-10-15 16:45:37,165 [WrapperSimpleAppMain] DEBUG org.hibernate.persister.walking.spi.MetamodelGraphWalker - Visiting attribute path : timeBucket
2020-10-15 16:45:37,165 [WrapperSimpleAppMain] DEBUG org.hibernate.loader.plan.build.internal.spaces.QuerySpacesImpl - Adding QuerySpace : uid = gen:1 -> org.hibernate.loader.plan.build.internal.spaces.CollectionQuerySpaceImpl@5b28152b]
2020-10-15 16:45:37,165 [WrapperSimpleAppMain] DEBUG org.hibernate.loader.plan.build.internal.spaces.QuerySpacesImpl - Adding QuerySpace : uid = gen:2 -> org.hibernate.loader.plan.build.internal.spaces.CompositeQuerySpaceImpl@fa32355]
Please help how to reduce the startup time?