Logging SQL WITH named parameters and bind values

GavinLas · **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

CWitherow · **Posted:** Mon Oct 09, 2006 4:59 pm

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 ...

GavinLas · **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

GavinLas · **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

CWitherow · **Posted:** Tue Oct 10, 2006 8:37 am

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 ...

GavinLas · **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;
      }
   }
}

christian · **Posted:** Wed Oct 11, 2006 8:26 pm

Put it on the Wiki.

GavinLas · **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.

max · **Posted:** Thu Oct 12, 2006 3:12 am

yes interesting; but a performance hog so should be used with care.

GavinLas · **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

max · **Posted:** Fri Oct 13, 2006 12:07 am

just alot of string manipulation.

in any case; it's a nice utility.

max · **Posted:** Fri Oct 13, 2006 12:08 am

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 ;)

GavinLas · **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).

gskempes · **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.

GavinLas · **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