Tom Van Rossom Tom Van Rossom - 1 month ago 22
Java Question

Performance gap between spring data jpa and hibernate - jHipster

I'm trying to find out why my jHipster app is so slow when querying a database.

This is one of my services using spring-data's

PagingAndSortingRepository


@Transactional(readOnly = true)
public Page<Center> findAll(Pageable pageable) {
log.debug("Request to get all Centers");

return centerRepository.findAll(pageable);
}


I've used JHipsters'
LoggingAspect
and added a timer to log the performance of each method.

@Around("loggingPointcut()")
public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {
Stopwatch stopwatch = null;
if (log.isDebugEnabled()) {
log.debug("Enter: {}.{}() with argument[s] = {}", joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName(), Arrays.toString(joinPoint.getArgs()));
stopwatch = Stopwatch.createStarted();
}
try {
Object result = joinPoint.proceed();
if (log.isDebugEnabled()) {
log.debug("Exit: {}.{}() [took {} ms] with result = {}", joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName(), stopwatch.elapsed(MILLISECONDS), result);
}
return result;
} catch (IllegalArgumentException e) {
log.error("Illegal argument: {} in {}.{}()", Arrays.toString(joinPoint.getArgs()),
joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());

throw e;
}
}


I configured hibernate to generate the statictics:

spring.jpa.properties.hibernate.generate_statistics=true


If I change the log-levels of
org.hibernate.stat.internal.ConcurrentStatisticsImpl
and
org.hibernate.engine.internal.StatisticalLoggingSessionEventListener
I see the following logs:

2016-10-13 11:00:00,640 DEBUG [http-nio-8080-exec-8] LoggingAspect: Enter: com.fluidda.broncholab.service.CenterService.findAll() with argument[s] = [Page request [number: 0, size 20, sort: id: ASC]]
2016-10-13 11:00:00,643 DEBUG [http-nio-8080-exec-8] CenterService: Request to get all Centers
2016-10-13 11:00:02,238 DEBUG [http-nio-8080-exec-8] ConcurrentStatisticsImpl: HHH000117: HQL: select count(generatedAlias0) from Center as generatedAlias0, time: 1ms, rows: 1
2016-10-13 11:00:02,241 DEBUG [http-nio-8080-exec-8] ConcurrentStatisticsImpl: HHH000117: HQL: select generatedAlias0 from Center as generatedAlias0 order by generatedAlias0.id asc, time: 2ms, rows: 3
2016-10-13 11:00:02,242 DEBUG [http-nio-8080-exec-8] LoggingAspect: Exit: com.fluidda.broncholab.service.CenterService.findAll() [took 1601 ms] with result = Page 1 of 1 containing com.fluidda.broncholab.domain.Center instances
2016-10-13 11:00:02,243 INFO [http-nio-8080-exec-8] StatisticalLoggingSessionEventListener: Session Metrics {
568512 nanoseconds spent acquiring 1 JDBC connections;
0 nanoseconds spent releasing 0 JDBC connections;
92324 nanoseconds spent preparing 2 JDBC statements;
992105 nanoseconds spent executing 2 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
34717 nanoseconds spent performing 3 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
2943 nanoseconds spent executing 2 partial-flushes (flushing a total of 0 entities and 0 collections)


If you take a look at the timings (not the timestamp when the item was logged), you'll see a big difference between:


  • ConcurrentStatisticsImpl: time: 2ms, rows: 3

  • LoggingAspect: [took 1601 ms]

  • StatisticalLoggingSessionEventListener: 992105 nanoseconds spent executing 2 JDBC statements;



The strange is, that these performance issue's do not occur all the time! This is the dropwizard statistic:

Service name Count Mean Min p50 p75 p95 p99 Max
....web.rest.CenterResource.getAllCenters 5 13 10 16 16 16 16 1,612


Does anyone know what may cause these performance drops?

Does anyone know how I can investigate any further?

Answer

After adding extra logging, and not using an ASYNC logger, I've find out, the server was losing time parsing the HQL.

I've created another question about this: Hibernate QueryTranslatorImpl HQL AST parsing performance

Comments