The log configuration we currently use might possibly decrease overall performance of web apps.

I did a quick, but controlled analysis with researchr running on my local pc [Intel core i5-2500k, 8GB, SSD @ USB2.0]. CPU scaling was disabled.
5 log configurations were tested, 4 times each.

All tests used the same deployed instance of the researchr war-file. The log4j.properties file is changed in the deployed /webapps/researchr/WEB-INF/classes folder before starting tomcat.
After starting tomcat, the homepage of researchr is loaded once. From this point measurements were started by clicking the very same links for each tests (using a script). Load times were recorded using the development console of firefox. Load times for google analytics were filtered out afterwards.

The results are attached as pdf.

To enable WebDSL’s sql logging log4j.logger.org.hibernate.SQL needs to be set to debug, and log4j.logger.org.hibernate.type to trace. It would be nice if this can be done dynamically.

Example of default generated log4j.properties by Webdsl R4949 (debug=false @ application.ini):

	### direct log messages to stdout ###
	log4j.appender.stdout=org.apache.log4j.ConsoleAppender
	log4j.appender.stdout.Target=System.out
	log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
	log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n
	
	# Do not change the name of this appender
	# use NDCAppender.getNamed("hibernateLog").getLog()
	# This will get you all logs for the current thread configured for this appender
	# .getNamed() can return null, if it could not find a NDCAppender by the given name
	# Only call .getLog() on the same thread that handles the page request
	# You can use .getLog(<<RequestLogEntry>>.getId().toString()) from another thread if needed 
	log4j.appender.hibernateLog=utils.NDCAppender
			
	### set log levels - for more verbose logging change 'info' to 'debug' ###
	
	#Note: enable rootlogger and org.hibernate.type for debugging queries
	#log4j.rootLogger=info, stdout
	### log JDBC bind parameters ###
	log4j.logger.org.hibernate.type=trace, hibernateLog
	
	#log4j.logger.org.hibernate=info
	#log4j.logger.org.hibernate=debug
	
	### log HQL query parser activity
	#log4j.logger.org.hibernate.hql.ast.AST=debug
	
	### log just the SQL
	log4j.logger.org.hibernate.SQL=debug, hibernateLog
	
	### log schema export/update ###
	#log4j.logger.org.hibernate.tool.hbm2ddl=info
	
	### log HQL parse trees
	#log4j.logger.org.hibernate.hql=debug
	
	### log cache activity ###
	#log4j.logger.org.hibernate.cache=info
	
	### log transaction activity
	#log4j.logger.org.hibernate.transaction=debug
	
	### log JDBC resource acquisition
	log4j.logger.org.hibernate.jdbc=debug, hibernateLog
	
	### enable the following line if you want to track down connection ###
	### leakages when using DriverManagerConnectionProvider ###
	#log4j.logger.org.hibernate.connection.DriverManagerConnectionProvider=trace

Submitted by Elmer van Chastelet on 1 March 2012 at 14:36

Another run with only log4j.logger.org.hibernate.type=trace, hibernateLog changed to log4j.logger.org.hibernate.type=error, hibernateLog gives a total loading time of 3580ms.

The trace level is needed to get rid of the ? parameters in query logs. I think we need to make this optional. SQL logging will still work then, but without parameter values filled in.

Added Logger-analysis.pdf.

This shows repeated tests (4 times) for 5 different settings.
I do like xmacrorec ;)

The analysis (updated) shows that the new settings (R4950) are about 7.3% faster than r4949 wrt total page loading time (20 links clicked on researchr website). If we can change all logging levels to error (and maybe dynamically switch to more detailed level when ?logsql is used) we could win 15.2% in total page loading time over r4949.

Updated ?logsql to dynamically set required logging levels in revision 4951. ?logsql also uses the org.hibernate.type.descriptor.sql.BasicBinder logger instead of the org.hibernate.type logger. This eliminates logging of values returned by a query.

Nice work Chris! Your changes in r4951 result in the best page loading times.

See rightmost column in the updated Logger-analysisv3-r4951, which also includes single test runs performed on the lab pc’s @ 8th floor.

Closing this issue…