--Spring Boot + Spring Data Log output and see how SQL statements are issued when updating entities with JPA
├── build.gradle
├── settings.gradle
└── src
└── main
├── java
│ └── com
│ └── example
│ ├── Counter.java
│ ├── CounterController.java
│ ├── CounterRepository.java
│ └── CounterService.java
└── resources
├── application.properties
└── data.sql
build.gradle
plugins {
id 'org.springframework.boot' version '2.2.6.RELEASE'
id 'io.spring.dependency-management' version '1.0.9.RELEASE'
id 'java'
}
group = 'com.example'
version = '0.0.1'
sourceCompatibility = '11'
repositories {
mavenCentral()
}
dependencies {
// Spring
implementation 'org.springframework.boot:spring-boot-starter-web'
implementation 'org.springframework.boot:spring-boot-starter-data-jpa'
// Lombok
compileOnly 'org.projectlombok:lombok'
annotationProcessor 'org.projectlombok:lombok'
// H2 Database
runtimeOnly 'com.h2database:h2'
}
settings.gradle
rootProject.name = 'my-app'
src/main/resources/application.properties
application.properties
#H2 Database settings
#Turn off autocommit AUTOCOMMIT=OFF
#TRACE to output logs_LEVEL_SYSTEM_OUT=Specify 2
spring.datasource.url=jdbc:h2:mem:testdb;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=false;AUTOCOMMIT=OFF;TRACE_LEVEL_SYSTEM_OUT=2
#Specify to output logs such as Spring Framework and Hibernate ORM
logging.level.org.hibernate.SQL=DEBUG
logging.level.org.hibernate.type.descriptor.sql=TRACE
logging.level.org.springframework.orm.jpa=DEBUG
logging.level.com.example=DEBUG
#Do not use the Open EntityManager in View pattern
spring.jpa.open-in-view=false
src/main/resources/data.sql
--Add initial data to DB
INSERT INTO counter (name, count, updated_at) VALUES ('mycounter', 0, LOCALTIMESTAMP);
src/main/java/com/example/Counter.java
Entity class.
package com.example;
import lombok.Data;
import javax.persistence.Entity;
import javax.persistence.Id;
import java.time.LocalDateTime;
/**
*Equivalent to one record in the DB table.
*/
@Data //Lombok automatically generates useful methods such as getter setter
@Entity //Treat as a JPA entity
public class Counter {
//Counter name
@Id //Make JPA recognize this variable as the ID of the object
private String name;
//Count number
private int count;
//Update date and time
private LocalDateTime updatedAt;
}
src/main/java/com/example/CounterController.java
package com.example;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RestController;
import java.util.Map;
@SpringBootApplication
@RestController
@Slf4j // org.slf4j.Automatically generate static final variable log of Logger type
public class CounterController {
public static void main(String[] args) {
SpringApplication.run(CounterController.class, args);
}
@Autowired
private CounterService service;
@GetMapping("/counter/{name}")
public Map counter(@PathVariable("name") String name) {
//Count up
log.debug("Before: countup");
Counter counter = service.countup(name);
log.debug("After: countup");
//Generate JSON response
return Map.of(counter.getName(), counter.getCount());
}
}
src/main/java/com/example/CounterService.java
package com.example;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Service;
import javax.transaction.Transactional;
import java.time.LocalDateTime;
@Service
@Slf4j // org.slf4j.Automatically generate static final variable log of Logger type
public class CounterService {
@Autowired
private CounterRepository repository;
/**
*Count up the counter.
*
* @param name counter name
* @list of return counters
*/
@Transactional //Start transaction at method start, commit at end
public Counter countup(String name) {
//Get 1 record from DB
log.debug("Before: getOne");
Counter counter = repository.getOne(name);
log.debug("After: getOne");
//Update count
log.debug("Before: setCount");
counter.setCount(counter.getCount() + 1);
log.debug("After: setCount");
//Update date and time
log.debug("Before: setUpdatedAt");
counter.setUpdatedAt(LocalDateTime.now());
log.debug("After: setUpdatedAt");
//Get 1 record from DB
log.debug("Before: getOne");
Counter result = repository.getOne(name);
log.debug("After: getOne");
return result;
}
}
src/main/java/com/example/CounterRepository.java
package com.example;
import org.springframework.data.jpa.repository.JpaRepository;
import org.springframework.stereotype.Repository;
/**
*Repository for DB access.
*The method provided by Spring Data JPA as standard is automatically generated.
*/
@Repository
public interface CounterRepository extends JpaRepository<Counter, String> { //Specify entity and primary key types
}
Launch the Spring Boot application with the gradle bootRun task.
$ gradle bootRun
> Task :bootRun
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.2.6.RELEASE)
If you look at the Spring Boot log, you can see that Hibernate ORM 5.4.12.Final is used.
org.hibernate.Version : HHH000412: Hibernate ORM core version 5.4.12.Final
o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.0.Final}
org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
DB table is automatically generated from the entity class definition.
org.hibernate.SQL : drop table counter if exists
org.hibernate.SQL : create table counter (name varchar(255) not null, count integer not null, updated_at timestamp, primary key (name))
o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
H2 Database log. As described in data.sql, an insert statement has been issued.
2020-05-09 23:21:10 jdbc[3]:
/*SQL */drop table counter if exists;
2020-05-09 23:21:10 jdbc[3]:
/*SQL t:6*/create table counter (name varchar(255) not null, count integer not null, updated_at timestamp, primary key (name));
2020-05-09 23:21:10 jdbc[3]:
/*SQL #:1 t:16*/INSERT INTO counter (name, count, updated_at) VALUES ('mycounter', 0, LOCALTIMESTAMP);
Access with the curl command from another terminal.
$ curl http://localhost:8080/counter/mycounter
{"mycounter":1}
Check the Spring Boot log. When calling CounterService # countup.
com.example.CounterController : Before: countup
o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [com.example.CounterService.countup]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
o.s.orm.jpa.JpaTransactionManager : Opened new EntityManager [SessionImpl(1254645459<open>)] for JPA transaction
o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@4ef360f9]
When calling CounterRepository # getOne.
com.example.CounterService : Before: getOne
o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(1254645459<open>)] for JPA transaction
o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
com.example.CounterService : After: getOne
When calling Counter # setCount. It looks like we are finally issuing a select statement here.
com.example.CounterService : Before: setCount
org.hibernate.SQL : select counter0_.name as name1_0_0_, counter0_.count as count2_0_0_, counter0_.updated_at as updated_3_0_0_ from counter counter0_ where counter0_.name=?
o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [VARCHAR] - [mycounter]
o.h.type.descriptor.sql.BasicExtractor : extracted value ([count2_0_0_] : [INTEGER]) - [0]
o.h.type.descriptor.sql.BasicExtractor : extracted value ([updated_3_0_0_] : [TIMESTAMP]) - [2020-05-09T23:21:10.472636]
com.example.CounterService : After: setCount
H2 Database log.
2020-05-09 23:21:19 jdbc[3]:
/*SQL l:153 #:1*/select counter0_.name as name1_0_0_, counter0_.count as count2_0_0_, counter0_.updated_at as updated_3_0_0_ from counter counter0_ where counter0_.name=? {1: 'mycounter'};
2020-05-09 23:21:19 jdbc[3]:
/*SQL l:58 #:1*/SELECT VALUE FROM INFORMATION_SCHEMA.SETTINGS WHERE NAME=? {1: 'QUERY_TIMEOUT'};
When calling Counter # setUpdatedAt. It looks like it hasn't been processed.
com.example.CounterService : Before: setUpdatedAt
com.example.CounterService : After: setUpdatedAt
Even if the entity's setter method is called multiple times (setCount and setUpdatedAt), the update process is not executed at this point.
When calling CounterRepository # getOne.
com.example.CounterService : Before: getOne
o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(1254645459<open>)] for JPA transaction
o.s.orm.jpa.JpaTransactionManager : Participating in existing transaction
com.example.CounterService : After: getOne
After all the code in CounterService # countup is complete, an update statement is issued and committed.
o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(1254645459<open>)]
org.hibernate.SQL : update counter set count=?, updated_at=? where name=?
o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [INTEGER] - [1]
o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [TIMESTAMP] - [2020-05-09T23:21:19.247019]
o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [VARCHAR] - [mycounter]
H2 Database log.
2020-05-09 23:21:19 jdbc[3]:
/*SQL l:53 #:1 t:3*/update counter set count=?, updated_at=? where name=? {1: 1, 2: TIMESTAMP '2020-05-09 23:21:19.247019', 3: 'mycounter'};
2020-05-09 23:21:19 jdbc[3]:
/*SQL */COMMIT;
2020-05-09 23:21:19 jdbc[3]:
/*SQL */COMMIT;
After the transaction.
o.s.orm.jpa.JpaTransactionManager : Closing JPA EntityManager [SessionImpl(1254645459<open>)] after transaction
CounterService # countup call completed.
com.example.CounterController : After: countup
Recommended Posts