Best way to measure execution time for all HQL queries

aismail · **Joined:** Wed Mar 11, 2009 4:37 am **Posts:** 9

Hi everyone,

I'm trying to intercept all HQL queries for a web application using Spring in order to measure their execution time.

I already know about logging the SQL statements (using hibernate.show_sql=true + log4j), but logging the HQL statements before being compiled into SQL would be really nice. I also know about the "comment" feature for a given Query, but it's not feasible since we'd like to do this automatically, somehow (AOP is the last resort, I'm trying to make this work for any web application, whether AOP is enabled or not).

Is there any way to hook into hibernate and get this kind of info out of it? One of my (failed) attempts is described at http://forum.springsource.org/showthread.php?t=70086 (basically, it's about returning a proxied SessionFactory, which returns proxied Sessions, and so on - using CGLIB + java Dynamic Proxy from JDK 1.3).

Thanks,
Andrei

aismail · **Joined:** Wed Mar 11, 2009 4:37 am **Posts:** 9

I forgot to mention in the previous post, I need more detailed / refined statistics than those provided by default using Hibernate (I assume that the statistics available are those in orghibernate.stat package). Ideally, I would want to log:
- HQL query
- corresponding SQL query
- named + positional parameters for the HQL query
- execution time (for each query!)

Thanks,
Andrei

rtalakola · **Joined:** Tue Apr 07, 2009 11:35 am **Posts:** 2

You could try using a p6spy driver.
It gives you all the SQL queries with parameters, result sets and execution time.

You need to include the p6spy.jar file in the classpath ,
configure the datasource definations to wrap the connections with the spy driver and spy.properties in your classpath. You can refer to the documentation for the set up.

aismail · **Joined:** Wed Mar 11, 2009 4:37 am **Posts:** 9

Hi, rtalakola!

Thanks for the quick reply. I must say, we'd rather prefer to log HQL queries, instead of SQL. I know about the proxy driver approach for the SQL logging.

Andrei

mmerder · **Posted:** Tue Apr 07, 2009 1:44 pm

You will have to change the source code of hibernate to get the execution time of each hql-query:
I created a patch in Hibernate's JIRA. Maybe one of the next hibernate releases will have a function like this.

mmerder · **Posted:** Tue Apr 07, 2009 1:47 pm

Please vote for this JIRA-issue (you have to create a JIRA-account), so that it sooner gets fixed.

aismail · **Joined:** Wed Mar 11, 2009 4:37 am **Posts:** 9

Hello, mmerder!

Thanks for your answers. Firstly, about your patch, I've read it, but I don't fully agree with it - I think it's a little too specific - and that the execution time should be exposed in another form - not in a String one. I know this is the quickest hack, but if I define a custom logger, I expect to be easily able to parse the execution time.

Secondly, for me it's not an option to fork the Hibernate source code. My "plug-in" is expected to work "out-of-the-box" with a web-application, and forking the Hibernate source code in a production environment, even if we're talking about a few lines of code, is not an option. Therefore, the only thing I can assume is that I have Hibernate newer than version X and Spring newer than version Y.

So, anyone, is there any other way to display HQL query execution time? Maybe using Spring AOP? Has anyone done it before?

Thanks a lot,
Andrei

mmerder · **Posted:** Wed Apr 08, 2009 3:42 am

Why do you think it's too specific?

About parsing the execution time: If you were using an own SLF4J Logger, you wouldn't even have to parse the string to get the execution time, because the time is passed in another parameter than the message-string. But I know that it is quite complex to write an own SLF4J appender. I have done it with a log4j-appender, where I had to parse the string, which is very easy though, because it always looks the same.

Quote:

Secondly, for me it's not an option to fork the Hibernate source code. My "plug-in" is expected to work "out-of-the-box" with a web-application, and forking the Hibernate source code in a production environment, even if we're talking about a few lines of code, is not an option. Therefore, the only thing I can assume is that I have Hibernate newer than version X and Spring newer than version Y.

It may take some versions, until hibernate supports logging the execution time of each query, I don't think you'll want to wait for it. Anyway, my patch adds only a single line of code, so what's the deal changing it. That's the idea of open source. But I can understand you, I don't like to change it either.

Quote:

So, anyone, is there any other way to display HQL query execution time? Maybe using Spring AOP?

I haven't done it using AOP yet, but it could be a possible solution. I don't think there are good join points in hibernate's source, as the HQL-Queries are executed within more complex methods, so you would measure not only the execution time. You could use the JDBS-execute-methods as join points and measure the time it took to execute them. But this would be the same as using a p6spy-driver.

Anyway, I am curious about you finding a solution for that problem. Keep me updated, please.

aismail · **Joined:** Wed Mar 11, 2009 4:37 am **Posts:** 9

Hello, mmerder!

Thanks again for the quick answer!

I think the patch is too specific because it only exposes execution time (maybe we want some other type of meta-data about the query; for example, I'd also like named / positional parameter values for the HQL query). I will vote with it, though, because it's a quick alternative to otherwise bigger changes to incorporate hooking mechanisms in hibernate.

It's not my decision to not be able to fork hibernate, and, for now, it's not an option. I'll give AOP a try today and in a day or so, I'll post my results (or lack of them) here.

Thanks,
Andrei

mmerder · **Posted:** Wed Apr 08, 2009 4:35 am

You can log the value of the positional parameters, if you set log-level of org.hibernate.type to a finer level (I think trace or debug). I guess you have already known this and (like me) do not like the debug messages of org.hibernate.type?

kochcp · **Posted:** Wed Apr 08, 2009 11:39 am

It is pretty easy thing to do using AOP

aismail · **Joined:** Wed Mar 11, 2009 4:37 am **Posts:** 9

Hi, everyone!

@kochcp
Can you please provide a brief example of how to do it using AOP?
Do you think it's possible to do it without introduction an additional compilation step for the web application or modifying hibernate in any way?

I'm still a newbie in terms of AOP. I have been reading yesterday about Spring AOP (the AOP framework I'd like to use) and the docs say it can only deal with advice for objects managed by Spring (which is bad, because Query objects aren't, and having them be managed by it would probably introduce a very big overhead).

@mmerder
I wasn't familiar with that method. But I also need the named parameters and I think it would be a little difficult to correlate logging statements in order to parse the parameters. On the application I'm trying to profile, thousands of queries are being ran every second.

Thank you very much,
Andrei

kochcp · **Posted:** Thu Apr 09, 2009 8:14 am

If you use spring AOP you don't need to use a load-time weaver, as opposed to a pure AspectJ approach.

first, your advice

Code:

public class ProfilingAdvice implements Ordered{

   private static final Logger logger = Logger.getLogger(DebugAdvice.class);

   private int order;
   private boolean sysout = false;

   public Object profile(ProceedingJoinPoint call) throws Throwable {
      Object o;
      StopWatch clock = new StopWatch();
      try {
         clock.start(call.toShortString());
         o = call.proceed();
      } finally {
         clock.stop();
         logger.debug(clock.prettyPrint());
         if (sysout) {
            System.out.println(clock.prettyPrint());
         }
      }

      return o; 
   }

        ... (getters and setters)

then in your spring context files...

Code:

<bean id = "profile_monitor" class = "foo.ProfilingAdvice" >
       <property name="order" value="2" />
       <property name="sysout" value="true" />
    </bean>

<aop:config>
<aop:aspect id = "profile_time" ref="profile_monitor">
          <aop:around 
             pointcut="execution(* foo.dao..*Service.*(..))" 
             method="profile"
            />
       </aop:aspect>
</aop:config>

My pointcut says it will wrap that aspect "profile_monitor" using the method "profile" around anything with a package name beginning with foo.dao and any class ending in the words Service and any method (provided its public) in those classes with any amount and kinds of arguments. You can use ands and ors and such to specify more than one pointcut predicate

aismail · **Joined:** Wed Mar 11, 2009 4:37 am **Posts:** 9

Hello, kochcp!

Thanks for your quick reply. Your approach is indeed a classic and can be found in the Spring docs. However, I wanted to know the execution times for all HQL queries, not for all DAO calls. There is a big difference between the two: there might be poorly written classes in the application that don't use DAO calls for database access, and use instead Hibernate session directly to issue a query. This is exactly the case for the application I'm profiling, and there's no way I can refactor all those classes *now*. And not including them in the profiling is a big mistake, because there is a high probability of them causing problems, as they are poorly written.

Also, as far as I can tell from the Spring docs, your approach would work only for Spring-managed beans. As I said before, Query, Session, Criteria, and other Hibernate objects are not managed by the IOC (Inversion of Control Container) by default (and I suspect serious overhead associated with solving this problem).

So, what I'm asking for is: how do I easily log the execution time of all HQL queries in a Java application, given the following constraints:
- can't modify application source code (only configuration, and modifications should be as unintrusive as possible)
- can't deploy a forked version of Hibernate with the application
- ideally, the measurements impose little overhead on the application, allowing for live profiling on production

aismail · **Joined:** Wed Mar 11, 2009 4:37 am **Posts:** 9

Hi all,

We managed to use proxying of the SessionFactory and of the Session objects in order to achieve this. You can find more details about:
* what we tried: http://forum.springsource.org/showthread.php?t=70086
* the solution for the problem we encountered: http://blockers.wordpress.com/2009/06/0 ... plication/

PS, I don't know if we're allowed to post links, so please excuse me in advance :)