Zrób to sam - NHibernate Profiler

20.03.2013

Średnio raz w miesiącu NHibernate doprowadza mnie do białej gorączki wyjątkiem:

System.Transactions.TransactionAbortedException: The transaction has aborted. ---> System.Data.SqlTypes.SqlTypeException: SqlDateTime overflow. Must be between 1/1/1753 12:00:00 AM and 12/31/9999 11:59:59 PM.

Powodem powstania tego wyjątku jest niewypełnienie (lub błąd w definicji mapowania) właściwości DateTime obiektu biznesowego zapisywanego do bazy danych. Problem w tym, że treść tego komunikatu jest tak ogólna, że w przypadku pracy z domeną złożoną z więcej niż kilku obiektów namierzenie źródła problemu może potrwać… bardzo długo. Nie pomoże tutaj nawet Sql Profiler z Sql Server.

Jak podejść do tematu? Można skorzystać z NHibernate Profiler Orena Eini (Ayende). NHProf w ciągu chwili zaprowadzi nas do źródła problemu. Jest jeden problem. Ten program kosztuje i to nie małe pieniądze. W okolicach 300-400 USD, zależnie od rodzaju licencji (subskrypcja? sic!). Innych alternatyw (w postaci programów) niestety nie ma. Można próbować włączać opcję ShowSql() przy konfiguracji SessionFactory, ale to też za dużo nie pomoże (błąd powstaje jeszcze przed generacją kodu T-SQL). Słabo.

Przy, którymś z kolei exception tego typu miałem juz serdecznie dosyć. Myślałem już nawet o zakupie NHProfa. Na szczęście przed pozbyciem się kilku setek zielonych zajrzałem DotPeek’iem w kod inicjujący NHProf. Mocno się zdziwiłem. Pod spodem jest obiekt zbierający logi log4net z różnych części NHibernate’a (loggerów) i pompujący je do procesu NHProf. Tylko tyle. 300-400 USD za trochę SMO, router logów z GUI, który nie działa na Windows 2008 (wersja 1.x, w 2.x chyba już się zlitowali i to naprawili)... c’mon Oren!

Wiedząc jak to działa, wystarczyło tylko dobrać się do logów NHibernate’a. Jako, że korzystam w swoich aplikacjach z NLog’a musiałem tutaj trochę pokombinować (pogooglować). Wykombinowałem bibliotekę NHibernate.NLog dostępną na NuGecie. Po zainstalowaniu w projekcie pojawi się klasa NLogFactory i przykładowa konfiguracja NLoga. Teraz aby zobaczyć wszystkie logi z NHibernate w swojej aplikacji wystarczy dodać do App.config w sekcji AppSettings:

<add key="nhibernate-logger" value="MyNamespace.NLogFactory, MyAssemblyName"/>

A w NLog.config:

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" throwExceptions="true">

    <targets async="true">
        <target name="ds" xsi:type="Console"/>
    </targets>

    <rules>
        <logger name="NHibernate.*" minlevel="Trace" writeTo="ds" />
    </rules>
</nlog>

Teraz w logach NLoga dostaniemy gigantyczną ilość informacji z wnętrza NH. Ilość danych jest na prawdę duża. Kilka prostych zapytań objętych jedną transakcją MSDTC generowało u mnie kilku megabajtowy plik :O Proponuję nie uruchamiać tego na produkcji bez nadzoru ;) Żeby zmniejszyć trochę ilość danych można ograniczyć poziom logowania i zawęzić loggery do NHibernate.SQL i NHibernate.AdoNet.AbstractBatcher. Teraz wystarczy przeszukać log w poszukiwaniu błędów. Poor man’s NHibernate Profiler. Najważniejsze, że działa.

Lista wszystkich loggerów NHibernate:

  • NHibernate.Transaction.AdoTransaction
  • NHibernate.SQL
  • NHibernate.Impl.SessionImpl
  • NHibernate.Impl.StatelessSessionImpl
  • NHibernate.Impl.AbstractSessionImpl",
  • NHibernate.Event.Default.DefaultInitializeCollectionEventListener
  • NHibernate.Event.Default.DefaultLoadEventListener
  • NHibernate.Cache.StandardQueryCache
  • NHibernate.Persister.Entity.AbstractEntityPersister
  • NHibernate.Loader.Loader
  • NHibernate.AdoNet.AbstractBatcher
  • NHibernate.Tool.hbm2ddl.SchemaExport
  • NHibernate.Tool.hbm2ddl.SchemaUpdate
  • NHibernate.Search.Query.FullTextQueryImpl