ORM - Logging and Debugging

  • Category:
  • ORM
edit

ORM - Logging and Debugging

When something goes wrong with ORM, the first step is to see what Hibernate is actually doing. Lucee 5.6 added native logging integration that pipes Hibernate's internal logging through Lucee's log system.

Logging Settings

All logging settings go in this.ormSettings in your ORM - Configuration. They all default to false:

this.ormSettings = {
	logSQL: true,
	logParams: true,
	formatSQL: true,
	logCache: true,
	logVerbose: true
};

Setting What it logs
logSQL SQL statements generated by Hibernate
logParams Parameter bindings — the actual values bound to ? placeholders. (new in 5.6)
formatSQL Pretty-prints SQL with indentation and line breaks. (new in 5.6)
logCache L2 cache and query cache activity — hits, misses, puts, evictions. (new in 5.6)
logVerbose Hibernate internals — session lifecycle, entity loading, dirty checking, schema tools. Produces a LOT of output. (new in 5.6)

Where Logs Go

ORM logs write to the Lucee orm log. The location depends on your Lucee configuration:

  • Default: {lucee-server}/logs/orm.log or {lucee-web}/logs/orm.log
  • Lucee Admin: Configure log appenders and levels under Settings > Logging
  • Console output: Set the environment variable LUCEE_LOGGING_FORCE_APPENDER=console to redirect to stdout (useful for development and CI)

Log Levels

The ormSettings flags (logSQL, logParams, etc.) control what Hibernate sends to the log. The Lucee log level controls the minimum severity that gets written. For full output, set the orm log to TRACE level in your Application.cfc:

function onApplicationStart() {
	configImport( type: "server", data: {
		loggers: {
			orm: {
				level: "TRACE",
				appender: "console"
			}
		}
	});
}

Both the ormSettings flags and the log level must be set — one without the other won't produce output.

Inspecting Generated Mappings

savemapping

Set savemapping: true to write the generated .hbm.xml mapping files to disk alongside your entity CFCs:

this.ormSettings = {
	savemapping: true
};

This creates files like User.cfc.hbm.xml next to your User.cfc. Inspect these to see exactly what Hibernate thinks your entities look like — column types, relationships, cascade settings, etc.

Dev only. Files are written on every application startup.

Reading Mapping Files

When something maps unexpectedly (wrong column type, missing relationship, incorrect cascade), check the generated .hbm.xml:

<property name="price" type="big_decimal">
    <column name="price" precision="12" scale="4"/>
</property>

If the mapping doesn't match your intent, adjust the property attributes in your CFC and check again.

Debugging Techniques

Check the SQL First

When data isn't saving, loading, or updating correctly, enable logSQL and logParams to see the actual SQL:

this.ormSettings = {
	logSQL: true,
	logParams: true,
	formatSQL: true
};

Look for:

  • Missing INSERT/UPDATE statements (entity wasn't dirty, or flush didn't happen)
  • Wrong column values (mapping issue)
  • Unexpected WHERE clauses (filter or discriminator issue)
  • Duplicate SQL (missing inverse="true" on a bidirectional relationship)

Session Diagnostics

The native Hibernate session exposes useful state:

sess = ORMGetSession();

// Are there pending changes?
if ( sess.isDirty() ) {
	systemOutput( "Session has unflushed changes", true );
}

// How many entities are cached in this session?
stats = sess.getStatistics();
systemOutput( "Entities: #stats.getEntityCount()#", true );
systemOutput( "Collections: #stats.getCollectionCount()#", true );

Get an Entity's PK Dynamically

When writing generic utility code:

pk = ORMGetSession().getIdentifier( entity );

Inspect Entity Metadata

Get Hibernate's metadata for any entity — property names, types, identifier info:

meta = ORMGetSessionFactory().getClassMetadata( "User" );
systemOutput( "Properties: #arrayToList( meta.getPropertyNames() )#", true );
systemOutput( "ID property: #meta.getIdentifierPropertyName()#", true );

Check the Active Dialect

Verify which SQL dialect Hibernate is using:

dialect = ORMGetSessionFactory().getDialect();
systemOutput( "Dialect: #dialect.getClass().getName()#", true );

Using Log Markers

Write a marker to the orm log before an operation, then search the log file for everything after the marker:

marker = createUUID();
cflog( text: marker, log: "orm" );

// ... your ORM operations here ...

// later, read the log and find your section

This is useful when the log contains output from many requests and you need to isolate one.

Common Debugging Scenarios

"Why isn't my entity saving?"

  1. Enable logSQL: true — is an INSERT being generated?
  2. Check flushAtRequestEnd — if false, are you calling ormFlush() or using a transaction?
  3. Check ORMGetSession().isDirty() — does Hibernate think anything changed?
  4. Check ORMGetSession().contains( entity ) — is the entity persistent?

"Why am I getting extra UPDATE statements?"

  1. Enable logSQL: true and count the statements
  2. Check for missing inverse="true" on bidirectional relationships — see ORM - Relationships
  3. Check for entities loaded and modified unintentionally (dirty checking)

"Why is this query slow?"

  1. Enable logSQL: true, logParams: true — check the generated SQL
  2. Look for N+1 patterns — the same SELECT repeated with different IDs
  3. Enable logCache: true if using L2 cache — check hit/miss ratios
  4. Consider batchsize, fetch="join", or HQL JOIN FETCH — see ORM - Relationships

What's Next?

See also