ColdFusion ORM : How to log SQL

When you use ORM for developing an application, SQLs are generated and executed by the underlying ORM engine (i.e Hibernate for ColdFusion ORM). However, for both troubleshooting and performance optimization, it is crucial to monitor what queries are getting generated. It can help you find out if there is any error in mapping that you have provided as well as it can help you decide various tuning strategies.

ColdFusion can log the SQLs generated by ORM either onto the console or a file. At the same time it leaves enough hook for you to log it anywhere you want.

ColdFusion ORM provides two ways to log the SQLs.

1. Using application setting to log to console : This is a quick and simple way to log the sql to console. This is enabled by setting "logsql" in ormsettings.

      <cfset this.ormsettings.logsql="true">

   This setting is self sufficient and it will log all the sqls executed by hibernate to the console (or a file where the server output goes). However this is not a very flexible option. The sqls are always written to the console and it will be combined with any other output that goes to console. Also this option will not show the DDL queries used for creating or updating tables. It only logs the SQL for the entity operations.
   
2. Using log4J.properties: Hibernate uses log4j for its logging and you can completely control its logging (including SQL) by modifying the log4j.properties. log4j.properties is present under <cf_home>/lib directory. Please note that you don't need to do any application specific setting for this.

I will go in details about using log4j.properties for SQL logging. Here is a snippet from log4j.properties file that is shipped with ColdFusion.

###--------------- Hibernate Log Settings ------ 
### Set Hibernate log 
log4j.logger.org.hibernate=ERROR, HIBERNATECONSOLE 
 
### log just the SQL 
#log4j.logger.org.hibernate.SQL=DEBUG, HIBERNATECONSOLE 
#log4j.additivity.org.hibernate.SQL=false 
### Also log the parameter binding to the prepared statements. 
#log4j.logger.org.hibernate.type=DEBUG 
### log schema export/update ### 
log4j.logger.org.hibernate.tool.hbm2ddl=DEBUG, HIBERNATECONSOLE 
### log cache activity ### 
log4j.logger.org.hibernate.cache=ERROR, HIBERNATECONSOLE 

# HibernateConsole is set to be a ColsoleAppender for Hibernate message  using a PatternLayout. 
log4j.appender.HIBERNATECONSOLE=org.apache.log4j.ConsoleAppender 
log4j.appender.HIBERNATECONSOLE.layout=org.apache.log4j.PatternLayout 
log4j.appender.HIBERNATECONSOLE.layout.ConversionPattern=%d{MM/dd HH:mm:ss} [%t] HIBERNATE %-5p - %m%n%n 
#--------------------------------------------- 

First we will see the relevant settings for SQL logging:

• log4j.logger.org.hibernate.SQL : Defines whether the SQL executed for entity operations will be logged and where it will be logged. The second value for this i.e 'HIBERNATECONSOLE' is a appender that controls where the SQLs will be logged. In the above example HIBERNATECONSOLE is a 'console' appender which means it will log the sql to console.
  
• log4j.logger.org.hibernate.type : Defines whether parameter values used for parametrized query will be logged.
  
• log4j.logger.org.hibernate.tool.hbm2ddl : Defines whether DDL sql statements will be logged.

To enable the SQL logging for console, we just need to uncomment the settings mentioned above. Here is how the hibernate log settings in log4j.properties file would look like

###--------------- Hibernate Log Settings ------ 
### Set Hibernate log 
log4j.logger.org.hibernate=ERROR, HIBERNATECONSOLE 
 
### log just the SQL 
log4j.logger.org.hibernate.SQL=DEBUG, HIBERNATECONSOLE 
log4j.additivity.org.hibernate.SQL=false 
### Also log the parameter binding to the prepared statements. 
#log4j.logger.org.hibernate.type=DEBUG 
### log schema export/update ### 
log4j.logger.org.hibernate.tool.hbm2ddl=DEBUG, HIBERNATECONSOLE 
### log cache activity ### 
log4j.logger.org.hibernate.cache=ERROR, HIBERNATECONSOLE 

# HibernateConsole is set to be a ColsoleAppender for Hibernate message  using a PatternLayout. 
log4j.appender.HIBERNATECONSOLE=org.apache.log4j.ConsoleAppender 
log4j.appender.HIBERNATECONSOLE.layout=org.apache.log4j.PatternLayout 
log4j.appender.HIBERNATECONSOLE.layout.ConversionPattern=%d{MM/dd HH:mm:ss} [%t] HIBERNATE %-5p - %m%n%n 
#--------------------------------------------- 

Here is the complete log4j.properties for logging SQL for console. Ofcourse after changing this you need to restart the server. If you need to log the parameter values used for queries, you need to uncomment '#log4j.logger.org.hibernate.type=DEBUG' as well.

What if you want to log the SQL to a file and not to console? That is pretty easy. You just need to change the 'Appender' used here (HIBERNATECONSOLE) to point to a 'FileAppender' instead of a ConsoleAppender. Here is how the configuration for HIBERNATECONSOLE should look like after you point it to a File Appender.

log4j.appender.HIBERNATECONSOLE=org.apache.log4j.FileAppender
log4j.appender.HIBERNATECONSOLE.File=../hibernatesql.log
log4j.appender.HIBERNATECONSOLE.Append=true
log4j.appender.HIBERNATECONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.HIBERNATECONSOLE.layout.ConversionPattern=%d{MM/dd HH:mm:ss} [%t] HIBERNATE %-5p - %m%n%n

For standalone ColdFusion installation, the file 'hibernatesql.log' will be created in the /logs directory.You can also specify a full path of the file for property 'log4j.appender.HIBERNATECONSOLE.File' and the log will be written to that.

That was easy. Isn't it? What if you want a rolling log file where you dont want the log file size to grow infinitely. That is fairly easy too. All you need to do is to use an appropriate appender. The appender definition for that will look like

log4j.appender.HIBERNATECONSOLE=org.apache.log4j.RollingFileAppender
log4j.appender.HIBERNATECONSOLE.File=../hibernatesql.log
log4j.appender.HIBERNATECONSOLE.Append=true
log4j.appender.HIBERNATECONSOLE.MaxFileSize=500KB
log4j.appender.HIBERNATECONSOLE.MaxBackupIndex=3
log4j.appender.HIBERNATECONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.HIBERNATECONSOLE.layout.ConversionPattern=%d{MM/dd HH:mm:ss} [%t] HIBERNATE %-5p - %m%n%n

Here is the complete log4j.properties for logging SQL to a file that will be rolled automatically once it reaches 500KB.

Now that you have seen how easy it is to change one 'Appender' to another, you can pretty much log it anywhich way you want. Here are some of the interesting 'Appender's that come with log4j which you can easily use.

DailyRollingFileAppender, ExternallyRolledFileAppender, JMSAppender, SMTPAppender, SocketAppender, SyslogAppender

See log4J for more details on log4j settings.