NHibernate - find the code that's executing the query

Question

I'm working on a very big project that was done by someone else. This code has many projects in it, and it's using NHibernate as ORM. The database is very busy, so I'm trying to diagnose the places where it's slow and try to diagnose the entire system flow.

One of the things I've done is add a log4net for NHibernate.SQL which outputs all running queries to a log file:

<logger name="NHibernate.SQL" additivity="false">
    <level value="ALL" />
    <appender-ref ref="NHibernateSQLAppender" />
</logger>

and this is the appender:

<appender name="NHibernateSQLAppender" type="log4net.Appender.RollingFileAppender">
        <file value="NHibernateSQL.txt"></file>
        <appendToFile value="true"></appendToFile>
        <maximumFileSize value="15MB"></maximumFileSize>
        <maxSizeRollBackups value="10"></maxSizeRollBackups>
        <rollingStyle value="Size"></rollingStyle>
        <layout type="log4net.Layout.PatternLayout">
            <param name="ConversionPattern" value="%d [%t] [%line] %-5p %c [%x] &lt;%X{auth}&gt; - %m%n"></param>
        </layout>
</appender>

In the log file I see a query that runs many times in a short period of time and I would like to find the code that runs it. I was able to find the hbm file by the table name, and the class that it's mapped to.

I searched for references to that class - but there are many.

So my basic question is how can I find which code runs that specific query? is that even possible?

Thanks

Have you tried adding stack trace to appener layout? - http://stackoverflow.com/questions/9319810/how-to-log-stack-trace-using-log4net-c — Novakov, Aug 19 '14 at 08:02
You can use `%stacktrace{level}` in pattern: http://stackoverflow.com/a/9319894/1619238 — Vlad, Jun 21 '16 at 12:05

score 1 · Answer 1 · answered Aug 19 '14 at 08:55

1

Have you tried Nhibernate Profiler? Using the profiler will help and if I remember correct I think you get the stack trace for each query?

More info on the profiler http://www.hibernatingrhinos.com/products/nhprof

answered Aug 19 '14 at 08:55

Mats Björkman Eldh

119
3

Erik Hart · Answer 2 · 2014-08-20T22:38:26.183

You can set the name(space) in the <logger> to NHibernate only (without .SQL), which will be pretty verbose. Then you may go back from ALL to TRACE or DEBUG level or look for specific namespaces with useful information.

Does your application use log4net, too? Then you can get combined logs of the application and NHibernate, checking what is sending the queries. Just add another <logger /> block with your application's namespace; you can use the same <appender>!

Normally, you can easily see the database objects in the SQL queries.

Many times (often 100s of times) the same query points out to the infamous N+1 problem - load subordinate rows/objects for a number of parent objects/rows by iterating over the parents and initialize the child collection. For example, send

SELECT * FROM Children WHERE ParentId=@parid /* for some 100 Parent objects. */

That's first one (1) query returning N parent objects before, plus N queries for child collections on each parent.

N+1 even gets worse, when programmers are not familiar with NHibernate collections and implement wrong, or start to code their own collection handling without NHibernate collection mapping (understanding NHibernate literally as an OR Mapper, make objects from an SQL result or oherwise). Replacing by joins will likely result in excessively huge result sets (cartesian product).

But NHibernate is also an optimizer for DB access, offering good ways between N+1 and monster join, namely batch settings, in the session factory config (adonet.batch_size 50, for example), and then batch-size set on each class element and collection property.

NHibernate - find the code that's executing the query

2 Answers2