2 tricks to NHProf

Haven’t touch NhProf for a while, this morning the error message said, the installed license for NHibernate Profiler is not valid!

After contact with Ayende, it turns out the issue is from our user profile, because if I switch to a different user, everything works smoothly.

OK, while waiting for somebody can figure out that specific user profile problem, what I can do is to use the runas command to ‘sudo’ nhprof to run under another user account.

One annoying thing is windows keep asking input password when runas starts, echo password or pipe into a text file doesn’t work. The trick is to use built-in savecred option in runas command, just type in the password once, then it will save it.

runas /savecred /user:local\nhprof c:\app\nhprof\launch_nhprof.bat

Also, the trick for waiting for nhprof to generate report when shutting down:

runas /savecred /user:local\nhprof c:\app\nhprof\kill_nhprof.bat

@echo off
@echo waitinging for output report generating ...
:WAIT_FOR_OUTPUT
if not exist c:\tmp\nhprof_Output.html (
GOTO WAIT_FOR_OUTPUT
)
@echo on

Initialize NhProf in NUnit test

NhProf can be setup without changing the app code, but that assume you already have log4net hooked up in app. Our experience is setting up log4net is still more work comparing to init nhprof in unit-test code. http://nhprof.com/Learn/GettingStarted

Here is a easy way to init Nhprof in unit-test project, create a Global class with SetupFixture attribute, remove any namespace, this will ensure the setup code in this class run before any of the fixtures in the entire assembly. (NUnit doc)

    [SetUpFixture]
    public class Global
    {
        [SetUp]
        public void RunBeforeAnyTests()
        {
			Console.WriteLine("Initializing NHibernateProfiler......");
            HibernatingRhinos.Profiler.Appender.NHibernate.NHibernateProfiler.Initialize();
        }

    }

Embed NhProf into CruiseControl.net

There is a brief document on NHProf website describing how to embed NhProf into CI server, here are practical problems I encountered and my solutions/workaround.

First problem is, once NhProf command line start up, it sits there until Ctl+C. I need to make it run in background mode, in window term, start it in a new command window. This is simple, adding a start right before the start batch fixed the problem.

But the second problem is very difficult, NhProf can output to xml format or html format, but there is no xslt file available to let user to do xml transformation.

I could create my own xslt file, but looked into the html output, it’s a lot of work. I decided to simply embed the whole html chunk as the CData block into CruiseControl merged result.

NAnt:

  <target name="run.test.with.nhprof" depends="launch.nhprof, run.test, shutdown.nhprof, wrap.nhprof.output" />

  <target name="launch.nhprof" >
	<if test="${file::exists('c:\app\nhprof\start_nhprof.bat')}">
	    <exec basedir="${dir.tools}/nhprof/" workingdir="${dir.compile}" program="c:\app\nhprof\start_nhprof.bat" />
		<echo message="NHibernate Profiler started." />
	</if>
  </target>

  <target name="shutdown.nhprof" >
  	<if test="${file::exists('c:\app\nhprof\shutdown_nhprof.bat')}">
		<exec basedir="${dir.tools}/nhprof/" workingdir="${dir.compile}" program="c:\app\nhprof\shutdown_nhprof.bat" />
	</if>
  </target>

  <target name="wrap.nhprof.output" >
	<echo message="Waiting for NhProf generating output file..." />
	<sleep milliseconds="1000" />

	<loadfile
                file="${dir.compile}/nhprof_output.html"
                property="nhprof.output" />
	<echo file="${dir.compile}/nhprof_output.xml" message="&lt;nhprof&gt;&lt;![CDATA[${nhprof.output}]]&gt;&lt;/nhprof&gt;" />
  </target>

Xslt:

 	<xsl:template match="/">
		<xsl:value-of select="cruisecontrol//nhprof" disable-output-escaping="yes" />
	</xsl:template>

Here is the result:

Note: IE doesn’t support nested html tag (html/html), this screen shot is taken from Firefox.

1st day of NHProf

Finally, I got some time to try this must-have tool for NHibernate, downloaded it, asked for the trail key, why 33 days?

No changing to source code sounds a good idea, the assumption is using log4net appender, every NH project suppose use log4net, doesn’t it?

I’m not sure what NHibernate internal statistics is? (Ayende doesn’t recommend turn this on) Because we are using FluentNHibernate, there is no hibernate.cfg.xml file we can change, there is 2 solutions from stack overflow, but without seeing this xml file, how can I know it works? (BTW, how can I export hibernate.cfg.xml to somewhere like what we can do for hbm.xml?)

The result is, I can’t output statistics file for NHprof, so instance is the only way. Fortunately, it works. But, what if the port is being used? Or how to modify it? I couldn’t find it in NHProf.exe.config, it can’t be hardcoded?

     tcp://127.0.0.1:22897

Input from Ayende: Changing the port that the profiler listen to is done through the UI, Options > Settings

OK, back to our app, 5 Unbounded result set warnings and one N+1 select alert. Not too bad, the interesting part is, this N+1 select alert only appears in WCF client, not in domain service or repository layer.

It turns out the problem happens in AutoMapper which is doing the property loop through the result set from repository. Some properties are set to lazy-load.

We should be  really careful when using AutoMapper, I think we should either explicitly exclude those lazy-load properties, or create a query to eager fetch those needed properties.

Thanks to NHProf, developers can figure out what’s extatly beneath their feet, ice or solid ground.