All code in this post can be found here: https://github.com/cuipengfei/gs-accessing-data-jpa/tree/master/complete
You can run this test to reproduce the problem: https://github.com/cuipengfei/gs-accessing-data-jpa/blob/master/complete/src/test/java/hello/T1ServiceTest.java
I have a domain model:
{code:java}
@Entity
@Table(name = "t1", schema = "test")
public class T1 extends BaseEntity {
@Column(nullable = false)
private UUID someField;
@Column()
private ZonedDateTime date;
public T1(UUID someField, ZonedDateTime date) {
this.someField = someField;
this.date = date;
}
}
{code}
It has a field typed as ZonedDateTime, so I have a converter to convert it to sql time stamp:
{code:java}
@Converter(autoApply = true)
public class ZonedDateTimeAttributeConverter
implements AttributeConverter<ZonedDateTime, Timestamp> {
@Override
public Timestamp convertToDatabaseColumn(ZonedDateTime entityValue) {
return (entityValue == null) ? null :
valueOf(entityValue.withZoneSameInstant(of("UTC")).toLocalDateTime());
}
@Override
public ZonedDateTime convertToEntityAttribute(Timestamp databaseValue) {
return (databaseValue == null) ? null : databaseValue.toLocalDateTime().atZone(
of("UTC"));
}
}
{code}
When I try to create a lot of T1s in a transaction like this:
{code:java}
@Service
public class T1Service {
private static final Logger log = LoggerFactory.getLogger(T1Service.class);
@Autowired
T1Repository t1Repository;
@Transactional
public void insertMany() {
for (int i = 0; i < 1000; i++) {
log.info("!!! " + (i + 1) + "th item start");
UUID randomUUID = UUID.randomUUID();
T1 foundT1 = tryToFindExistingT1(randomUUID);//certainly won't find
if (foundT1 == null) {
log.info("t1 not found");
ZonedDateTime date = now();
//date = null;
//if you enable the line above, there won't be any update statements anymore
//and find will also become faster
T1 t1 = new T1(randomUUID, date);
saveT1(t1);
}
log.info("!!! " + (i + 1) + "th item finished");
log.info("====================================");
}
}
private T1 tryToFindExistingT1(UUID someField) {
long start = currentTimeMillis();
T1 t1Id = t1Repository.findBySomeField(someField);
//as nth item increases, the line above will become very very slow
//and also, there will be more and more update statements
//but if you set date of t1 to null, update statement will disappear and it'll not be slow
log.info("find took: " + (currentTimeMillis() - start) + " milliseconds");
return t1Id;
}
private T1 saveT1(T1 t1) {
long start = currentTimeMillis();
T1 savedT1 = t1Repository.save(t1);
log.info("save took: " + (currentTimeMillis() - start) + " milliseconds");
return savedT1;
}
}
{code}
There will be update statements generated by hibernate for the whole t1 table.
Here is the log for the first a few rounds of the for loop:
{code:java}
2017-03-20 17:51:54.039 INFO 74789 --- [ main] hello.T1Service : !!! 1th item start
2017-03-20 17:51:54.052 INFO 74789 --- [ main] o.h.h.i.QueryTranslatorFactoryInitiator : HHH000397: Using ASTQueryTranslatorFactory
Hibernate: select t1x0_.id as id1_0_, t1x0_.date as date2_0_, t1x0_.some_field as some_fie3_0_ from test.t1 t1x0_ where t1x0_.some_field=?
2017-03-20 17:51:54.154 INFO 74789 --- [ main] hello.T1Service : find took: 114 milliseconds
2017-03-20 17:51:54.154 INFO 74789 --- [ main] hello.T1Service : t1 not found
2017-03-20 17:51:54.177 INFO 74789 --- [ main] hello.T1Service : save took: 15 milliseconds
2017-03-20 17:51:54.177 INFO 74789 --- [ main] hello.T1Service : !!! 1th item finished
2017-03-20 17:51:54.177 INFO 74789 --- [ main] hello.T1Service : ====================================
2017-03-20 17:51:54.177 INFO 74789 --- [ main] hello.T1Service : !!! 2th item start
Hibernate: insert into test.t1 (date, some_field, id) values (?, ?, ?)
Hibernate: update test.t1 set date=?, some_field=? where id=?
Hibernate: select t1x0_.id as id1_0_, t1x0_.date as date2_0_, t1x0_.some_field as some_fie3_0_ from test.t1 t1x0_ where t1x0_.some_field=?
2017-03-20 17:51:54.194 INFO 74789 --- [ main] hello.T1Service : find took: 17 milliseconds
2017-03-20 17:51:54.194 INFO 74789 --- [ main] hello.T1Service : t1 not found
2017-03-20 17:51:54.195 INFO 74789 --- [ main] hello.T1Service : save took: 1 milliseconds
2017-03-20 17:51:54.195 INFO 74789 --- [ main] hello.T1Service : !!! 2th item finished
2017-03-20 17:51:54.195 INFO 74789 --- [ main] hello.T1Service : ====================================
2017-03-20 17:51:54.195 INFO 74789 --- [ main] hello.T1Service : !!! 3th item start
Hibernate: insert into test.t1 (date, some_field, id) values (?, ?, ?)
Hibernate: update test.t1 set date=?, some_field=? where id=?
Hibernate: update test.t1 set date=?, some_field=? where id=?
Hibernate: select t1x0_.id as id1_0_, t1x0_.date as date2_0_, t1x0_.some_field as some_fie3_0_ from test.t1 t1x0_ where t1x0_.some_field=?
2017-03-20 17:51:54.200 INFO 74789 --- [ main] hello.T1Service : find took: 4 milliseconds
2017-03-20 17:51:54.200 INFO 74789 --- [ main] hello.T1Service : t1 not found
2017-03-20 17:51:54.200 INFO 74789 --- [ main] hello.T1Service : save took: 0 milliseconds
2017-03-20 17:51:54.200 INFO 74789 --- [ main] hello.T1Service : !!! 3th item finished
2017-03-20 17:51:54.200 INFO 74789 --- [ main] hello.T1Service : ====================================
2017-03-20 17:51:54.200 INFO 74789 --- [ main] hello.T1Service : !!! 4th item start
Hibernate: insert into test.t1 (date, some_field, id) values (?, ?, ?)
Hibernate: update test.t1 set date=?, some_field=? where id=?
Hibernate: update test.t1 set date=?, some_field=? where id=?
Hibernate: update test.t1 set date=?, some_field=? where id=?
Hibernate: select t1x0_.id as id1_0_, t1x0_.date as date2_0_, t1x0_.some_field as some_fie3_0_ from test.t1 t1x0_ where t1x0_.some_field=?
2017-03-20 17:51:54.209 INFO 74789 --- [ main] hello.T1Service : find took: 9 milliseconds
2017-03-20 17:51:54.209 INFO 74789 --- [ main] hello.T1Service : t1 not found
2017-03-20 17:51:54.210 INFO 74789 --- [ main] hello.T1Service : save took: 1 milliseconds
2017-03-20 17:51:54.210 INFO 74789 --- [ main] hello.T1Service : !!! 4th item finished
2017-03-20 17:51:54.210 INFO 74789 --- [ main] hello.T1Service : ====================================
{code}
As you can see in the log, more and more update statements will be generated by hibernate.
It looks like the number of update statements is always same as how many rows of T1 waiting to be committed.
Now if I remove the converter, this problem goes away.
I can use hibernate-java8 lib instead of this converter to achieve the same effect, but why does this happen?
Why does JPA AttributeConverter make hibernate generate update statements on whole table in transaction? |
|
