Friday, July 31, 2009

ColdFusion ORM : Troubleshooting - 'Lazy' does not work

Few days back Manju logged a bug in CF-ORM saying 'lazy' does not work for many-to-one relation and that too on non-Windows machine. At first, I simply rejected the bug because a) ORM can not have anything to do with OS and therefore, if it works on Windows, it works on all the plaform and b) I know it works :-). But he did not agree and I had to take a look at that machine. And apparently he was right - lazy was not working ! The related entity was in-fact getting loaded immediately. (Question for you - how will you know that lazy is working or not?)

Even after seeing this, I did not believe it and asked him to replicate this on another system and he successfully showed that to me on one another system. And he agreed that it works fine on most of the configurations. The problem exists only on a few of the systems.

This got me thinking - Why would a relation get loaded immediately even after it is marked lazy? The only answer would be - if some one is accessing that lazy field and calling some method on it. I checked his code which was loading the entities to see if there could be any case, where the field would get loaded and unfortunately there was none.

And then suddenly it hit me - what if "memory tracking" is swithched on? That would access each of the field of each object recursively to compute the size of an object and that can definitely cause this. I immediately checked the server monitor and the "memory tracking" was right there staring at me in "red"! It was indeed enabled. I asked Manju to check the other system as well (where lazy was not working) and the memory tracking was enabled there as well.

So the lesson - If the 'memory tracking' is enabled on the server, the relationship will no longer remain lazy. And btw, you should enable "Memory tracking" on the server only if you need to track the memory for some troubleshooting. Memory tracking is really really expensive in terms of performance.

Another reason why it might not work for you could be - if you are sending the object to flex. Currently, during serialization, the related objects also get sent irrespective of the lazy attribute set on the relationship. We are still working on it and hopefully by the time we release, this will be fixed.

Monday, July 27, 2009

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.

Saturday, July 18, 2009

ColdFusion 9 : Implicit/Generated CFC Methods

How many times did you write the accessor methods (better known as getters and setters) for the fields of your CFC? And how many times did you feel that it was really a mundane job and wished there was a better way to do this? With ColdFusion 9, we have done just that! You no longer need to write those accessors. ColdFusion will automatically generate the accessor methods for you in the object. All you need to do is to define the properties using cfproperty.

Consider this CFC Person.cfc

Component Person{
property firstname;
property lastname;
property age;
property city;
property state;
}

When an object is created for this CFC, you can directly call the setters and getters for the properties as


person = new Person();
person.setFirstName("Brad");
person.setLastName("Pitt");
person.setAge(46);

writeOutput("Name : #person.getFirstName()# #person.getLastName()#");
writeOutput("Age : #person.getAge()#");


The implicit setter/getter uses the 'variable' scope, which is a private scope for a object, for storing the data. i.e the setter method puts the data in the variable scope and the getter method gets the data from the variable scope.

What if you want to override the setter/getter method? Ofcourse you can do that. You just need to define those methods in your CFC and ColdFusion will call your method instead of calling the implicit one.

Hmm.. What if you dont want ColdFusion to generate getter or setter or both methods for a particular property? You can disable that by adding attribute getter="false" and setter="false" on the property.

So if you define a property

property name="city" getter="false" setter="false";

ColdFusion will not generate getCity() and setCity() methods for this CFC.

The implicit methods can also do some nice validation if you have given the 'type' for properties. Consider the same Person.cfc with type specified where we have made age as a numeric type.


Component Person{
property string firstname;
property string lastname;
property numeric age;
property string city;
property string state;
}

ColdFusion will do the datatype validation whenever the setter method is called for any property. So if you call


person = new Person();
person.setFirstName("Brad");
person.setLastName("Pitt");
person.setAge("LA");

It will throw a nice error saying "The value cannot be converted to a numeric".

Whats more interesting is that you can do a whole lot of validation using cfproperty. We have added two more attributes on cfproperty named 'validate' and 'validateparams'. These attributes allow you do even more advanced validations of the property data when the setter method is called for a property. (This is similar to cfparam or cfform validation).

The possible values for validate attributes are

  • string
  • boolean
  • integer
  • numeric
  • date
  • time
  • creditcard: A 13-16 digit number conforming to the mod10 algorithm.
  • email: A valid e-mail address.
  • eurodate: A date-time value. Any date part must be in the format dd/mm/yy. The format can use /, -, or . characters as delimiters.
  • regex: Matches input against pattern specified in validateparams.
  • ssn: A U.S. social security number.
  • telephone: A standard U.S. telephone number.
  • UUID: A Home Universally Unique Identifier, formatted 'XXXXXXXX-XXXX-XXXX-XXXXXXXXXXXXXXX', where 'X' is a hexadecimal number.
  • guid: A Universally Unique Identifier of the form "XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX" where 'X' is a hexadecimal number
  • zipcode: U.S., 5- or 9-digit format ZIP codes

The 'validateparams' attribute available with <cfproperty> takes the parameters required by the validator specified in the 'validate' attribute. This needs to be specified in the implicit struct notation.
  • min: Minimum value if 'validate' is integer/numeric
  • max: Maximum value if the 'validate' is integer/numeric
  • minLength: Minimum length of the string if the 'validate' is string
  • maxLength: Maximum length of the string if the 'validate' is string
  • pattern: regex expression if the validator specified in 'validate' attribute is regex
Consider the Person again where we will add few more properties with some validation

Component Person{
property string firstname;
property string lastname;
property numeric age;
property string city;
/**
* @validate string
* @validateparams {minLength=2, maxLength=2}
*/
property string state;
/**
* @validate zipcode
*/
property numeric zip;
/**
* @validate telephone
*/
proeprty phone;
}

Now when you create an object of Person and call setState(state), before setting the data for state in variable scope, ColdFusion will validate that state value provided is of type 'string' and its length is 2. Similarly setZip() will validate that the input data is a valid zip code and setPhone() will validate that the input data is a valid telephone number.

For String type properties, you can also do regular expression validation allows you to have all sort of validation on a property of string type.

And to top it all, all of these nice goodies are available to you at a much lesser cost than regular UDFs. Yes, you read it right. Implicit methods perform much better than regular UDFs that you write in CFC. To confirm that, lets use this CFC where we will use implicit methods for 'firstName' and write our own accessors for 'lastName'.


component 
{
property String firstName;
lastName = "";

public void function setLastName(string name)
{
lastName = name;
}

public string function getLastName()
{
return lastName;
}
}

Both implicit methods and UDFs are doing exactly the same thing i.e settings and getting the data in/from variable scope. Now lets run this comparison test



person = new Person();
t = getTickCount();
for(i = 0; i < 100000; i++)
{
person.setfirstName("Brad");
fname = person.getFirstName();
}
writeOutput("Total Time in implicit methods " & (getTickCount() - t));
t = getTickCount();
for(i = 0; i < 100000; i++)
{
person.setLastName("Pitt");
lname = person.getLastName();
}
writeOutput("Total Time in UDF methods " & (getTickCount() - t));

Here is the output
Total Time in implicit methods 63
Total Time in UDF methods 485

Thats almost eight times faster than regular UDF. Isn't that sweet? You get those auto-generated methods, whole lot of auto-magical validations and to top that, incredible performance. I am sure writing accessors for your CFC fields will become a thing of past now !