oracle - Hibernate query stalling as sessions open and close without connecting

Collectives™ on Stack Overflow

Find centralized, trusted content and collaborate around the technologies you use most.
Learn more about Collectives
Teams
Q&A for work
Connect and share knowledge within a single location that is structured and easy to search.
Learn more about Teams
We have a Grails application that uses Hibernate to query an Oracle database.
A relatively simple criteria query that takes, at worst, a twentieth of a second when run directly against the database through something like SQL Developer, is taking anywhere from a fraction of a second to 30 seconds to complete.
Having set logSql to true and confirmed that the generated SQL is performant (explain plan cost of around 100 and execution time of 10-30 milliseconds), we took at closer look at what Hibernate is up to by setting its logging level to TRACE .
Here is what we saw in stdout:
******************** START HIBERNATE QUERY TRACE *****************
start time (millis): 1400772671767
2014-05-22 11:31:11,767 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction  - begin
2014-05-22 11:31:11,767 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction  - current autocommit status: true
2014-05-22 11:31:11,767 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction  - disabling autocommit
2014-05-22 11:31:11,767 [http-bio-8080-exec-5] TRACE jdbc.JDBCContext  - after transaction begin
2014-05-22 11:31:11,770 [http-bio-8080-exec-5] TRACE loader.Loader  - querySpaces is [REDACTED]
2014-05-22 11:31:11,770 [http-bio-8080-exec-5] TRACE loader.Loader  - transformer=org.hibernate.transform.RootEntityResultTransformer returnTypes=[ REDACTED ] returnClasses=[ class REDACTED ]
2014-05-22 11:31:11,770 [http-bio-8080-exec-5] DEBUG jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2014-05-22 11:31:11,771 [http-bio-8080-exec-5] DEBUG hibernate.SQL  - select REDACTED
2014-05-22 11:31:11,771 [http-bio-8080-exec-5] TRACE jdbc.AbstractBatcher  - preparing statement
2014-05-22 11:31:11,771 [http-bio-8080-exec-5] TRACE sql.BasicBinder  - binding parameter [1] as REDACTED
2014-05-22 11:31:11,771 [http-bio-8080-exec-5] TRACE sql.BasicBinder  - binding parameter [2] as REDACTED
2014-05-22 11:31:11,772 [http-bio-8080-exec-5] TRACE sql.BasicBinder  - binding parameter [3] as REDACTED
2014-05-22 11:31:11,772 [http-bio-8080-exec-5] TRACE loader.Loader  - Bound [4] parameters total
2014-05-22 11:31:12,323 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564865835008
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564865839104
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:12,324 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564874059776
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564874059777
2014-05-22 11:31:14,331 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:14,332 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:16,339 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564882284544
2014-05-22 11:31:16,339 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:16,339 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:16,339 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564882284545
2014-05-22 11:31:16,340 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:16,340 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:18,348 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564890513408
2014-05-22 11:31:18,348 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:18,348 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:18,348 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564890513409
2014-05-22 11:31:18,349 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:18,349 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:20,356 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564898738176
2014-05-22 11:31:20,356 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:20,356 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:20,356 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564898738177
2014-05-22 11:31:20,357 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:20,357 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564906958848
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564906962944
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:22,364 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:24,373 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564915191808
2014-05-22 11:31:24,373 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:24,373 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:24,373 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564915191809
2014-05-22 11:31:24,374 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:24,374 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564923408384
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564923408385
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:26,379 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564931633152
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564931633153
2014-05-22 11:31:28,387 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:28,388 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:30,395 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564939857920
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564939862016
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:30,396 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:32,403 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564948082688
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564948086784
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:32,404 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:34,408 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564956295168
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564956299264
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:34,409 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564964519936
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564964519937
2014-05-22 11:31:36,416 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:36,417 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:38,421 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564972732416
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564972736512
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:38,422 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:40,428 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564980953088
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564980957184
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:40,429 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:42,436 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564989177856
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564989181952
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:42,437 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:44,441 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564997390336
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737564997394432
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:44,442 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:46,449 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737565005615104
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737565005619200
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:46,450 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737565013839872
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] DEBUG impl.SessionImpl  - opened session at timestamp: 5737565013843968
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] TRACE impl.SessionImpl  - closing session
2014-05-22 11:31:48,458 [http-bio-8080-exec-10] TRACE jdbc.ConnectionManager  - connection already null in cleanup : no action
2014-05-22 11:31:49,985 [http-bio-8080-exec-5] DEBUG jdbc.AbstractBatcher  - about to open ResultSet (open ResultSets: 0, globally: 0)
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE loader.Loader  - processing result set
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE loader.Loader  - done processing result set (0 rows)
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] DEBUG jdbc.AbstractBatcher  - about to close ResultSet (open ResultSets: 1, globally: 1)
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] DEBUG jdbc.AbstractBatcher  - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE jdbc.AbstractBatcher  - closing statement
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE loader.Loader  - total objects hydrated: 0
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] DEBUG engine.StatefulPersistenceContext  - initializing non-lazy collections
2014-05-22 11:31:49,986 [http-bio-8080-exec-5] TRACE loader.Loader  - transformer=org.hibernate.transform.RootEntityResultTransformer returnTypes=[ REDACTED ] returnClasses=[ class REDACTED ]
2014-05-22 11:31:49,987 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction  - commit
2014-05-22 11:31:49,987 [http-bio-8080-exec-5] TRACE impl.SessionImpl  - automatically flushing session
2014-05-22 11:31:49,987 [http-bio-8080-exec-5] TRACE def.AbstractFlushingEventListener  - flushing session
2014-05-22 11:31:49,987 [http-bio-8080-exec-5] REDACTED
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE jdbc.ConnectionManager  - registering flush begin
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE jdbc.ConnectionManager  - registering flush end
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE def.AbstractFlushingEventListener  - post flush
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE jdbc.JDBCContext  - before transaction completion
2014-05-22 11:31:49,989 [http-bio-8080-exec-5] TRACE impl.SessionImpl  - before transaction completion
2014-05-22 11:31:49,991 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction  - re-enabling autocommit
2014-05-22 11:31:49,991 [http-bio-8080-exec-5] DEBUG transaction.JDBCTransaction  - committed JDBC Connection
2014-05-22 11:31:49,991 [http-bio-8080-exec-5] TRACE jdbc.JDBCContext  - after transaction completion
2014-05-22 11:31:49,991 [http-bio-8080-exec-5] DEBUG jdbc.ConnectionManager  - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] TRACE impl.SessionImpl  - after transaction completion
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] DEBUG impl.SessionImpl  - disconnecting session
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] TRACE jdbc.ConnectionManager  - performing cleanup
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] DEBUG jdbc.ConnectionManager  - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] TRACE jdbc.JDBCContext  - after transaction completion
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] DEBUG jdbc.ConnectionManager  - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
2014-05-22 11:31:49,992 [http-bio-8080-exec-5] TRACE impl.SessionImpl  - after transaction completion
end time (millis): 1400772709992
difference: 38.225 seconds
******************* END HIBERNATE QUERY TRACE ********************
Let me call your attention to what caught OUR attention -- the six lines that repeat approximately every 2 seconds -- opened session then closing session then connection already null, done twice, in the span of a millisecond.
Every 2 seconds or so, Hibernate is opening and immediately closing 2 sessions? Am I interpreting this correctly? Under what circumstances would it be doing something like this?
The data source configuration in DataSource.groovy is basic:
dataSource_REDACTED {
        driverClassName = 'oracle.jdbc.OracleDriver'
        dialect = 'org.hibernate.dialect.Oracle10gDialect'
        url = 'jdbc:oracle:thin:@REDACTED:1521/REDACTED'
        username = 'REDACTED'
        password = 'REDACTED'
        pooled = true
        properties {
            maxActive = 20
            minIdle = 1
            initialSize = 10
            testOnBorrow = true
            testWhileIdle = true
            validationQuery = "SELECT 1 FROM DUAL"
No properties {} block there, so whatever the defaults for properties such as idle timeout are used.
There is also a hibernate configuration in the same file:
hibernate {
    cache.use_second_level_cache = true
    cache.use_query_cache = true
    cache.provider_class = 'net.sf.ehcache.hibernate.EhCacheProvider'
The criteria query I am executing is, like I said earlier, fairly simple:
withTransaction {
    List<MyAwesomeClass> awesomeThings = withCriteria {
        between("importantTime", startDate, endDate)
        eq("importantField", targetValue)
The criteria query is run from a method in a Grails domain class that is called directly by a controller, rather than a transactional service, so I wrapped it in a withTransaction.
Anyway, in short, what is the deal here? Why this messing about with sessions until something (not sure what) happens and the query is actually executed? Could it have something to do with availability of the database itself when attempting to create connections?
This lines caught my attention:
transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources! 
TRACE jdbc.JDBCContext  - after autocommit
According to Hibernate docs:
  ON_CLOSE - is essentially the legacy behavior described above. The
  Hibernate session obtains a connection when it first needs to perform
  some JDBC access and holds unto that connection until the session is
  closed.
  on_close - says to use ConnectionReleaseMode.ON_CLOSE. This setting is
  left for backwards compatibility, but its use is highly discouraged.
It's true that JPA allows you to execute queries even if your not running inside a Transaction but I wouldn't recommend you to this setting.
I always wrap all Hibernate code inside a Transaction and for read-only operations I choose the readOnly=true flag.
Every thread seems to open and close two session successively and if that's because you run two consecutive queries you can optimize it by running them in the same session.
Because you are opening and closing sessions so rapidly you are opening and closing JDBC connections too, and your settings don't contain any connection pooling. Unless you use connection pooling, creating and destroying connection is going to be extremely expensive.
Check out my benchmark on how connection pooling can drastically improve your application performance.
Always use transactions 
Use connection pooling
                Actually I've now wrapped the query in a transaction, unfortunately to no effect in terms of performance i.e. avoiding the sessions reopening and closing every two seconds. I should also mention that we use pooled data sources in all environments besides local dev (and yes there's something to be said for being consistent so I should make that change), but they experience the same performance problem so I don't think pooling or lack thereof is part of the issue. That said, I'll go ahead and reconfigure the dev datasource to use a connection pool to eliminate that discrepancy.
– Dmitry Sharkov
                May 21, 2014 at 16:21
                I have updated the original question to reflect use of pooling and transactions. Sadly, all I managed to do was set a new record with 38 seconds runtime. There is something else here that I'm missing :-/
– Dmitry Sharkov
                May 22, 2014 at 15:46
        Thanks for contributing an answer to Stack Overflow!
Please be sure to answer the question. Provide details and share your research!
But avoid …
Asking for help, clarification, or responding to other answers.
Making statements based on opinion; back them up with references or personal experience.
To learn more, see our tips on writing great answers.