In my project I have a problem with one JPQL query which takes about 1,5s. When I execute SQL query copied from debug log (the same one which executes Hibernates) direct on PostgreSQL db it takes about 15ms.
@Service
@Transactional
@Slf4j
public class PersonSyncServiceImpl
extends HotelApiCommunicationService implements PersonSyncService {
[...]
private PersonLinked getLinkedPerson(CNPerson cnPerson, Obiekt obiekt) {
PersonLinked person = cnPerson.getPersonLinked();
if (person == null) {
var o = cnPerson;
List<PersonLinked> personList = personLinkedDao.findPersonLinkedByRecordData(
o.getPersonImiona(), o.getPersonNazwisko(), o.getPersonPesel(), o.getPersonEmail(), o.getPersonTelefon1());
person = personList.stream()
.findFirst().orElse(null);
if (person == null) {
person = createPersonLinkedFromCnPerson(cnPerson);
personLinkedDao.save(person);
}
cnPerson.setPersonLinked(person);
}
return person;
}
[...]
}
Problem is with this line:
List<PersonLinked> personList = personLinkedDao.findPersonLinkedByRecordData(
o.getPersonImiona(), o.getPersonNazwisko(), o.getPersonPesel(), o.getPersonEmail(), o.getPersonTelefon1());
Dao with defined query:
@Repository
@Transactional
public interface PersonLinkedDao extends JpaRepository<PersonLinked, Long> {
@Query("select o from PersonLinked o \n" +
"where o.personImiona = :imie and o.personNazwisko = :nazwisko \n" +
" and (o.personPesel = :pesel or o.personEmail = :email or o.personTelefon1 = :telefon)")
List<PersonLinked> findPersonLinkedByRecordData(
@Param("imie") String personImiona,
@Param("nazwisko") String personNazwisko,
@Param("pesel") String personPesel,
@Param("email") String personEmail,
@Param("telefon") String personTelefon);
}
SQL from Hibernate debug log:
select [..]
from
person personlinke0_
where
personlinke0_.person_imiona=?
and personlinke0_.person_nazwisko=?
and (
personlinke0_.person_pesel=?
or personlinke0_.person_email=?
or personlinke0_.person_telefon1=?
)
When I execute this query on database it takes about 15ms, execution from code takes about 1,5s. I commented out this line in code and lag disappeared, so for sure problem is this jpql select.
Database connection configuration:
spring.datasource.driver-class-name=org.postgresql.Driver
spring.jpa.database-platform=org.hibernate.dialect.PostgreSQL9Dialect
spring.datasource.url=jdbc:postgresql://192.168.1.200:5433/XXXXXXX
spring.datasource.username=XXXXX
spring.datasource.password=XXXXX
spring.jpa.show-sql=false
spring.jpa.properties.hibernate.format_sql=true
spring.jpa.properties.hibernate.jdbc.batch_size=50
spring.jpa.properties.hibernate.order_inserts=true
spring.jpa.properties.hibernate.generate_statistics=true
UPDATE 1:
debug.log:
26-09-2020 16:06:36.130 [http-nio-8091-exec-2] DEBUG org.hibernate.SQL.logStatement -
select [...]
from
person personlinke0_
where
personlinke0_.person_imiona=?
and personlinke0_.person_nazwisko=?
and (
personlinke0_.person_pesel=?
or personlinke0_.person_email=?
or personlinke0_.person_telefon1=?
)
26-09-2020 16:06:36.130 [http-nio-8091-exec-2] DEBUG o.s.orm.jpa.JpaTransactionManager.doGetTransaction - Found thread-bound EntityManager [SessionImpl(1971671100<open>)] for JPA transaction
26-09-2020 16:06:36.130 [http-nio-8091-exec-2] DEBUG o.s.orm.jpa.JpaTransactionManager.handleExistingTransaction - Participating in existing transaction
26-09-2020 16:06:36.146 [http-nio-8091-exec-2] DEBUG o.s.orm.jpa.JpaTransactionManager.doGetTransaction - Found thread-bound EntityManager [SessionImpl(1971671100<open>)] for JPA transaction
26-09-2020 16:06:36.146 [http-nio-8091-exec-2] DEBUG o.s.orm.jpa.JpaTransactionManager.handleExistingTransaction - Participating in existing transaction
26-09-2020 16:06:36.146 [http-nio-8091-exec-2] DEBUG o.s.orm.jpa.JpaTransactionManager.doGetTransaction - Found thread-bound EntityManager [SessionImpl(1971671100<open>)] for JPA transaction
26-09-2020 16:06:36.146 [http-nio-8091-exec-2] DEBUG o.s.orm.jpa.JpaTransactionManager.handleExistingTransaction - Participating in existing transaction
26-09-2020 16:06:37.521 [http-nio-8091-exec-2] DEBUG org.hibernate.SQL.logStatement -
UPDATE 2:
PersonLinked entity class:
@Entity
@Table(name = "person")
@Getter
@Setter
@SuperBuilder
@EqualsAndHashCode(of = "personId")
public class PersonLinked extends SCPerson {
@Id
@GeneratedValue(generator = "seq_person", strategy = GenerationType.SEQUENCE)
@SequenceGenerator(name = "seq_person", sequenceName = "seq_person", allocationSize = 30)
@Column(name = "OSOBA_ID", nullable = false)
private Long personId;
@OneToMany(mappedBy = "personLinked", fetch = FetchType.LAZY)
private List<CNPerson> cnPersonList;
@Tolerate
public PersonLinked() {
super();
}
@PrePersist
@Override
protected void preInsert() {
super.preInsert();
}
}
SCPerson class:
@MappedSuperclass
@Getter
@Setter
@SuperBuilder
public class SCPerson {
[...]
}
Finally I found a solution, problem was in another part of code. Before calling method getLinkedPerson() I had this line of code:
List<CNPerson> cnPersonList = cnPersonDao.findCnPersonNotLinkedWithPerson(obiekt.getLoid());
cnPersonList constans here about 70 000 objects.
I changed it to:
List<Integer> ids = cnPersonDao.findCnPersonIdsNotLinkedWithPerson(obiekt.getLoid());
Problem is described here: https://stackoverflow.com/a/46258045/9678458
Slow down during Hibernate context refresh. In case when you update too many objects ORM engine (lets say Hibernate) has to sink them and keep them in memory. Literally Hibernate must have all old states and all new states of updated objects. Sometimes it does this quite unoptimal.
You can indicate this using debug. Try to find the slowest place and check what exactly is being invoked there. I might guess that it slows down when hibernate updates state of the cache.
I think it is because entities CNPerson and PersonLinked are linked, but I am not sure:
@ManyToOne(fetch = FetchType.LAZY,
cascade = {CascadeType.MERGE, CascadeType.PERSIST})
@JoinTable(name = "cnperson_links",
joinColumns = {@JoinColumn(name = "cnperson_loid")},
inverseJoinColumns = {@JoinColumn(name = "person_id")})
private PersonLinked personLinked;