HS6 SearchResult.took() duration incorrect

Hibernate Search
1

Please check out the code below to see if I am using this incorrectly, but it looks like the duration being returned by .took() is incorrect. Thanks, Keith

     LuceneSearchQuery<PatentDocSearchResultDO> query = 
      Search.session(entityManager)
        .search(PatentDocDO.class).extension(LuceneExtension.get())
        .select(f -> f.composite(PatentDocSearchResultDO::new, f.score(), f.entity()))
        .where(f -> f.bool((b -> {
           addSearchClausesFromCriteria(f, b,criteria);
        })))
             .toQuery();
        
     logger.info("Fetch start");
       SearchResult<PatentDocSearchResultDO> docSearchResult = query.fetch((int)pageable.getOffset(), pageable.getPageSize());

     logger.info("Fetch complete.  Took: {}", docSearchResult.took());

Logs:

PatentDocRepositoryImpl INFO 2021-03-04 12:19:16,840 [https-jsse-nio-8443-exec-5]
com.propat.pas.db.core.PatentDocRepositoryImpl
Fetch start

query TRACE 2021-03-04 12:19:17,095 [https-jsse-nio-8443-exec-5]
org.hibernate.search.query
HSEARCH000274: Executing Lucene query: +(+((org.apache.lucene.queryparser.surround.query.SimpleTermRewriteQuery(XML.ABST, blockchain, org.apache.lucene.queryparser.surround.query.BasicQueryFactory(maxBasicQueries: 262144, queriesMade: 0)) org.apache.lucene.queryparser.surround.query.DistanceRewriteQuery(XML.ABST, (block W chain*), org.apache.lucene.queryparser.surround.query.BasicQueryFactory(maxBasicQueries: 262144, queriesMade: 0))) (+(org.apache.lucene.queryparser.surround.query.SimpleTermRewriteQuery(XML.ACLM, blockchain, org.apache.lucene.queryparser.surround.query.BasicQueryFactory(maxBasicQueries: 262144, queriesMade: 0)) org.apache.lucene.queryparser.surround.query.DistanceRewriteQuery(XML.ACLM, (block W chain*), org.apache.lucene.queryparser.surround.query.BasicQueryFactory(maxBasicQueries: 262144, queriesMade: 0))))^1.2 (org.apache.lucene.queryparser.surround.query.SimpleTermRewriteQuery(TTL, blockchain, org.apache.lucene.queryparser.surround.query.BasicQueryFactory(maxBasicQueries: 262144, queriesMade: 0)) org.apache.lucene.queryparser.surround.query.DistanceRewriteQuery(TTL, (block W chain*), org.apache.lucene.queryparser.surround.query.BasicQueryFactory(maxBasicQueries: 262144, queriesMade: 0)))) #CASE.PDATE:[668066400000 TO 9223372036854775807] #DOC_TYPE:GRANT #(CASE.TYPE:UTILITY))

PatentDocRepositoryImpl INFO 2021-03-04 12:19:17,788 [https-jsse-nio-8443-exec-5]
com.propat.pas.db.core.PatentDocRepositoryImpl
Fetch complete. Took: PT164H44M58.342S

2

Wow, that’s embarassing. There is indeed a bug. Thanks for the report, I’ll have a look ASAP: [HSEARCH-4183] SearchResult.took() returns incorrect, very large value with the Lucene backend - Hibernate JIRA

3

I see from the JIRA ticket you already have a fix in. Thanks for the fast response! BTW, when this is delivered, will took return the duration of the query not including the hibernate object load time? That is what I am most interested in.

4

Yes, the returned value includes only the time spent executing the query. Entity loading is ignored.

5

@kmelkild The fix is available in the recently released 6.0.3.Final. Sorry it took so long… :slight_smile:

6

No problem. It’s funny, I was just about to ping you all on an ETA for 6.0.3 and then I saw it show up yesterday. Thanks again.

1 Like