This is a crosspost on stackoverflow:
http://stackoverflow.com/questions/40257688/hibernate-querytranslatorimpl-hql-ast-parsing-performanceI'm facing performance issues executing standard spring-data-jpa findAll queries using @NamedEntityGraph
When I examine the logs, I see the following statements:
Code:
2016-10-26 09:46:25,681 DEBUG [http-nio-8080-exec-1] CriteriaQueryImpl: Rendered criteria query -> select generatedAlias0 from Patient as generatedAlias0 order by generatedAlias0.id asc
2016-10-26 09:46:25,681 DEBUG [http-nio-8080-exec-1] CriteriaQueryImpl: Rendered criteria query -> select count(generatedAlias0) from Patient as generatedAlias0
2016-10-26 09:46:25,681 DEBUG [http-nio-8080-exec-1] SQL: select count(patient0_.id) as col_0_0_ from patient patient0_
2016-10-26 09:46:25,682 DEBUG [http-nio-8080-exec-1] Loader: Result row:
2016-10-26 09:46:25,682 DEBUG [http-nio-8080-exec-1] ConcurrentStatisticsImpl: HHH000117: HQL: select count(generatedAlias0) from Patient as generatedAlias0, time: 0ms, rows: 1
2016-10-26 09:46:25,682 DEBUG [http-nio-8080-exec-1] QueryTranslatorImpl: parse() - HQL: select generatedAlias0 from com.fluidda.broncholab.domain.Patient as generatedAlias0 order by generatedAlias0.id asc
2016-10-26 09:46:27,340 DEBUG [http-nio-8080-exec-1] QueryTranslatorImpl: --- HQL AST ---
\-[QUERY] Node: 'query'
+-[SELECT_FROM] Node: 'SELECT_FROM'
| +-[FROM] Node: 'from'
| | \-[RANGE] Node: 'RANGE'
| | +-[DOT] Node: '.'
| | | +-[DOT] Node: '.'
| | | | +-[DOT] Node: '.'
| | | | | +-[DOT] Node: '.'
| | | | | | +-[IDENT] Node: 'com'
| | | | | | \-[IDENT] Node: 'fluidda'
| | | | | \-[IDENT] Node: 'broncholab'
| | | | \-[IDENT] Node: 'domain'
| | | \-[IDENT] Node: 'Patient'
| | \-[ALIAS] Node: 'generatedAlias0'
| \-[SELECT] Node: 'select'
| \-[IDENT] Node: 'generatedAlias0'
\-[ORDER] Node: 'order'
+-[DOT] Node: '.'
| +-[IDENT] Node: 'generatedAlias0'
| \-[IDENT] Node: 'id'
\-[ASCENDING] Node: 'asc'
2016-10-26 09:46:27,340 DEBUG [http-nio-8080-exec-1] ErrorCounter: throwQueryException() : no errors
2016-10-26 09:46:27,340 DEBUG [http-nio-8080-exec-1] HqlSqlBaseWalker: select << begin [level=1, statement=select]
2016-10-26 09:46:27,341 DEBUG [http-nio-8080-exec-1] FromElement: FromClause{level=1} : com.fluidda.broncholab.domain.Patient (generatedAlias0) -> patient0_
There is a big gap between 2 QueryTranslatorImpl log statements:
almost 2 seconds?!When looking in the source code, I don't see anything special (hibernate-core-4.3.11.Final)
Code:
private HqlParser parse(boolean filter) throws TokenStreamException, RecognitionException {
// Parse the query string into an HQL AST.
final HqlParser parser = HqlParser.getInstance( hql );
parser.setFilter( filter );
LOG.debugf( "parse() - HQL: %s", hql );
parser.statement();
final AST hqlAst = parser.getAST();
final NodeTraverser walker = new NodeTraverser( new JavaConstantConverter() );
walker.traverseDepthFirst( hqlAst );
showHqlAst( hqlAst );
parser.getParseErrorHandler().throwQueryException();
return parser;
}
What is the problem here? It is a very basic HQL, why does it takes so long?
Is it possible to cache these HQL AST parsing?