-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 20 posts ]  Go to page 1, 2  Next
Author Message
 Post subject: Logging SQL WITH named parameters and bind values
PostPosted: Mon Oct 09, 2006 9:40 am 
Beginner
Beginner

Joined: Thu Aug 28, 2003 7:05 pm
Posts: 20
I am using Hibernate 3.1.3 and would like to output the SQL WITH the named
parameters and bind values. For example, hibernate currently produces...

/* named HQL query request.loadByBusiness */ select
request0_.oid as oid14_,
request0_.version as version14_,
request0_.request_details as request3_14_,
request0_.response_details as response4_14_,
request0_.notes as notes14_,
request0_.status as status14_,
request0_.request_date as request7_14_,
request0_.request_member_oid as request8_14_,
request0_.bus_oid as bus9_14_
from
request request0_,
member member1_
where
request0_.request_member_oid=member1_.oid
and request0_.bus_oid=?

for the HQL:
from Request
where business.id = :businessId

but what I want is:
/* named HQL query request.loadByBusiness */ select
request0_.oid as oid14_,
request0_.version as version14_,
request0_.request_details as request3_14_,
request0_.response_details as response4_14_,
request0_.notes as notes14_,
request0_.status as status14_,
request0_.request_date as request7_14_,
request0_.request_member_oid as request8_14_,
request0_.bus_oid as bus9_14_
from
request request0_,
member member1_
where
request0_.request_member_oid=member1_.oid
and request0_.bus_oid=:businessId


/* Parameters values
:businessId=1
*/


This would greatly assist in debugging complex queries as I can copy and paste them into my sql editor and run them. I will then be prompted to enter the bind variables.

Any idea how I can achieve this? Is there a feature or a patch that can do this?

Thanks
Gavin


Top
 Profile  
 
 Post subject:
PostPosted: Mon Oct 09, 2006 4:59 pm 
Senior
Senior

Joined: Wed Aug 17, 2005 12:56 pm
Posts: 136
Location: Erie, PA (USA)
Set property
Code:
hibernate.show_sql=true
This will show the SQL

Turn on debug logging for "org.hibernate.type".

Note that Hibernate uses commons-logging.

Curtis ...

_________________
---- Don't forget to rate! ----


Top
 Profile  
 
 Post subject:
PostPosted: Mon Oct 09, 2006 6:03 pm 
Beginner
Beginner

Joined: Thu Aug 28, 2003 7:05 pm
Posts: 20
Thanks, but that is not quite what I am looking for. I have already done those things... but...

1) the sql has ? instead of the named parameters
2) the bind values are all in separate log messages. I would like it all in one message.

Maybe one of the hibernate developers could tell me what the best "extension point" is to implement this.

Thanks


Top
 Profile  
 
 Post subject:
PostPosted: Mon Oct 09, 2006 6:30 pm 
Beginner
Beginner

Joined: Thu Aug 28, 2003 7:05 pm
Posts: 20
I was thinking about this problem and was wondering if another approach would work.

I have a Query object that has all the information (hql query, parameters). All I need to do is translate or retrieve the "SQL" query and create the log message.

Does anyone know how I can translate or retrieve the SQL from the HQL string?

Thanks


Top
 Profile  
 
 Post subject:
PostPosted: Tue Oct 10, 2006 8:37 am 
Senior
Senior

Joined: Wed Aug 17, 2005 12:56 pm
Posts: 136
Location: Erie, PA (USA)
The "SQL" that you see in the console is what gets sent to the database server -- the "?" parameter markers are part of SQL. Hibernate creates a prepared statement and then submits it and the parameters to the db server that then handles binding the parameter values to the parameter markers.

You might be able to find an extension point where you can reformat the debug output or you might consider P6Spy which inserts a layer between the application and the db and can provide enhanced debugging capabilities (although, I could not get it working in my environment).

Good luck,
Curtis ...

_________________
---- Don't forget to rate! ----


Top
 Profile  
 
 Post subject:
PostPosted: Wed Oct 11, 2006 7:17 pm 
Beginner
Beginner

Joined: Thu Aug 28, 2003 7:05 pm
Posts: 20
After digging around I found the DynamicQueryTranslator (in Hibernate Eclipse tools). Based on that, I created a QueryLogger class. The output is as follows:

Code:
/*---------- hql ---------- */
from Request
where business.id = :businessId
and   (:filterByStatus = 'off' or status = :status)
and   (:filterByName = 'off'
      or lower(concat(requestMember.name.firstName,' ',requestMember.name.lastName)) like lower(concat('%',:memberNamePattern,'%')) )
and   ( :filterByDate = 'off'
        or :filterByDate = 'from' and date(requestDate) >= date(:fromDate) 
        or :filterByDate = 'fromAndTo' and date(requestDate) between date(:fromDate) and date(:toDate) )

/*---------- sql ---------- */
select
      request0_.oid as oid14_,
      request0_.version as version14_,
      request0_.request_details as request3_14_,
      request0_.response_details as response4_14_,
      request0_.notes as notes14_,
      request0_.status as status14_,
      request0_.request_date as request7_14_,
      request0_.request_member_oid as request8_14_,
      request0_.bus_oid as bus9_14_
   from
      request request0_,
      member member1_
   where
      request0_.request_member_oid=member1_.oid
      and request0_.bus_oid=:businessId
      and (
         :filterByStatus='off'
         or request0_.status=:status
      )
      and (
         :filterByName='off'
         or lower(concat(member1_.first_name, ' ', member1_.last_name)) like lower(concat('%', :memberNamePattern, '%'))
      )
      and (
         :filterByDate='off'
         or :filterByDate='from'
         and date(request0_.request_date)>=date(:fromDate)
         or :filterByDate='fromAndTo'
         and (
            date(request0_.request_date) between date(:fromDate) and date(:toDate)
         )
      )

/*---------- returns ---------- */
bussite.service.db.entity.member.Request

/*---------- parameters ---------- */
businessId [long]="18"
filterByDate [string]="fromAndTo"
filterByName [string]="on"
filterByStatus [string]="off"
fromDate="Tue Oct 10 09:06:51 EST 2006"
memberNamePattern="TEST"
status [string]=null
toDate="Sat Oct 14 09:06:51 EST 2006"

There are a few hacks in this class and I have not yet tested it with other types of queries. However, it gives me a neat sql string that I can copy and paste into my SQL editor and debug. Makes finding bugs in the sql much, much easier.

Code:
Here is the class:
package bussite.service.db.common;

import java.lang.reflect.Method;
import java.util.Collections;
import java.util.Iterator;
import java.util.Map;
import java.util.TreeMap;

import org.apache.commons.lang.StringUtils;
import org.hibernate.Query;
import org.hibernate.SessionFactory;
import org.hibernate.engine.TypedValue;
import org.hibernate.engine.query.HQLQueryPlan;
import org.hibernate.hql.ParameterTranslations;
import org.hibernate.hql.QueryTranslator;
import org.hibernate.impl.AbstractQueryImpl;
import org.hibernate.impl.SessionFactoryImpl;
import org.hibernate.pretty.Formatter;
import org.hibernate.type.Type;

public class QueryLogger {
   private static org.apache.commons.logging.Log LOG = org.apache.commons.logging.LogFactory
         .getLog(QueryLogger.class);
   
   public void debugSQL(final SessionFactory sf, final Query query) {
      String hqlQueryString = query.getQueryString();
      // hack - to get to the actual queries..
      SessionFactoryImpl sfimpl = (SessionFactoryImpl) sf;
      HQLQueryPlan plan = new HQLQueryPlan(
            hqlQueryString,
            false,
            Collections.EMPTY_MAP,
            sfimpl);

      
      StringBuffer str = new StringBuffer();
      
      // output the hql
      str.append("/*---------- hql ---------- */\n");
      str.append(hqlQueryString);
      str.append("\n\n");

      // get parameter values
      Map<String,TypedValue> parameterValues = getParameterValues(query);
      
      QueryTranslator[] translators = plan.getTranslators();
      for (int i = 0; i < translators.length; i++) {
         QueryTranslator translator = translators[i];
   
         // get parameter location (in sql)
         Map<String, ParameterInfo> parameters = getParameters(translator,parameterValues);
         
         String sqlString = getSqlString(translator, parameters);
         str.append("/*---------- sql ---------- */\n");
         str.append(sqlString);
         str.append("\n\n");
         
         String returnTypeString = getReturnTypeString(translator);
         str.append("/*---------- returns ---------- */\n");
         str.append(returnTypeString);
         str.append("\n\n");
         
         String parameterString = getParametersString(parameters);
         str.append("/*---------- parameters ---------- */\n");
         str.append(parameterString);
         str.append("\n\n");
         
         str.append("\n\n");
      }
      
      LOG.info(str.toString());
   }

   /**
    * Returns a string of all the query's parameters.
    * The format is:
    * name [type]="value"
    *
    * @param parameters
    * @return
    */
   private String getParametersString(Map<String, ParameterInfo> parameters) {
      StringBuffer str = new StringBuffer();
      for (Iterator iter = parameters.values().iterator(); iter.hasNext();) {
         ParameterInfo paramInfo = (ParameterInfo) iter.next();
         str.append(paramInfo.getName());
         if (paramInfo.getType() != null) {
            str.append(" [" + paramInfo.getType().getName() + "]");   
         }
         
         str.append("=");
         
         if (paramInfo.getValue() != null) {
            str.append("\"" + paramInfo.getValue() + "\"");
         } else {
            str.append("null");
         }
         str.append("\n");         
      }
      return str.toString();
   }

   /**
    * Returns a string of the queries return types.
    * @param translator
    * @return
    */
   private String getReturnTypeString(QueryTranslator translator) {
      StringBuffer str = new StringBuffer();
      if (! translator.isManipulationStatement()) {
         Type[] returnTypes = translator.getReturnTypes();
         for (int j = 0; j < returnTypes.length; j++) {
            Type returnType = returnTypes[j];
            str.append(returnType.getName());
            if (j < returnTypes.length - 1) {
               str.append(", ");
            }
         }
      }
      return str.toString();
   }

   /**
    * Returns the formatted sql query (including the named parameters)
    * @param translator
    * @param parameters
    * @return
    */
   private String getSqlString(QueryTranslator translator, Map<String, ParameterInfo> parameters) {
      Map<Integer,String> paramLocationToName = new TreeMap<Integer,String>();
      for (Iterator iter = parameters.values().iterator(); iter.hasNext();) {
         ParameterInfo paramInfo   = (ParameterInfo) iter.next();
         for (int j = 0; j < paramInfo.locations.length; j++) {
            paramLocationToName.put(
                  new Integer(paramInfo.locations[j]),
                  paramInfo.name);
         }
      }
      String sql = translator.getSQLString();            
      StringBuffer sqlBuffer = new StringBuffer(sql);
      for (Iterator iter = paramLocationToName.values().iterator(); iter.hasNext();) {
         String paramName = (String) iter.next();
         int index = sqlBuffer.indexOf("?");
         
         if (index != -1) {
            sqlBuffer.replace(index, index + 1, ":" + paramName);
         }   
      }
      String sqlWithNamedParams = StringUtils.remove(sqlBuffer.toString(),"?");
      
      sqlWithNamedParams = new Formatter(sqlWithNamedParams)
            .setIndentString("   ")
            .setInitialString("")
            .format();

      return sqlWithNamedParams;
   }

   /**
    * Returns the parameter information, including: the name, the locations in the query and the value
    * @param translator
    * @param parameterValues
    * @return
    */
   private Map<String, ParameterInfo> getParameters(QueryTranslator translator, Map<String,TypedValue> parameterValues) {
      Map<String,ParameterInfo> parameters = new TreeMap<String,ParameterInfo>();
      ParameterTranslations parameterTranslations = translator.getParameterTranslations();
      for (Iterator iter = parameterTranslations.getNamedParameterNames().iterator(); iter.hasNext();) {
         ParameterInfo paramInfo = new ParameterInfo(); 
         paramInfo.setName((String) iter.next());
         paramInfo.setLocations(parameterTranslations.getNamedParameterSqlLocations(paramInfo.getName()));
         paramInfo.setType(parameterTranslations.getNamedParameterExpectedType(paramInfo.getName()));
         
         parameters.put(paramInfo.getName(), paramInfo);
      }

      for (Iterator iter = parameters.values().iterator(); iter.hasNext();) {
         ParameterInfo paramInfo = (ParameterInfo) iter.next();
         TypedValue typeValue = (TypedValue) parameterValues.get(paramInfo.name);
         if (typeValue != null) {
            paramInfo.setValue(typeValue.getValue());   
         }
      }
      
      return parameters;
   }

   /**
    * Access the parameter values bound to the Query. 
    * @param query
    * @return
    */
   private Map getParameterValues(Query query) {
      try {
         // Wordaround: The only way to access the parameter values is to call a protected method.
         Method m = AbstractQueryImpl.class.getDeclaredMethod("getNamedParams", new Class[0]);
         if (m != null) {
            m.setAccessible(true);
            return (Map) m.invoke(query, new Object[0]);
         }
      } catch (Exception e) {
         LOG.info("Unable to access parameter values.", e);
      }
      return Collections.EMPTY_MAP;
   }

   private class ParameterInfo {
      private int[] locations;
      private String name;
      private Type type;
      private Object value;
      public int[] getLocations() {
         return locations;
      }
      public void setLocations(int[] locations) {
         this.locations = locations;
      }
      public String getName() {
         return name;
      }
      public void setName(String name) {
         this.name = name;
      }
      public Type getType() {
         return type;
      }
      public void setType(Type type) {
         this.type = type;
      }
      public Object getValue() {
         return value;
      }
      public void setValue(Object value) {
         this.value = value;
      }
   }
}


Top
 Profile  
 
 Post subject:
PostPosted: Wed Oct 11, 2006 8:26 pm 
Hibernate Team
Hibernate Team

Joined: Mon Aug 25, 2003 9:11 pm
Posts: 4592
Location: Switzerland
Put it on the Wiki.


Top
 Profile  
 
 Post subject:
PostPosted: Wed Oct 11, 2006 11:17 pm 
Beginner
Beginner

Joined: Thu Aug 28, 2003 7:05 pm
Posts: 20
I will. Just cleaning it up. However, I think I need to log an improvement that allows me to get the query parameter values without using a reflection hack.


Top
 Profile  
 
 Post subject:
PostPosted: Thu Oct 12, 2006 3:12 am 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 6:10 am
Posts: 8615
Location: Neuchatel, Switzerland (Danish)
yes interesting; but a performance hog so should be used with care.

_________________
Max
Don't forget to rate


Top
 Profile  
 
 Post subject:
PostPosted: Thu Oct 12, 2006 6:20 pm 
Beginner
Beginner

Joined: Thu Aug 28, 2003 7:05 pm
Posts: 20
Thanks for your comments.

Why a performance hog?

Did you have any specific "performance issues" in mind.

My guess would be the only "slow" part would be the creation of the HQL plan. I think that you have a plan cache which could be used instead.

Anyway, I have a check to see if "debug" is set, so there should be no impact unless I am logging at a very low level.

Cheers


Top
 Profile  
 
 Post subject:
PostPosted: Fri Oct 13, 2006 12:07 am 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 6:10 am
Posts: 8615
Location: Neuchatel, Switzerland (Danish)
just alot of string manipulation.

in any case; it's a nice utility.

_________________
Max
Don't forget to rate


Top
 Profile  
 
 Post subject:
PostPosted: Fri Oct 13, 2006 12:08 am 
Hibernate Team
Hibernate Team

Joined: Tue Aug 26, 2003 6:10 am
Posts: 8615
Location: Neuchatel, Switzerland (Danish)
the true test for it is if you can insert the call into hibernate core and have it called for every hql in the unit test ;)

_________________
Max
Don't forget to rate


Top
 Profile  
 
 Post subject:
PostPosted: Fri Oct 13, 2006 1:55 am 
Beginner
Beginner

Joined: Thu Aug 28, 2003 7:05 pm
Posts: 20
I would love to have it inserted into the core or at least have an extension point that I could format my own message without going back to all the string manipulation.

All the objects are already on the query (which would save some of the duplicate work). The string manipulation is only required because Hibernate does to expose them nicely. For example, putting back the parameter names is a backward step. They should already be in the Plan and getting the parameter values should be a simple method call.


Anyway, thanks for the feedback (and the great framework).


Top
 Profile  
 
 Post subject: How to integrate with Spring?
PostPosted: Fri Oct 13, 2006 3:38 am 
Beginner
Beginner

Joined: Mon Nov 22, 2004 11:21 am
Posts: 42
Does anybody know how to integrate this class with Spring? The SessionFactory I pass from the HibernateTemplate is a proxy class generated at runtime. Therefore I get a ClassCastException when I try to cast it to SessionFactoryImpl.

@GavinLas: thanks for this helper class. I think it is very useful. However I would prefer the method debugSQL to return a String instead of logging on its own. And the method should be static, so I anybody can integrate it to his/her own log code.

_________________
Real programmers confuse Halloween and Christmas because OCT 31 = DEC 25


Top
 Profile  
 
 Post subject:
PostPosted: Sat Oct 14, 2006 6:27 am 
Beginner
Beginner

Joined: Thu Aug 28, 2003 7:05 pm
Posts: 20
Thanks.

The code I posted was a first attempt. I have already made those changes, as well as handling of NativeSQL (not much to do, just print out the parameter values).

What I would like to know, is if there is anyway to really integrate it into core hibernate so we can get this for any statement. Maybe an extension point to the current SQL logging.

Cheers


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 20 posts ]  Go to page 1, 2  Next

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.