Разоблачение JPA транзакции занимает слишком много времени - PullRequest
Новая
       25

Разоблачение JPA транзакции занимает слишком много времени

0 голосов
/ 13 сентября 2018

Я работал с SpringBoot 1.5.10.RELEASE, Postgre Server 9.6, версия драйвера 9.4.1212.jre7, tomcat-jdbc (версия spring bom).

Вот конфигурация JPA:

  • spring.datasource.driver-class-name = org.postgresql.Driver
  • spring.jpa.hibernate.ddl-auto = нет
  • spring.jpa.database-platform = org.hibernate.dialect.PostgreSQLDialect

Код Java:

AssureMaladieController.java 

@BasePathAwareController 
public class AssureMaladieController {

@Autowired
IAssureMaladieService assureMaladieService;

@Autowired
RepositoryEntityLinks repositoryEntityLinks;


@RequestMapping(value = "/assures/{id}/reglements/find", method = RequestMethod.GET)
@ResponseBody
public ResponseEntity<AbstractSupport> getReglements(@PathVariable Long id, @RequestParam EnumTypeReglement typeReglement, @RequestParam @DateTimeFormat(pattern = "yyyy-MM-dd") Date date ) {
    log.trace("entrée dans getReglements")
    List<Reglement> reglements =assureMaladieService.getReglementsAfter(id,typeReglement, date);
}

AssureMaladieService.java 

@Service
public class AssureMaladieService implements IAssureMaladieService{

@Autowired
private ReglementRepository reglementRepository;

@Transactional
public List<Reglement> getReglementsAfter(Long idAssure, EnumTypeReglement typeReglement, Date dateDebut){
    log.trace("entrée dans getReglementsAfter")
    if (personnePhysiqueRepository.findOne(idAssure)== null){
        throw new RessourceNonTrouveeException();
    }
    List<Reglement> reglements= reglementRepository.findByAssureMaladie_IdAndTypeReglement_CodeAndDateGreaterThanEqualOrderByDateDesc(idAssure,typeReglement,dateDebut);

    return reglements;
}

ReglementRepository.java 

import org.springframework.data.repository.CrudRepository;

@RepositoryRestResource(path="reglements")
public interface ReglementRepository extends CrudRepository<Reglement,Long> {    

    @Override
    @PostAuthorize("(returnObject!=null?hasPermission(returnObject.assureMaladie.matricule, 'maladie','R'):true)")
    Reglement findOne(@Param("id")Long var1);
}

Иногда JPA требуется несколько минут, чтобы перейти от первого класса ко второму

В ненормальном случае журналы: 

2018-09-13 14:36:54.826 DEBUG 21979 --- [http-nio-8001-exec-9] n.c.g.c.i.c.AssureMaladieController      : entrée dans getReglements avec les id : 484608 type règlement : ASSURE date : Mon Aug 13 00:00:00 NCT 2018
2018-09-13 14:36:54.826 DEBUG 21979 --- [http-nio-8001-exec-9] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [nc.cafat.gen.cli.impl.service.AssureMaladieService.getReglementsAfter]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2018-09-13 14:36:54.826 DEBUG 21979 --- [http-nio-8001-exec-9] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@1cf1ad2a] for JPA transaction
2018-09-13 14:52:32.272 DEBUG 21979 --- [http-nio-8001-exec-9] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@665fa46c]
2018-09-13 14:52:32.273 TRACE 21979 --- [http-nio-8001-exec-9] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@7329c08c] for key [org.apache.tomcat.jdbc.pool.DataSource@4165b803{ConnectionPool[defaultAutoCommit=null; defaultReadOnly=null; defaultTransactionIsolation=-1; defaultCatalog=null; driverClassName=org.postgresql.Driver; maxActive=100; maxIdle=100; minIdle=10; initialSize=10; maxWait=30000; testOnBorrow=true; testOnReturn=false; timeBetweenEvictionRunsMillis=5000; numTestsPerEvictionRun=0; minEvictableIdleTimeMillis=60000; testWhileIdle=false; testOnConnect=false; password=********; url=jdbc:postgresql://DBPG-PRD-80:5432/prd_cafat_01; username=prdcafatuser; validationQuery=SELECT 1; validationQueryTimeout=-1; validatorClassName=null; validationInterval=3000; accessToUnderlyingConnectionAllowed=true; removeAbandoned=false; removeAbandonedTimeout=60; logAbandoned=false; connectionProperties=null; initSQL=null; jdbcInterceptors=null; jmxEnabled=true; fairQueue=true; useEquals=true; abandonWhenPercentageFull=0; maxAge=0; useLock=false; dataSource=null; dataSourceJNDI=null; suspectTimeout=0; alternateUsernameAllowed=false; commitOnReturn=false; rollbackOnReturn=false; useDisposableConnectionFacade=true; logValidationErrors=false; propagateInterruptState=false; ignoreExceptionOnPreLoad=false; useStatementFacade=true; }] to thread [http-nio-8001-exec-9]
2018-09-13 14:52:32.273 TRACE 21979 --- [http-nio-8001-exec-9] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@189284e4] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@30d8f1e5] to thread [http-nio-8001-exec-9]
2018-09-13 14:52:32.273 TRACE 21979 --- [http-nio-8001-exec-9] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2018-09-13 14:52:32.273 TRACE 21979 --- [http-nio-8001-exec-9] o.s.t.i.TransactionInterceptor           : Getting transaction for [nc.cafat.gen.cli.impl.service.AssureMaladieService.getReglementsAfter]
2018-09-13 14:52:32.273 DEBUG 21979 --- [http-nio-8001-exec-9] n.c.g.c.i.service.AssureMaladieService   : entrée dans getReglementsAfter avec les idAssure : 484608 type règlement : ASSURE dateDebut : Mon Aug 13 00:00:00 NCT 2018

Более 15 минут!

В обычном случае журналы: 

2018-09-13 14:56:47.796 DEBUG 21979 --- [http-nio-8001-exec-6] n.c.g.c.i.c.AssureMaladieController      : entrée dans getReglements avec les id : 484608 type règlement : ASSURE date : Mon Aug 13 00:00:00 NCT 2018
2018-09-13 14:56:47.796 DEBUG 21979 --- [http-nio-8001-exec-6] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [nc.cafat.gen.cli.impl.service.AssureMaladieService.getReglementsAfter]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
2018-09-13 14:56:47.797 DEBUG 21979 --- [http-nio-8001-exec-6] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [org.hibernate.jpa.internal.EntityManagerImpl@36b59887] for JPA transaction
2018-09-13 14:56:47.797 DEBUG 21979 --- [http-nio-8001-exec-6] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC transaction 
2018-09-13 14:56:47.798 TRACE 21979 --- [http-nio-8001-exec-6] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.jdbc.datasource.ConnectionHolder@62337496] for key [org.apache.tomcat.jdbc.pool.DataSource@4165b803{ConnectionPool[defaultAutoCommit=null; defaultReadOnly=null; defaultTransactionIsolation=-1; defaultCatalog=null; driverClassName=org.postgresql.Driver; maxActive=100; maxIdle=100; minIdle=10; initialSize=10; maxWait=30000; testOnBorrow=true; testOnReturn=false; timeBetweenEvictionRunsMillis=5000; numTestsPerEvictionRun=0; minEvictableIdleTimeMillis=60000; testWhileIdle=false; testOnConnect=false; ; username=prdcafatuser; validationQuery=SELECT 1; validationQueryTimeout=-1; validatorClassName=null; validationInterval=3000; accessToUnderlyingConnectionAllowed=true; removeAbandoned=false; removeAbandonedTimeout=60; logAbandoned=false; connectionProperties=null; initSQL=null; jdbcInterceptors=null; jmxEnabled=true; fairQueue=true; useEquals=true; abandonWhenPercentageFull=0; maxAge=0; useLock=false; dataSource=null; dataSourceJNDI=null; suspectTimeout=0; alternateUsernameAllowed=false; commitOnReturn=false; rollbackOnReturn=false; useDisposableConnectionFacade=true; logValidationErrors=false; propagateInterruptState=false; ignoreExceptionOnPreLoad=false; useStatementFacade=true; }] to thread [http-nio-8001-exec-6]
2018-09-13 14:56:47.798 TRACE 21979 --- [http-nio-8001-exec-6] .s.t.s.TransactionSynchronizationManager : Bound value [org.springframework.orm.jpa.EntityManagerHolder@4961b514] for key [org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean@30d8f1e5] to thread [http-nio-8001-exec-6]
2018-09-13 14:56:47.798 TRACE 21979 --- [http-nio-8001-exec-6] .s.t.s.TransactionSynchronizationManager : Initializing transaction synchronization
2018-09-13 14:56:47.798 TRACE 21979 --- [http-nio-8001-exec-6] o.s.t.i.TransactionInterceptor           : Getting transaction for [nc.cafat.gen.cli.impl.service.AssureMaladieService.getReglementsAfter]
2018-09-13 14:56:47.798 DEBUG 21979 --- [http-nio-8001-exec-6] n.c.g.c.i.service.AssureMaladieService   : entrée dans getReglementsAfter avec les idAssure : 484608 type règlement : ASSURE dateDebut : Mon Aug 13 00:00:00 NCT 2018

Visual VM подтверждает, что поток занимает 15 минут в ЦП (945160 ~ 15m45s)

Процессорное время

Строка, занимающая большую часть, определяется драйвером на сокете:

Считывание сокета

Эта публикация, похоже, связана с той же проблемой: https://github.com/brettwooldridge/HikariCP/issues/603

Мы пытаемся это:

  • переключиться с tomcat-jdbc на hikari 3.2.0(похоже, это исправлено с версии 2.6.2)
  • updatejdbc PG драйвер с 9.4 до 42.2.5

(было бы проще перейти на версию 2.0, но мысталкиваюсь с другой проблемой при миграции)

...