Hi
For a certain part of the service I'm working on I need to use a StatelessSession.
I have to make a slightly simple query, that nevertheless I can't get working, if not using a normal Session...
Things have been working fine up to now, but I'm currently stuck with the following
Code:
StatelessSession session = sessionFactory.openStatelessSession();
Transaction tx = session.beginTransaction();
Collection<Measure> mm;
int loaded = 0;
try {
mm = dao.find(tb, server, tmStart, tmEnd, session);
loaded = mm.size();
tx.commit();
} catch (Exception e) {
if (tx != null) tx.rollback();
} finally {
session.close();
long endTime = System.currentTimeMillis() - startTime;
logger.info("Queried: " + loaded + " time: " + endTime);
}
where the dao.find() method looks like:
Code:
public Collection<Measure> find(TestBox tb, Server s, long tStart, long tEnd,StatelessSession sess) {
s = DomainCache.getInstance().getServer(s);
tb = DomainCache.getInstance().getTestBox(tb);
logger.debug("Query criteria: "+tb+", "+s+", "+tStart+", "+tEnd);
Query query = sess.createQuery("from Measure m where m.testBox=? and m.server=? and" +
" m.tm>=? and m.tm<=? order by m.tm").
setParameter(0, tb).
setParameter(1, s).
setParameter(2, tStart).
setParameter(3, tEnd);
if(maxResultSize>0)
query.setMaxResults(maxResultSize);
return query.list();
}
However I get the following behavior when list() gets called...
Code:
12:18:21,435 DEBUG Loader:1164 - result row: EntityKey[net.ripe.dnsmon.domain.Measure#346]
12:18:21,436 DEBUG Loader:1347 - Initializing object from ResultSet: [net.ripe.dnsmon.domain.Measure#346]
12:18:21,437 DEBUG AbstractEntityPersister:1860 - Hydrating entity: [net.ripe.dnsmon.domain.Measure#346]
12:18:21,437 DEBUG IntegerType:123 - returning '138' as column: SERVER6_5_
12:18:21,438 DEBUG IntegerType:123 - returning '2' as column: QUERY7_5_
12:18:21,439 DEBUG IntegerType:123 - returning '1' as column: TESTBOX8_5_
12:18:21,439 DEBUG LongType:123 - returning '1136073700' as column: TM5_
12:18:21,440 DEBUG ShortType:123 - returning '1' as column: attempt5_
12:18:21,441 DEBUG StringType:123 - returning 'k1.ams-ix' as column: answer5_
12:18:21,442 DEBUG FloatType:123 - returning '0.001891' as column: delay5_
12:18:21,443 DEBUG Loader:709 - done processing result set (101 rows)
12:18:21,444 DEBUG AbstractBatcher:334 - about to close ResultSet (open ResultSets: 1, globally: 1)
12:18:21,444 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:18:21,445 DEBUG AbstractBatcher:470 - closing statement
12:18:21,451 DEBUG Loader:839 - total objects hydrated: 101
12:18:21,453 DEBUG TwoPhaseLoad:104 - resolving associations for [net.ripe.dnsmon.domain.Measure#1]
12:18:21,453 DEBUG AbstractEntityPersister:2723 - Fetching entity: [net.ripe.dnsmon.domain.Server#138]
12:18:21,454 DEBUG Loader:1777 - loading entity: [net.ripe.dnsmon.domain.Server#138]
12:18:21,455 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:18:21,456 DEBUG SQL:346 - select server0_.id as id0_0_, server0_.ADDRESS as ADDRESS0_0_, server0_.NAME as NAME0_0_ from SERVERS server0_ where server0_.id=?
Hibernate: select server0_.id as id0_0_, server0_.ADDRESS as ADDRESS0_0_, server0_.NAME as NAME0_0_ from SERVERS server0_ where server0_.id=?
12:18:21,457 DEBUG AbstractBatcher:424 - preparing statement
12:18:21,460 DEBUG IntegerType:79 - binding '138' to parameter: 1
12:18:21,464 DEBUG AbstractBatcher:327 - about to open ResultSet (open ResultSets: 0, globally: 0)
12:18:21,465 DEBUG Loader:682 - processing result set
12:18:21,465 DEBUG Loader:687 - result set row: 0
12:18:21,466 DEBUG Loader:1164 - result row: EntityKey[net.ripe.dnsmon.domain.Server#138]
12:18:21,467 DEBUG Loader:1347 - Initializing object from ResultSet: [net.ripe.dnsmon.domain.Server#138]
12:18:21,468 DEBUG AbstractEntityPersister:1860 - Hydrating entity: [net.ripe.dnsmon.domain.Server#138]
12:18:21,469 DEBUG StringType:116 - returning null as column: ADDRESS0_0_
12:18:21,471 DEBUG StringType:123 - returning 'k.root-servers.net' as column: NAME0_0_
12:18:21,474 DEBUG Loader:709 - done processing result set (1 rows)
12:18:21,475 DEBUG AbstractBatcher:334 - about to close ResultSet (open ResultSets: 1, globally: 1)
12:18:21,476 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:18:21,477 DEBUG AbstractBatcher:470 - closing statement
12:18:21,478 DEBUG Loader:839 - total objects hydrated: 1
12:18:21,479 DEBUG TwoPhaseLoad:104 - resolving associations for [net.ripe.dnsmon.domain.Server#138]
12:18:21,480 DEBUG CollectionLoadContext:141 - creating collection wrapper:[net.ripe.dnsmon.domain.Server.authorities#138]
12:18:21,481 DEBUG TwoPhaseLoad:203 - done materializing entity [net.ripe.dnsmon.domain.Server#138]
12:18:21,482 DEBUG Loader:1808 - done entity load
12:18:21,483 DEBUG AbstractEntityPersister:2723 - Fetching entity: [net.ripe.dnsmon.domain.QueryType#2]
12:18:21,484 DEBUG Loader:1777 - loading entity: [net.ripe.dnsmon.domain.QueryType#2]
12:18:21,485 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:18:21,486 DEBUG SQL:346 - select querytype0_.CODE as CODE4_0_, querytype0_.type as type4_0_ from QUERY_TYPES querytype0_ where querytype0_.CODE=?
Hibernate: select querytype0_.CODE as CODE4_0_, querytype0_.type as type4_0_ from QUERY_TYPES querytype0_ where querytype0_.CODE=?
12:18:21,487 DEBUG AbstractBatcher:424 - preparing statement
12:18:21,490 DEBUG IntegerType:79 - binding '2' to parameter: 1
12:18:21,491 DEBUG AbstractBatcher:327 - about to open ResultSet (open ResultSets: 0, globally: 0)
12:18:21,492 DEBUG Loader:682 - processing result set
12:18:21,493 DEBUG Loader:687 - result set row: 0
12:18:21,494 DEBUG Loader:1164 - result row: EntityKey[net.ripe.dnsmon.domain.QueryType#2]
12:18:21,495 DEBUG Loader:1347 - Initializing object from ResultSet: [net.ripe.dnsmon.domain.QueryType#2]
12:18:21,496 DEBUG AbstractEntityPersister:1860 - Hydrating entity: [net.ripe.dnsmon.domain.QueryType#2]
12:18:21,497 DEBUG StringType:123 - returning 'id.server' as column: type4_0_
12:18:21,498 DEBUG Loader:709 - done processing result set (1 rows)
12:18:21,499 DEBUG AbstractBatcher:334 - about to close ResultSet (open ResultSets: 1, globally: 1)
12:18:21,500 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:18:21,501 DEBUG AbstractBatcher:470 - closing statement
12:18:21,502 DEBUG Loader:839 - total objects hydrated: 1
12:18:21,503 DEBUG TwoPhaseLoad:104 - resolving associations for [net.ripe.dnsmon.domain.QueryType#2]
12:18:21,504 DEBUG TwoPhaseLoad:203 - done materializing entity [net.ripe.dnsmon.domain.QueryType#2]
12:18:21,507 DEBUG Loader:1808 - done entity load
12:18:21,508 DEBUG AbstractEntityPersister:2723 - Fetching entity: [net.ripe.dnsmon.domain.TestBox#1]
12:18:21,509 DEBUG Loader:1777 - loading entity: [net.ripe.dnsmon.domain.TestBox#1]
12:18:21,510 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:18:21,511 DEBUG SQL:346 - select testbox0_.id as id7_0_, testbox0_.alias as alias7_0_, testbox0_.name as name7_0_ from TESTBOXES testbox0_ where testbox0_.id=?
Hibernate: select testbox0_.id as id7_0_, testbox0_.alias as alias7_0_, testbox0_.name as name7_0_ from TESTBOXES testbox0_ where testbox0_.id=?
12:18:21,512 DEBUG AbstractBatcher:424 - preparing statement
12:18:21,513 DEBUG IntegerType:79 - binding '1' to parameter: 1
12:18:21,515 DEBUG AbstractBatcher:327 - about to open ResultSet (open ResultSets: 0, globally: 0)
12:18:21,516 DEBUG Loader:682 - processing result set
12:18:21,517 DEBUG Loader:687 - result set row: 0
12:18:21,518 DEBUG Loader:1164 - result row: EntityKey[net.ripe.dnsmon.domain.TestBox#1]
12:18:21,519 DEBUG Loader:1347 - Initializing object from ResultSet: [net.ripe.dnsmon.domain.TestBox#1]
12:18:21,519 DEBUG AbstractEntityPersister:1860 - Hydrating entity: [net.ripe.dnsmon.domain.TestBox#1]
12:18:21,520 DEBUG StringType:123 - returning 'tt01(NL)' as column: alias7_0_
12:18:21,523 DEBUG StringType:123 - returning 'tt01.ripe.net' as column: name7_0_
12:18:21,523 DEBUG Loader:709 - done processing result set (1 rows)
12:18:21,524 DEBUG AbstractBatcher:334 - about to close ResultSet (open ResultSets: 1, globally: 1)
12:18:21,525 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:18:21,526 DEBUG AbstractBatcher:470 - closing statement
12:18:21,527 DEBUG Loader:839 - total objects hydrated: 1
12:18:21,528 DEBUG TwoPhaseLoad:104 - resolving associations for [net.ripe.dnsmon.domain.TestBox#1]
12:18:21,528 DEBUG TwoPhaseLoad:203 - done materializing entity [net.ripe.dnsmon.domain.TestBox#1]
12:18:21,529 DEBUG Loader:1808 - done entity load
12:18:21,530 DEBUG TwoPhaseLoad:203 - done materializing entity [net.ripe.dnsmon.domain.Measure#1]
12:18:21,534 ERROR AssertionFailure:22 - an assertion failure occured (this may indicate a bug in Hibernate, but is more likely due to unsafe use of the session)
org.hibernate.AssertionFailure: possible non-threadsafe access to the session
at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:97)
at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:842)
at org.hibernate.loader.Loader.doQuery(Loader.java:717)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
at org.hibernate.loader.Loader.doList(Loader.java:2150)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2029)
at org.hibernate.loader.Loader.list(Loader.java:2024)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:369)
at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:300)
at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:146)
at org.hibernate.impl.StatelessSessionImpl.list(StatelessSessionImpl.java:368)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
at net.ripe.dnsmon.measures.dao.MeasureDAO.find(MeasureDAO.java:170)
at net.ripe.dnsmon.measures.MeasureFacade.getMeasures(MeasureFacade.java:216)
at net.ripe.dnsmon.measures.MeasureFacade.main(MeasureFacade.java:195)
12:18:21,542 DEBUG JDBCTransaction:152 - rollback
12:18:21,543 DEBUG JDBCTransaction:163 - rolled back JDBC Connection
12:18:21,544 DEBUG JDBCContext:207 - after transaction completion
12:18:21,544 DEBUG ConnectionManager:296 - aggressively releasing JDBC connection
12:18:21,545 DEBUG ConnectionManager:333 - closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:18:21,552 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
12:18:21,553 DEBUG ConnectionManager:267 - connection already null in cleanup : no action
The above snippet shows the activity starting from the last record returned by list(). Basically it shows hibernate getting the record, trying to resolve the associations ( I don't know why...shouldn't StatelessSession ignore them?) and materialazing them. Then it hangs materializing the Measure instance...
The generated SQL (show_sql=true):This is the query generated by the find() method:
Code:
select measure0_.MEASURE_ID as MEASURE1_5_, measure0_.SERVER_ID as SERVER6_5_, measure0_.QUERY_CODE as QUERY7_5_, measure0_.TESTBOX_ID as TESTBOX8_5_, measure0_.TM as TM5_, measure0_.attempt as attempt5_, measure0_.answer as answer5_, measure0_.delay as delay5_ from MEASURES measure0_ where measure0_.TESTBOX_ID=? and measure0_.SERVER_ID=? and measure0_.TM>=? and measure0_.TM<=? order by measure0_.TM
That is, nothing new here. Nevertheless I don't understand why
I don't know if this could be the problem but in the same instance that allocates the StatelessSession and manage the transaction, there is an init() that makes use of a normal Session.
Code:
private void init() {
Session s = sessionFactory.getCurrentSession();
s.beginTransaction();
DomainCache.getInstance().initCache(s);
s.getTransaction().commit();
s.close();
logger.debug(DomainCache.getInstance().toString());
}
But I don't see how invoking this could/should interfere with the StatelessSession usage, even if the instances contained in DomainCache are used there. Beside this the same pattern (calling init() and then using a stateless session using DomainCache) works when doing batch updates.
I have to say that I'm stuck...I hope that somebody will enlighten me because I'm obviously doing something wrong but I can't figure out what:(
Thanks everybody, sorry for the long post
Francesco