[Hibernate-issues] [Hibernate-JIRA] Commented: (HB-483) Odd behavior from query cache startup

[<leg...@at...>]

The following comment has been added to this issue:

     Author: Loren Rosen
    Created: Fri, 21 Nov 2003 11:38 AM
       Body:
The little test program here uses an existing database; it doesn't insert or modify anything.

I'll attach a debug log. Note that I added some additional debug logging statements to the hibernate code, whose meaning I hope is self-explanatory. Also, I've manually added some comments to the log file, prefixed by "****", which indicate what I think is going on. Basically, the first time through hibernates caches the query, but doesn't set the update timestamp. The next time the update timestamp gets set, and the query is re-cached. The query cache timestamp is before the update timestamp, and consequently, the third time through, hibernate decides the query is not up to date. The query gets cached yet again, this time with a later timestamp, and so the fourth time through it succeeds in getting using the cached query.
---------------------------------------------------------------------
View the issue:

  http://opensource.atlassian.com/projects/hibernate/secure/ViewIssue.jspa?key=HB-483


Here is an overview of the issue:
---------------------------------------------------------------------
        Key: HB-483
    Summary: Odd behavior from query cache startup
       Type: Bug

     Status: Unassigned
   Priority: Minor

    Project: Hibernate2
 Components: 
             core
   Versions:
             2.1 beta 6

   Assignee: 
   Reporter: Loren Rosen

    Created: Thu, 20 Nov 2003 12:16 PM
    Updated: Fri, 21 Nov 2003 11:38 AM
Environment: Mac OSX 10.1.5
JDK 1.3.1

Description:
It seems that it takes 3 query calls before the query cache is propery initialized and starts caching queries. I'll grant this isn't so critical for overall effectiveness of the cache, but it will confuse someone who tries to write a very simple program to demonstrate the operation of the query cache.

For example, if the gist of main() is this:
        Session sess;
        Long l = new Long(79);

        for (int i=1;i<=5;i++) {
            System.out.println("-----run query iteration " + i + " --------------");
            sess = sessions.openSession();
            runQuery(l, sess);
            sess.close();
        }

and here's the method it calls
    private static void runQuery(Long docId, Session sess) throws Exception {

        Document doc;
        Transaction tx = null;

        try {
            tx = sess.beginTransaction();
            Query q = sess.createQuery("select from Document doc where doc.id=:docId");
            q.setLong("docId", docId.longValue());
            q.setCacheable(true);
            List list = q.list();
            tx.commit();
        } catch (Exception e) {
            tx.rollback();
            throw e;
        }

    }

If you run this with query logging enabled, you'll see that only the 4th and 5th iterations of loop succeed in getting the query results from the query cache.

I've traced through the code, and I think I know what's going on. It's a bit complicated to explain, but I'll be happy to write it down if anyone wants to try fixing the problem.


---------------------------------------------------------------------
JIRA INFORMATION:
This message is automatically generated by JIRA.

If you think it was sent incorrectly contact one of the administrators:
   http://opensource.atlassian.com/projects/hibernate/secure/Administrators.jspa

If you want more information on JIRA, or have a bug to report see:
   http://www.atlassian.com/software/jira