Uploaded image for project: 'Hibernate Search'
  1. HSEARCH-2893

Fix ORM performance tests on Wildfly (they fail silently)

    Details

      Description

      To be precise, the failures are logged but only to the test output, which does not appear in the console, and no top-level exception is thrown. So we didn't notice the failures.

      Example:

      11:35:40,226 INFO  [org.hibernate.search.batchindexing.impl.SimpleIndexingProgressMonitor] (default task-2) HSEARCH000028: Reindexed 999 entities
      11:35:40,226 INFO  [stdout] (default task-2) [2017-09-27 11:35:40.226] starting measuring
      11:35:40,271 INFO  [stdout] (default task-2) ==================================================================
      11:35:40,272 INFO  [stdout] (default task-2) HIBERNATE SEARCH PERFORMANCE TEST REPORT
      11:35:40,272 INFO  [stdout] (default task-2) 
      11:35:40,273 INFO  [stdout] (default task-2) SUMMARY
      11:35:40,273 INFO  [stdout] (default task-2)     Name   : SmokeTestScenario
      11:35:40,274 INFO  [stdout] (default task-2)     Date   : 2017-09-27 11:35
      11:35:40,275 INFO  [stdout] (default task-2) 
      11:35:40,276 INFO  [stdout] (default task-2)     Measured time (HH:mm:ss.SSS)
      11:35:40,278 INFO  [stdout] (default task-2)         MEASURED TASKS : 00:00:00.039
      11:35:40,280 INFO  [stdout] (default task-2)         init database  : 00:00:00.330
      11:35:40,281 INFO  [stdout] (default task-2)         init index     : 00:00:00.849
      11:35:40,282 INFO  [stdout] (default task-2)         warmup phase   : 00:00:00.089
      11:35:40,282 INFO  [stdout] (default task-2) 
      11:35:40,282 INFO  [stdout] (default task-2) TASKS
      11:35:40,284 INFO  [stdout] (default task-2)      10x InsertBookTask                      | sum n/a | avg n/a
      11:35:40,286 INFO  [stdout] (default task-2)      10x UpdateBookRatingTask                | sum n/a | avg n/a
      11:35:40,288 INFO  [stdout] (default task-2)      10x UpdateBookTotalSoldTask             | sum n/a | avg n/a
      11:35:40,289 INFO  [stdout] (default task-2)      10x QueryBooksByAuthorTask              | sum n/a | avg n/a
      11:35:40,291 INFO  [stdout] (default task-2)      10x QueryBooksByAverageRatingTask       | sum n/a | avg n/a
      11:35:40,292 INFO  [stdout] (default task-2)      10x QueryBooksByBestRatingTask          | sum n/a | avg n/a
      11:35:40,294 INFO  [stdout] (default task-2)      10x QueryBooksByNewestPublishedTask     | sum n/a | avg n/a
      11:35:40,295 INFO  [stdout] (default task-2)      10x QueryBooksBySummaryTask             | sum n/a | avg n/a
      11:35:40,297 INFO  [stdout] (default task-2)      10x QueryBooksByTitleTask               | sum n/a | avg n/a
      11:35:40,298 INFO  [stdout] (default task-2)      10x QueryBooksByTotalSoldTask           | sum n/a | avg n/a
      11:35:40,298 INFO  [stdout] (default task-2) 
      11:35:40,299 INFO  [stdout] (default task-2) TEST CONFIGURATION
      11:35:40,299 INFO  [stdout] (default task-2)     measure performance : false
      11:35:40,300 INFO  [stdout] (default task-2)     threads             : 2
      11:35:40,301 INFO  [stdout] (default task-2)     measured cycles     : 10
      11:35:40,301 INFO  [stdout] (default task-2)     warmup cycles       : 10
      11:35:40,302 INFO  [stdout] (default task-2)     initial book count  : 10
      11:35:40,303 INFO  [stdout] (default task-2)     initial autor count : 10
      11:35:40,303 INFO  [stdout] (default task-2)     verbose             : false
      11:35:40,304 INFO  [stdout] (default task-2)     measure memory      : false
      11:35:40,305 INFO  [stdout] (default task-2)     measure task time   : false
      11:35:40,306 INFO  [stdout] (default task-2)     check query results : true
      11:35:40,307 INFO  [stdout] (default task-2)     check index state   : true
      11:35:40,307 INFO  [stdout] (default task-2) 
      11:35:40,307 INFO  [stdout] (default task-2) HIBERNATE SEARCH PROPERTIES
      11:35:40,309 INFO  [stdout] (default task-2)     hibernate.search.default.directory_provider = local-heap
      11:35:40,310 INFO  [stdout] (default task-2)     hibernate.search.default.lucene_version = LUCENE_CURRENT
      11:35:40,310 INFO  [stdout] (default task-2) 
      11:35:40,310 INFO  [stdout] (default task-2) VERSIONS
      11:35:40,311 INFO  [stdout] (default task-2)     org.hibernate.search : 5.9.0-SNAPSHOT
      11:35:40,312 INFO  [stdout] (default task-2)     org.hibernate        : 5.2.11.Final
      11:35:40,312 INFO  [stdout] (default task-2) 
      11:35:40,314 INFO  [stdout] (default task-2) ==================================================================
      11:35:40,315 INFO  [stdout] (default task-2) INDEX CHECK...
      11:35:40,315 INFO  [stdout] (default task-2) 
      11:35:40,319 INFO  [stdout] (default task-2) directory : RAMDirectory@59e1e563 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@c656afe
      11:35:40,319 INFO  [stdout] (default task-2) 
      11:35:40,327 INFO  [stdout] (default task-2) Segments file=segments_2 numSegments=1 version=5.5.4 id=cyje3agk07bn9ocfyrn6yc2xr format=
      11:35:40,329 INFO  [stdout] (default task-2)   1 of 1: name=_6 maxDoc=999
      11:35:40,330 INFO  [stdout] (default task-2)     version=5.5.4
      11:35:40,332 INFO  [stdout] (default task-2)     id=cyje3agk07bn9ocfyrn6yc2xq
      11:35:40,333 INFO  [stdout] (default task-2)     codec=Lucene54
      11:35:40,334 INFO  [stdout] (default task-2)     compound=false
      11:35:40,335 INFO  [stdout] (default task-2)     numFiles=12
      11:35:40,339 INFO  [stdout] (default task-2)     size (MB)=0.286
      11:35:40,346 INFO  [stdout] (default task-2)     diagnostics = {os=Linux, java.vendor=Oracle Corporation, java.version=1.8.0_121, java.vm.version=25.121-b13, lucene.version=5.5.4, mergeMaxNumSegments=1, os.arch=amd64, java.runtime.version=1.8.0_121-b13, source=merge, mergeFactor=6, os.version=4.12.9-300.fc26.x86_64, timestamp=1506504940097}
      11:35:40,347 INFO  [stdout] (default task-2)     no deletions
      11:35:40,350 INFO  [stdout] (default task-2)     test: open reader.........OK [took 0.001 sec]
      11:35:40,352 INFO  [stdout] (default task-2)     test: check integrity.....OK [took 0.001 sec]
      11:35:40,353 INFO  [stdout] (default task-2)     test: check live docs.....OK [took 0.001 sec]
      11:35:40,356 INFO  [stdout] (default task-2)     test: field infos.........OK [8 fields] [took 0.002 sec]
      11:35:40,358 INFO  [stdout] (default task-2)     test: field norms.........OK [3 fields] [took 0.001 sec]
      11:35:40,427 INFO  [stdout] (default task-2)     test: terms, freq, prox...OK [3237 terms; 110078 terms/docs pairs; 146396 tokens] [took 0.066 sec]
      11:35:40,440 INFO  [stdout] (default task-2)     test: stored fields.......OK [5994 total field count; avg 6.0 fields per doc] [took 0.011 sec]
      11:35:40,443 INFO  [stdout] (default task-2)     test: term vectors........OK [0 total term vector count; avg 0.0 term/freq vector fields per doc] [took 0.001 sec]
      11:35:40,448 INFO  [stdout] (default task-2)     test: docvalues...........OK [3 docvalues fields; 0 BINARY; 3 NUMERIC; 0 SORTED; 0 SORTED_NUMERIC; 0 SORTED_SET] [took 0.001 sec]
      11:35:40,448 INFO  [stdout] (default task-2) 
      11:35:40,450 INFO  [stdout] (default task-2) No problems were detected with this index.
      11:35:40,450 INFO  [stdout] (default task-2) 
      11:35:40,451 INFO  [stdout] (default task-2) Took 0.126 sec total.
      11:35:40,453 INFO  [stdout] (default task-2) ==================================================================
      11:35:40,461 INFO  [stdout] (default task-2) ===========================================================================
      11:35:40,462 INFO  [stdout] (default task-2) EXCEPTIONS
      11:35:40,462 INFO  [stdout] (default task-2) 
      11:35:40,464 INFO  [stdout] (default task-2) java.lang.IllegalStateException: A JTA EntityManager cannot use getTransaction()
      11:35:40,467 INFO  [stdout] (default task-2)    at org.hibernate.internal.AbstractSharedSessionContract.getTransaction(AbstractSharedSessionContract.java:382)
      11:35:40,469 INFO  [stdout] (default task-2)    at org.hibernate.internal.AbstractSharedSessionContract.beginTransaction(AbstractSharedSessionContract.java:408)
      11:35:40,472 INFO  [stdout] (default task-2)    at org.hibernate.engine.spi.SessionDelegatorBaseImpl.beginTransaction(SessionDelegatorBaseImpl.java:468)
      11:35:40,474 INFO  [stdout] (default task-2)    at org.hibernate.search.test.performance.task.AbstractTask.run(AbstractTask.java:50)
      11:35:40,476 INFO  [stdout] (default task-2)    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      11:35:40,478 INFO  [stdout] (default task-2)    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      11:35:40,480 INFO  [stdout] (default task-2)    at java.lang.Thread.run(Thread.java:745)
      11:35:40,481 INFO  [stdout] (default task-2) ---------------------------------------------------------------
      11:35:40,483 INFO  [stdout] (default task-2) java.lang.IllegalStateException: A JTA EntityManager cannot use getTransaction()
      11:35:40,486 INFO  [stdout] (default task-2)    at org.hibernate.internal.AbstractSharedSessionContract.getTransaction(AbstractSharedSessionContract.java:382)
      11:35:40,489 INFO  [stdout] (default task-2)    at org.hibernate.internal.AbstractSharedSessionContract.beginTransaction(AbstractSharedSessionContract.java:408)
      11:35:40,491 INFO  [stdout] (default task-2)    at org.hibernate.engine.spi.SessionDelegatorBaseImpl.beginTransaction(SessionDelegatorBaseImpl.java:468)
      11:35:40,493 INFO  [stdout] (default task-2)    at org.hibernate.search.test.performance.task.AbstractTask.run(AbstractTask.java:50)
      11:35:40,495 INFO  [stdout] (default task-2)    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      (etc.)
      

        Attachments

          Activity

            People

            • Assignee:
              yrodiere Yoann Rodière
              Reporter:
              yrodiere Yoann Rodière
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: