Hi All,

I'm quite new to this hibernate stuff, so please excuse my ignorance if I'm being really daft. I'm exploring the hibernate statistics object so that I can measure the performance of the queries in my application (generate_statistics is true).

Although I can see in the log (show_sql is true) that queries are being being sent to the database, the count in the statistics does not reflect them. I've isolated it down to the following case where two queries are sent to the database, but only one is shown in the statistics.

Hibernate version:

Hibernate 3.1.2

Mapping documents:

<session-factory>
<property name="connection.username">root</property>
<property name="connection.url">jdbc:mysql://pvr/test</property>
<property name="dialect">org.hibernate.dialect.MySQLDialect</property>
<property name="myeclipse.connection.profile">Test</property>
<property name="connection.driver_class">com.mysql.jdbc.Driver</property>
<property name="connection.autocommit">false</property>
<property name="cache.use_query_cache">true</property>
<property name="cache.provider_class">org.hibernate.cache.EhCacheProvider</property>
<property name="show_sql">true</property>
<property name="generate_statistics">true</property>
<property name="c3p0.acquire_increment">1</property>
<property name="c3p0.idle_test_period">100</property> <!-- seconds -->
<property name="c3p0.max_size">100</property>
<property name="c3p0.max_statements">0</property>
<property name="c3p0.min_size">10</property>
<property name="c3p0.timeout">100</property> <!-- seconds -->

<mapping resource="tv/clever/hibernate/mapping/Customer.hbm.xml" />
<mapping resource="tv/clever/hibernate/mapping/Book.hbm.xml" />

</session-factory>

Code between sessionFactory.openSession() and session.close():

logStats("1");

List customers = session.createQuery("select c from Customer as c").list();

logStats("2");

Customer customer = (Customer)customers.get(0);
log.info("customer: " + customer);

logStats("3");

log.info("customer books: " + customer.getBooks());

logStats("4");

protected void logStats(String x) {

Statistics s = HibernateSessionFactory.currentSession().getSessionFactory().getStatistics();
log.info("(" + x + ") queryCount: " + s.getQueries().length + ", queriesExecutedToDatabase" + s.getQueryExecutionCount());

}

Full stack trace of any exception that occurs:

No Exception

Name and version of the database you are using:

mysql 4.1.16-nt

Debug level Hibernate log excerpt:

5378 [main] INFO tv.clever.test.HibernateTest - (1) queryCount: 0, queriesExecutedToDatabase0
Hibernate: select customer0_.id as id0_, customer0_.firstname as firstname0_, customer0_.lastname as lastname0_, customer0_.age as age0_ from customer customer0_
5889 [main] INFO tv.clever.test.HibernateTest - (2) queryCount: 1, queriesExecutedToDatabase1
5889 [main] INFO tv.clever.test.HibernateTest - customer: Customer [id=17, firstname=Carsten, lastname=Liebzeit]
5889 [main] INFO tv.clever.test.HibernateTest - (3) queryCount: 1, queriesExecutedToDatabase1
Hibernate: select books0_.customer_fk as customer2_1_, books0_.id as id1_, books0_.id as id1_0_, books0_.customer_fk as customer2_1_0_, books0_.title as title1_0_, books0_.author as author1_0_, books0_.borrowallowed as borrowal5_1_0_ from book books0_ where books0_.customer_fk=?
5929 [main] INFO tv.clever.test.HibernateTest - customer books: [Book [id=18, title=Hibernation in winter]]
5929 [main] INFO tv.clever.test.HibernateTest - (4) queryCount: 1, queriesExecutedToDatabase1
5929 [main] INFO tv.clever.test.HibernateTest - (end) queryCount: 1, queriesExecutedToDatabase1


Any help would be appreciated,

Regards,

George

Hi,

It doesn't look like anyone has been able to offer any feedback on this so I'll explain my latest findings, hoping that it might twig a thought with someone.

It seems that only queries which are executed directly (eg. session.createQuery("select c from Customer as c").list()) are being put into the query statistics. Queries which are constructed by using a hibernate collection method (eg. customer.getBooks()) are not showing in the statistics.

Are the query statistics not meant to show all queries sent to the database? and if not, then is there a way to get overall statistics? As it stands, I would be unaware of any slow queries that I had not written myself?

Help here would be really appreciated,

Regards,

George

the statistics is of course statistics from hibernate's point of view!

queries means queries and not collection fetches nor "number of sql executed"

Thanks Max,

The reason that I thought that a collection fetch would be included in the hibernate statistics is because it is hibernate that 'writes', and executes the query that gets sent to the database to get the collection.

Is there no way to get statistics on this kind of database interaction that hibernate is initialising? I was hoping that I'd be able to look at runtime statistics to find out what hibernate is doing, rather than just getting confirmation of queries that I have written myself - For example statistics showing all queries that hibernate sends would highlight the n+1 problem which could be happening unknown to me due to a bad hibernate config.

Thanks for your help,

George

did you try and look at the other statistics - they are actually quite detailed about exactly this problem ;)

i'll give you a hint *FetchCount.

Thanks Max,

You're right, if the fetch count is very high then I can see that somewhere should be using a join rather than individual selects. But it doesn't show me where a fetch is being nasty to the database.

The querystats would show me if a query was taking a long time to return results, whereas fetch count only shows me when something is happening a lot of times. For example, a missing index on the primary key (god forbid) wouldn't be highlighted in the fetch count but would if I was able to see statistics of the query being run to populate the collection.

Thanks for your help,

George

add a request for enhancement, but I would use jdbc/db level monitoring tools for figuring these questions out.