Hibernate-FIX: Why request the initial POST/PUT API takes long time in Hibernate Springboot

tothemoon
  May 13, 2023
Java  Hibernate  JPA 
   530 Words  3 mins  

Discover

Our project is Springboot + hibernate, each time I deploy the project to the cloud(not only the cloud, but also in the local dev), the first POST/PUT API need long time to execute.

We make several assumptions:

  • DNS lookup
  • TCP Handshake and SSL Handshake
  • AWS RDS performance
  • Code problem

Assumption

Assumption 1 — DNS lookup

In Postman, obviously it’s an ideal time. So, move to the next.

Assumption 2 —TCP/SSL Handshake

Check the speed of handshake. Here is CLI, there is no any exception. So, move to the next.

curl -w "TCP handshake: %{time_connect}, SSL handshake: %{time_appconnect}\n" -so /dev/null https://{your domain}

TCP handshake: 0.057688, SSL handshake: 0.100967

Assumption 3 — AWS RDS

How to troubleshoot this problem? I run the server locally and connect to the AWS RDS as a DB source. as long as the server run locally, there is no any delay between RDS and backend, in other words, the problem is not related to RDS. Definitely code leads to potential bugs.

Assumption 4

This screenshot already told me where is the problem happend there.

However, troubleshooting in the backend is tedious.

Firstly, Warping the execution code:

1
2
3

long start = System.currentTimeMillis();
long end = System.currentTimeMillis();
log.error("Elapsed Time in milli seconds: "+ (end-start));

For example:

In controller:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

@PostMapping(produces = "application/json")
public ResponseEntity<SupplierOrderDTO> createSupplierOrder(
    @Valid @RequestBody SupplierOrderDTO supplierOrderDTO) {
    long start = System.currentTimeMillis();

    SupplierOrder savedSupplierOrder = supplierOrderService.createOrder(
            supplierOrderMapper.toEntity(supplierOrderDTO));
    long end = System.currentTimeMillis();
    log.error("Elapsed Time in milli seconds: "+ (end-start));
    return new ResponseEntity<>(supplierOrderMapper.toDTO(savedSupplierOrder), HttpStatus.CREATED);
}

In service :

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20

public SupplierOrder createOrder(SupplierOrder newSupplierOrder) {
    long start = System.currentTimeMillis();

    SupplierOrder savedSupplierOrder = saveOrder(newSupplierOrder);
 
    long end = System.currentTimeMillis();
    log.error("Elapsed Time in milli seconds: "+ (end-start));
    
    return savedSupplierOrder;
}
private SupplierOrder saveOrder(SupplierOrder supplierOrderToSave) {
    long start = System.currentTimeMillis();

    SupplierOrder supplierOrder =  supplierOrderRepository.save(supplierOrderToSave);

    long end = System.currentTimeMillis();
    log.error("Elapsed Time in milli seconds: "+ (end-start));
    
    return supplierOrder;
}

Print all the sql statement, we need to change some configuration in yml file:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

jpa:
  database-platform: org.hibernate.dialect.MySQL5InnoDBDialect
  database: MYSQL
  show-sql: true #show sql
  properties:
    hibernate.id.new_generator_mappings: true
    hibernate.cache.use_second_level_cache: false
    hibernate.cache.use_query_cache: false
    hibernate.format_sql: true  #show sql
    hibernate.generate_statistics: true  #show sql

Then package the project run in inbuilt tomcat. Run this CLI in terminal under the target folder.

1

 java -jar (warname).war

After the program start, head to Postman, run “create an order api”.

It takes 17s!!!!! insert method takes 16s, so let’s head to source code.

In the save method, before execute the creaete an order(add a new record to DB), the inner method will check the entity is already in the DB or not, so it will query in the DB. In fact, when I execute [persist] method. It faster than before. So I suppose, something happened in isNew function.

I found a solution finally. Just overwrite the isNew function in each entity class.

https://stackoverflow.com/questions/27573023/how-spring-data-jpa-decides-to-call-entitymanager-persist-or-entitymanager-me

When I depoly to the cloud and execute the create function, it only takes 1s in the initial request!

I am not sure it is a temporary fix or not…..