I used springboot+JPA+Hibernate to insert data. But the insertion speed of the first data is too slow, and it becomes faster later. I want to eliminate this situation and make all data insertions fast, including the first one. Is there any way to achieve this? Perhaps it can be achieved through configuration changes or some initialization operations. Below are my configurations, all the test code, and test result. And I have uploaded them to GitHub[https://github.com/MayflyShake/heart-test].
my pom.xml:
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>2.2.1.RELEASE</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>
<groupId>com.example</groupId>
<artifactId>heart</artifactId>
<version>0.0.1-SNAPSHOT</version>
<name>heart-test</name>
<description>Demo project for Spring Boot</description>
<properties>
<java.version>1.8</java.version>
<log4j2.version>2.17.0</log4j2.version>
</properties>
<dependencies>
<dependency>
<groupId>mysql</groupId>
<artifactId>mysql-connector-java</artifactId>
<version>6.0.6</version>
</dependency>
<dependency>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
<version>1.18.12</version>
<scope>provided</scope>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter</artifactId>
<exclusions>
<exclusion>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</exclusion>
</exclusions>
</dependency>
<dependency>
<groupId>com.lmax</groupId>
<artifactId>disruptor</artifactId>
<version>3.4.1</version>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-data-jpa</artifactId>
</dependency>
</dependencies>
<build>
<finalName>heart-test-0.0.1-SNAPSHOT</finalName>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-surefire-plugin</artifactId>
</plugin>
</plugins>
</build>
</project>
my application.yml
spring:
datasource:
driver-class-name: com.mysql.cj.jdbc.Driver
url: jdbc:mysql://localhost:3306/tt_test?useSSL=false&serverTimezone=UTC
username: root
password: root
hikari:
maximum-pool-size: 10
minimum-idle: 5
idle-timeout: 30000
pool-name: SpringBootHikariCP
auto-commit: true
connection-timeout: 30000
connection-test-query: SELECT 1
jpa:
hibernate:
database-platform: org.hibernate.dialect.MySQLDialect
ddl-auto: update
show-sql: true
logging:
config: config/log4j2-spring.xml
my entity:
@Slf4j
@Getter
@Setter
@Entity
@Table(name = "test_order")
public class TestOrder implements Serializable {
private static final long serialVersionUID = 1L;
@Id
@GeneratedValue(strategy = GenerationType.IDENTITY)
@Column(name = "order_id", nullable = false)
private Integer orderId;
@Column(name = "create_time")
private String createTime;
@Column(name = "params", columnDefinition = "text")
private String params;
}
my dao:
@Repository
public interface TestOrderDao extends JpaRepository<TestOrder, Integer> {
}
my test main code:
@SpringBootApplication
public class HeartApplication {
public static void main(String[] args) {
ConfigurableApplicationContext context = SpringApplication.run(HeartApplication.class, args);
TestOrderDao testOrderDao = context.getBean(TestOrderDao.class);
String param = "{"param1":"value1"}";
TestOrder t1 = new TestOrder();
t1.setCreateTime("2024-02-29 09:53:00");
t1.setParams(param);
TestOrder t2 = new TestOrder();
t2.setCreateTime("2024-02-29 09:53:00");
t2.setParams(param);
TestOrder t3 = new TestOrder();
t3.setCreateTime("2024-02-29 09:53:00");
t3.setParams(param);
System.out.println("start test");
new Thread(() -> {
try {
Thread.sleep(5000);
} catch (InterruptedException e) {
e.printStackTrace();
}
long begin = System.currentTimeMillis();
testOrderDao.save(t1);
long cost1 = System.currentTimeMillis() - begin;
System.out.println("cost1:" + cost1);
try {
Thread.sleep(5000);
} catch (InterruptedException e) {
e.printStackTrace();
}
long begin2 = System.currentTimeMillis();
testOrderDao.save(t2);
long cost2 = System.currentTimeMillis() - begin2;
System.out.println("cost2:" + cost2);
}).start();
new Thread(() -> {
try {
Thread.sleep(15000);
} catch (InterruptedException e) {
e.printStackTrace();
}
long begin3 = System.currentTimeMillis();
testOrderDao.save(t3);
long cost3 = System.currentTimeMillis() - begin3;
System.out.println("cost3:" + cost3);
}).start();
while (true) {
try {
Thread.sleep(10000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
}
and my test reuslt:
log:
19:37:44.909 [main] DEBUG com.zaxxer.hikari.HikariConfig - SpringBootHikariCP - configuration:
19:37:44.911 [main] DEBUG com.zaxxer.hikari.HikariConfig - allowPoolSuspension................................false
19:37:44.911 [main] DEBUG com.zaxxer.hikari.HikariConfig - autoCommit................................true
19:37:44.911 [main] DEBUG com.zaxxer.hikari.HikariConfig - catalog................................none
19:37:44.911 [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql................................none
19:37:44.911 [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery................................"SELECT 1"
19:37:44.911 [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout................................30000
19:37:44.912 [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSource................................none
19:37:44.912 [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName................................none
19:37:44.912 [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI................................none
19:37:44.912 [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties................................{password=<masked>}
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - driverClassName................................"com.mysql.cj.jdbc.Driver"
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - exceptionOverrideClassName................................none
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties................................{}
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry................................none
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout................................30000
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - initializationFailTimeout................................1
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - isolateInternalQueries................................false
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - jdbcUrl................................jdbc:mysql://localhost:3306/tt_test?useSSL=false&serverTimezone=UTC
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - keepaliveTime................................0
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - leakDetectionThreshold................................0
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime................................1800000
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize................................10
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry................................none
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - metricsTrackerFactory................................none
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle................................5
19:37:44.913 [main] DEBUG com.zaxxer.hikari.HikariConfig - password................................<masked>
19:37:44.915 [main] DEBUG com.zaxxer.hikari.HikariConfig - poolName................................"SpringBootHikariCP"
19:37:44.915 [main] DEBUG com.zaxxer.hikari.HikariConfig - readOnly................................false
19:37:44.915 [main] DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans................................false
19:37:44.915 [main] DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor................................none
19:37:44.915 [main] DEBUG com.zaxxer.hikari.HikariConfig - schema................................none
19:37:44.915 [main] DEBUG com.zaxxer.hikari.HikariConfig - threadFactory................................internal
19:37:44.915 [main] DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation................................default
19:37:44.915 [main] DEBUG com.zaxxer.hikari.HikariConfig - username................................"root"
19:37:44.915 [main] DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout................................5000
19:37:44.915 [main] INFO com.zaxxer.hikari.HikariDataSource - SpringBootHikariCP - Starting...
19:37:45.089 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - SpringBootHikariCP - Added connection com.mysql.cj.jdbc.ConnectionImpl@7be71476
19:37:45.091 [main] INFO com.zaxxer.hikari.HikariDataSource - SpringBootHikariCP - Start completed.
19:37:45.099 [main] DEBUG org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator - Database ->
name : MySQL
version : 5.5.62
major : 5
minor : 5
19:37:45.099 [main] DEBUG org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator - Driver ->
name : MySQL Connector Java
version : mysql-connector-java-6.0.6 ( Revision: 3dab84f4d9bede3cdd14d57b99e9e98a02a5b97d )
major : 6
minor : 0
19:37:45.099 [main] DEBUG org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator - JDBC version : 4.1
19:37:45.119 [main] INFO org.hibernate.dialect.Dialect - HHH000400: Using dialect: org.hibernate.dialect.MySQL55Dialect
19:37:45.137 [main] DEBUG org.hibernate.engine.jdbc.env.spi.IdentifierHelperBuilder - JDBC driver metadata reported database stores quoted identifiers in more than one case
19:37:45.137 [main] DEBUG org.hibernate.engine.jdbc.env.spi.IdentifierHelperBuilder - IdentifierCaseStrategy for both quoted and unquoted identifiers was set to the same strategy [LOWER]; that will likely lead to problems in schema update and validation if using quoted identifiers
19:37:45.173 [main] DEBUG org.hibernate.type.spi.TypeConfiguration$Scope - Scoping TypeConfiguration [org.hibernate.type.spi.TypeConfiguration@70c0a3d5] to MetadataBuildingContext [org.hibernate.boot.internal.MetadataBuildingContextRootImpl@5c8e67b9]
19:37:45.189 [main] DEBUG org.hibernate.boot.model.relational.Namespace - Created database namespace [logicalName=Name{catalog=null, schema=null}, physicalName=Name{catalog=null, schema=null}]
19:37:45.198 [main] DEBUG org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: com.example.heart.pojo.TestOrder
19:37:45.200 [SpringBootHikariCP housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - SpringBootHikariCP - Before cleanup stats (total=1, active=0, idle=1, waiting=0)
19:37:45.200 [SpringBootHikariCP housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - SpringBootHikariCP - After cleanup stats (total=1, active=0, idle=1, waiting=0)
19:37:45.207 [SpringBootHikariCP connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - SpringBootHikariCP - Added connection com.mysql.cj.jdbc.ConnectionImpl@435bedc7
19:37:45.211 [SpringBootHikariCP connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - SpringBootHikariCP - Added connection com.mysql.cj.jdbc.ConnectionImpl@37154be3
19:37:45.216 [SpringBootHikariCP connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - SpringBootHikariCP - Added connection com.mysql.cj.jdbc.ConnectionImpl@63751d50
19:37:45.221 [SpringBootHikariCP connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - SpringBootHikariCP - Added connection com.mysql.cj.jdbc.ConnectionImpl@62380e40
19:37:45.221 [SpringBootHikariCP connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - SpringBootHikariCP - After adding stats (total=5, active=0, idle=5, waiting=0)
19:37:45.228 [main] DEBUG org.hibernate.cfg.Ejb3Column - Binding column: Ejb3DiscriminatorColumn{logicalColumnName'DTYPE', discriminatorTypeName='string'}
19:37:45.236 [main] DEBUG org.hibernate.cfg.annotations.EntityBinder - Import with entity name TestOrder
19:37:45.239 [main] DEBUG org.hibernate.cfg.annotations.EntityBinder - Bind entity com.example.heart.pojo.TestOrder on table test_order
19:37:45.261 [main] DEBUG org.hibernate.cfg.Ejb3Column - Binding column: Ejb3Column{table=org.hibernate.mapping.Table(test_order), mappingColumn=order_id, insertable=true, updatable=true, unique=false}
19:37:45.265 [main] DEBUG org.hibernate.boot.internal.ClassLoaderAccessImpl - Not known whether passed class name [com.example.heart.pojo.TestOrder] is safe
19:37:45.266 [main] DEBUG org.hibernate.boot.internal.ClassLoaderAccessImpl - No temp ClassLoader provided; using live ClassLoader for loading potentially unsafe class : com.example.heart.pojo.TestOrder
19:37:45.266 [main] DEBUG org.hibernate.cfg.annotations.PropertyBinder - MetadataSourceProcessor property orderId with lazy=false
19:37:45.267 [main] DEBUG org.hibernate.cfg.AbstractPropertyHolder - Attempting to locate auto-apply AttributeConverter for property [com.example.heart.pojo.TestOrder:orderId]
19:37:45.270 [main] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - building SimpleValue for orderId
19:37:45.274 [main] DEBUG org.hibernate.cfg.annotations.PropertyBinder - Building property orderId
19:37:45.279 [main] DEBUG org.hibernate.cfg.BinderHelper - #makeIdGenerator(org.hibernate.mapping.SimpleValue([org.hibernate.mapping.Column(order_id)]), orderId, identity, , ...)
19:37:45.280 [main] DEBUG org.hibernate.cfg.Ejb3Column - Binding column: Ejb3Column{table=org.hibernate.mapping.Table(test_order), mappingColumn=create_time, insertable=true, updatable=true, unique=false}
19:37:45.280 [main] DEBUG org.hibernate.cfg.annotations.PropertyBinder - MetadataSourceProcessor property createTime with lazy=false
19:37:45.280 [main] DEBUG org.hibernate.cfg.AbstractPropertyHolder - Attempting to locate auto-apply AttributeConverter for property [com.example.heart.pojo.TestOrder:createTime]
19:37:45.280 [main] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - building SimpleValue for createTime
19:37:45.280 [main] DEBUG org.hibernate.cfg.annotations.PropertyBinder - Building property createTime
19:37:45.340 [main] DEBUG org.hibernate.cfg.Ejb3Column - Binding column: Ejb3Column{table=org.hibernate.mapping.Table(test_order), mappingColumn=params, insertable=true, updatable=true, unique=false}
19:37:45.340 [main] DEBUG org.hibernate.cfg.annotations.PropertyBinder - MetadataSourceProcessor property params with lazy=false
19:37:45.340 [main] DEBUG org.hibernate.cfg.AbstractPropertyHolder - Attempting to locate auto-apply AttributeConverter for property [com.example.heart.pojo.TestOrder:params]
19:37:45.341 [main] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - building SimpleValue for params
19:37:45.341 [main] DEBUG org.hibernate.cfg.annotations.PropertyBinder - Building property params
19:37:45.351 [main] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - Starting fillSimpleValue for orderId
19:37:45.351 [main] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - Starting fillSimpleValue for createTime
19:37:45.351 [main] DEBUG org.hibernate.cfg.annotations.SimpleValueBinder - Starting fillSimpleValue for params
19:37:45.352 [main] DEBUG org.hibernate.mapping.PrimaryKey - Forcing column [order_id] to be non-null as it is part of the primary key for table [test_order]
19:37:45.391 [main] DEBUG org.hibernate.internal.SessionFactoryImpl - Building session factory
19:37:45.392 [main] DEBUG org.hibernate.cfg.Settings - SessionFactory name : null
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Automatic flush during beforeCompletion(): enabled
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Automatic session close at end of transaction: disabled
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Statistics: disabled
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Deleted entity synthetic identifier rollback: disabled
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Default entity-mode: pojo
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Check Nullability in Core (should be disabled when Bean Validation is on): enabled
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Allow initialization of lazy state outside session : disabled
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Using BatchFetchStyle : LEGACY
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Default batch fetch size: -1
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Maximum outer join fetch depth: 2
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Default null ordering: NONE
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Order SQL updates by primary key: disabled
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - Order SQL inserts for batching: disabled
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - multi-tenancy strategy : NONE
19:37:45.393 [main] DEBUG org.hibernate.cfg.Settings - JTA Track by Thread: enabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Query language substitutions: {}
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Named query checking : enabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Second-level cache: disabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Second-level query cache: disabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Second-level query cache factory: null
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Second-level cache region prefix: null
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Optimize second-level cache for minimal puts: disabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Structured second-level cache entries: disabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Second-level cache direct-reference entries: disabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Automatic eviction of collection cache: disabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - JDBC batch size: 15
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - JDBC batch updates for versioned data: enabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Scrollable result sets: enabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - Wrap result sets: disabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - JDBC3 getGeneratedKeys(): enabled
19:37:45.394 [main] DEBUG org.hibernate.cfg.Settings - JDBC result set fetch size: null
19:37:45.395 [main] DEBUG org.hibernate.cfg.Settings - Connection release mode: ON_CLOSE
19:37:45.395 [main] DEBUG org.hibernate.cfg.Settings - Generate SQL with comments: disabled
19:37:45.395 [main] DEBUG org.hibernate.cfg.Settings - JPA compliance - query : disabled
19:37:45.395 [main] DEBUG org.hibernate.cfg.Settings - JPA compliance - closed-handling : disabled
19:37:45.395 [main] DEBUG org.hibernate.cfg.Settings - JPA compliance - lists : disabled
19:37:45.395 [main] DEBUG org.hibernate.cfg.Settings - JPA compliance - transactions : disabled
19:37:45.451 [main] DEBUG org.hibernate.service.internal.SessionFactoryServiceRegistryImpl - EventListenerRegistry access via ServiceRegistry is deprecated. Use `sessionFactory.getEventEngine().getListenerRegistry()` instead
19:37:45.451 [main] DEBUG org.hibernate.service.internal.SessionFactoryServiceRegistryImpl - EventListenerRegistry access via ServiceRegistry is deprecated. Use `sessionFactory.getEventEngine().getListenerRegistry()` instead
19:37:45.463 [main] DEBUG org.hibernate.internal.SessionFactoryImpl - Session factory constructed with filter configurations : {}
...
start test
19:37:51.556 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
19:37:51.556 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Opened new EntityManager [SessionImpl(1291825417<open>)] for JPA transaction
19:37:51.558 [Thread-10] DEBUG org.hibernate.engine.transaction.internal.TransactionImpl - On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
19:37:51.558 [Thread-10] DEBUG org.hibernate.engine.transaction.internal.TransactionImpl - begin
19:37:51.560 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@d83e70a]
19:37:51.577 [Thread-10] DEBUG org.hibernate.engine.spi.ActionQueue - Executing identity-insert immediately
Hibernate: insert into test_order (create_time, params) values (?, ?)
19:37:51.579 [Thread-10] DEBUG org.hibernate.SQL - insert into test_order (create_time, params) values (?, ?)
19:37:51.588 [Thread-10] DEBUG org.hibernate.id.IdentifierGeneratorHelper - Natively generated identity: 28
19:37:51.588 [Thread-10] DEBUG org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl - HHH000387: ResultSet's statement was not registered
19:37:51.591 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Initiating transaction commit
19:37:51.591 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [SessionImpl(1291825417<open>)]
19:37:51.591 [Thread-10] DEBUG org.hibernate.engine.transaction.internal.TransactionImpl - committing
19:37:51.591 [Thread-10] DEBUG org.hibernate.event.internal.AbstractFlushingEventListener - Processing flush-time cascades
19:37:51.592 [Thread-10] DEBUG org.hibernate.event.internal.AbstractFlushingEventListener - Dirty checking collections
19:37:51.595 [Thread-10] DEBUG org.hibernate.event.internal.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
19:37:51.595 [Thread-10] DEBUG org.hibernate.event.internal.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
19:37:51.596 [Thread-10] DEBUG org.hibernate.internal.util.EntityPrinter - Listing entities:
19:37:51.596 [Thread-10] DEBUG org.hibernate.internal.util.EntityPrinter - com.example.heart.pojo.TestOrder{orderId=28, createTime=2024-02-29 09:53:00, params={"param1":"value1"}}
19:37:51.600 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Closing JPA EntityManager [SessionImpl(1291825417<open>)] after transaction
cost1:52
19:37:56.615 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Creating new transaction with name [org.springframework.data.jpa.repository.support.SimpleJpaRepository.save]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
19:37:56.615 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Opened new EntityManager [SessionImpl(1230646393<open>)] for JPA transaction
19:37:56.615 [Thread-10] DEBUG org.hibernate.engine.transaction.internal.TransactionImpl - On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
19:37:56.615 [Thread-10] DEBUG org.hibernate.engine.transaction.internal.TransactionImpl - begin
19:37:56.616 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@37ecaae]
Hibernate: insert into test_order (create_time, params) values (?, ?)
19:37:56.616 [Thread-10] DEBUG org.hibernate.engine.spi.ActionQueue - Executing identity-insert immediately
19:37:56.616 [Thread-10] DEBUG org.hibernate.SQL - insert into test_order (create_time, params) values (?, ?)
19:37:56.617 [Thread-10] DEBUG org.hibernate.id.IdentifierGeneratorHelper - Natively generated identity: 29
19:37:56.617 [Thread-10] DEBUG org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl - HHH000387: ResultSet's statement was not registered
19:37:56.617 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Initiating transaction commit
19:37:56.617 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [SessionImpl(1230646393<open>)]
19:37:56.617 [Thread-10] DEBUG org.hibernate.engine.transaction.internal.TransactionImpl - committing
19:37:56.617 [Thread-10] DEBUG org.hibernate.event.internal.AbstractFlushingEventListener - Processing flush-time cascades
19:37:56.617 [Thread-10] DEBUG org.hibernate.event.internal.AbstractFlushingEventListener - Dirty checking collections
19:37:56.619 [Thread-10] DEBUG org.hibernate.event.internal.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
19:37:56.619 [Thread-10] DEBUG org.hibernate.event.internal.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
19:37:56.619 [Thread-10] DEBUG org.hibernate.internal.util.EntityPrinter - Listing entities:
19:37:56.619 [Thread-10] DEBUG org.hibernate.internal.util.EntityPrinter - com.example.heart.pojo.TestOrder{orderId=29, createTime=2024-02-29 09:53:00, params={"param1":"value1"}}
19:37:56.621 [Thread-10] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Closing JPA EntityManager [SessionImpl(1230646393<open>)] after transaction
cost2:6
2
Answers
The slowness you’re experiencing with the first data insertion is likely due to Hibernate’s first-level cache being empty. When you save the first object, Hibernate needs to perform additional operations like schema validation, SQL statement generation, and potential connection pool initialization. These initial activities can cause a delay for the first insertion. Subsequent insertions are faster because the necessary information is already cached by Hibernate, making the process more efficient.
Try This:
Enable Hibernate Cache
As you alreeady know Hibernate provides a built-in caching mechanism that can significantly improve performance, especially for frequently accessed data
So you need to enable caching by adding the following configuration to your application.yml file:
For More Info Follow this Link : https://ignite.apache.org/docs/latest/extensions-and-integrations/hibernate-l2-cache
This test is incorrect. Java and a lot of framework/library take some time to "warm up".
You are lucky to have a reproducible result after only three occurences.
We need more information on what you try to achieve.
As stated in jmh (test framework for jdk micro-benchmark), you have to warm up the jvm, hibernate, database… in order to get a reproducible result. Check examples on project jmh