NHibernate (and ActiveRecord’s) show_sql in web application

Looking into When using an OR/M of any kind, it is quite worthwhile to be able to look at the SQL generated by the tool, for various reasons (such as tuning the DB, finding SELECT N+1 issues, and sheer curiosity).

  Solution #1 One way of doing that is to start a profiler on the DB engine, but it has its downsides. For one, you would need a profiler tool, which is not always freely available. You might also not be able to access the DB engine with that kind of tool on various hosted environments.

In NHibernate’s configuration (and it is also exposed to Castle’s ActiveRecord users) you can set a property names “show_sql” to true. This will cause NHibernate to spit every SQL query, along with its parameters, onto the Console. Very useful when running Tests, but when running within a Web Application, you do not have access to the Console window, and can’t really see what is going on.

That also leads to another problem with using a profiler on the DB engine – you won’t be able to figure out which queries belong to which web request.

  Solution #2 One comprehensive solution is to use the excellent tool from Oren Eini – NhProf. I will not cover this tool here; it does lots of great stuff, and can help your development cycle. However not everyone will be willing to pay the price for using it.

not to worry, I hereby offer you two more options, which gives you less options, but are good enough for the problem at hand, and are free.

  Free solution #1 NHibernate is using log4net. it stores a lot of what it’s doing there. So, one can always setup a logger named “NHibernate.SQL” and get a hold of the queries. I do not cover log4net usage here. Google it up, and then set up the NHibernate.SQL logger.

You’d also want to setup a log4net variable for you to group the queries it gets by the web-request that needed them. You can do so by setting a property on log4net’s GlobalContext. e.g., in Application_BeginRequest:

log4net.GlobalContext.Properties["page_url"] = Context.Request.RawUrl + "|" + Guid.NewGuid();

then you’d set the log appender to write the page_url value, and you’ll be able to Group By it.

But this suck. You need to depend on log4net even if you do not want to, and setup that hack-ish global property, then read it from the log4net storage, and lots of complexities. wouldn’t it be great if you could simply got a hold of the Console’s output (or at least the NH parts of it?)

  Free solution #2 – even simpler The Console object allow you to set a custom Writer to its Out stream. Meaning, you can grab the Console’s output into an in memory string during a request, and then at the end of the request, grab all lines that starts with “NHibernate:” and you’re done:

on Application_BeginRequest:

var writer = new StringWriter();
Console.SetOut(writer);
Context.Items[SqlLogFilter.SQL_LOG_WRITER_KEY] = writer;

on Application_EndRequest:

var writer = HttpContext.Current.Items[SQL_LOG_WRITER_KEY] as StringWriter;
if (writer != null)
{
	var lines = writer.ToString().Split(new[] { Environment.NewLine }, StringSplitOptions.RemoveEmptyEntries);
	var relevantLines =
		lines.Where(l => l.StartsWith("NHibernate") || l.Length > 0 && char.IsWhiteSpace(l[0])).ToArray()
		;
	var queries = string.Join(Environment.NewLine, relevantLines)
		.Split(new[] {"NHibernate:"}, StringSplitOptions.RemoveEmptyEntries)
		.Select(q => q.Trim());
	DoSomethingWith(queries);
}

within DoSomethingWith you can do whatever you like with the queries string collection

The more complete solution that I use, is taking advantage of a feature in Monorail’s AspView called ViewFilter (you can do this with ASP.NET’s output filter; look up HttpFilter. it’s not as clean, but workable). I create a filter that wrap the stuff that’s on the Application_EndRequest, turn the queries collection into a bunch of <pre> elements, and stick it within the view-engine’s output by simple string.Replace call, injecting these <pre> elements into a marker location in the markup.

I’d then use jQuery to make these <pre> elements visible when clicking somewhere secret on the screen.

The ViewFilter’s code (for reference):

public class SqlLogFilter : IViewFilter
{
	public static readonly string SQL_LOG_PLACEHOLDER = "SQL_LOG_PLACEHOLDER";
	public static readonly string SQL_LOG_WRITER_KEY = "SQL_LOG_WRITER_KEY";
	public string ApplyOn(string input)
	{
		var log = "";
		var writer = HttpContext.Current.Items[SQL_LOG_WRITER_KEY] as StringWriter;
		if (writer != null)
		{
			var lines = writer.ToString().Split(new[] { Environment.NewLine }, StringSplitOptions.RemoveEmptyEntries);
			var relevantLines =
				lines.Where(l => l.StartsWith("NHibernate") || l.Length > 0 && char.IsWhiteSpace(l[0])).ToArray()
				;
			var queries = string.Join(Environment.NewLine, relevantLines)
				.Split(new[] {"NHibernate:"}, StringSplitOptions.RemoveEmptyEntries)
				.Select(q => q.Trim());
			log = queries
				.Select(q => "<pre>" + q + "</pre>")
				.Aggregate("", (q1, q2) => q1 + q2);
			var count = queries.Count();
			log = "<p>Queries: " + count + "</p>" + log;
		}
		return input.Replace(SQL_LOG_PLACEHOLDER, log);
	}
}