Profiler causing extra database reads?

[Joseph Daigle]

We recently upgraded to NHibernate 3.2. We have a number of integration tests which "test" that queries are properly generated. These tests execute against an empty database which is built from our migration scripts on each test run. Essentially all we're doing is making sure that NHibernate generates valid queries based on the db schema.

Many of the queries rely on proxy entities for querying. For instance. Foo has a reference to Bar. We have the Id of an instance of Bar. Using ICriteria, we query for Foo by passing a proxy Bar which is created by ISession.Load<Bar>(id);. For our tests, this works just fine because we can use a randomly generated Id just to see if the query is properly generated.

However, since upgrading to NHibernate 3.2, tests which rely on this are failing. But only if we include the code "HibernatingRhinos.Profiler.Appender.NHibernate.NHibernateProfiler.Initialize();", which we leave on in our debug builds.

Here is an example stack trace (I've left out the lines from our application code, so it starts with the call into NHibernate):

at NHibernate.Impl.SessionFactoryImpl.DefaultEntityNotFoundDelegate.HandleEntityNotFound(String entityName, Object id) in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Impl\SessionFactoryImpl.cs:line 84

at NHibernate.Proxy.AbstractLazyInitializer.CheckTargetState() in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Proxy\AbstractLazyInitializer.cs:line 259

at NHibernate.Proxy.AbstractLazyInitializer.Initialize() in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Proxy\AbstractLazyInitializer.cs:line 127

at NHibernate.Proxy.DefaultLazyInitializer.Intercept(InvocationInfo info) in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Proxy\DefaultLazyInitializer.cs:line 32

at ProviderOrganizationProxy.ToString()

at System.String.Concat(Object arg0, Object arg1, Object arg2)

at NHibernate.Criterion.SimpleExpression.ToString() in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Criterion\SimpleExpression.cs:line 164

at NHibernate.Impl.CriteriaImpl.CriterionEntry.ToString() in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Impl\CriteriaImpl.cs:line 970

at NHibernate.Impl.CriteriaImpl.ToString() in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Impl\CriteriaImpl.cs:line 323

at System.Text.StringBuilder.AppendFormat(IFormatProvider provider, String format, Object[] args)

at System.String.Format(IFormatProvider provider, String format, Object[] args)

at System.String.Format(String format, Object[] args)

at HibernatingRhinos.Profiler.Appender.NHibernate3Logger.ProfilerLogger.DebugFormat(String format, Object[] args)

at NHibernate.Loader.Criteria.CriteriaQueryTranslator.CreateCriteriaSQLAliasMap() in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Loader\Criteria\CriteriaQueryTranslator.cs:line 503

at NHibernate.Loader.Criteria.CriteriaQueryTranslator..ctor(ISessionFactoryImplementor factory, CriteriaImpl criteria, String rootEntityName, String rootSQLAlias) in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Loader\Criteria\CriteriaQueryTranslator.cs:line 74

at NHibernate.Loader.Criteria.CriteriaLoader..ctor(IOuterJoinLoadable persister, ISessionFactoryImplementor factory, CriteriaImpl rootCriteria, String rootEntityName, IDictionary`2 enabledFilters) in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Loader\Criteria\CriteriaLoader.cs:line 37

at NHibernate.Impl.SessionImpl.List(CriteriaImpl criteria, IList results) in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Impl\SessionImpl.cs:line 1928

at NHibernate.Impl.CriteriaImpl.List(IList results) in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Impl\CriteriaImpl.cs:line 265

at NHibernate.Impl.CriteriaImpl.List[T]() in d:\CSharp\NH\NH\nhibernate\src\NHibernate\Impl\CriteriaImpl.cs:line 276

From this it appears that the Profiler is trying to effectively ToString() the proxy object which forces it to load.

It also appears that this might be the result of the new internal proxy factory in 3.2. We previously used Castle, which worked fine. I suppose the new implementation is forcing the entity to load.

So even though I'm getting this error, I believe there are still issues where using the Profiler is definitely causing extra database reads because of the new proxy implementation.

Should I open this as a bug with NHibernate?

[Ayende Rahien]

Hm,

the profiler should NEVER cause a db call.

Can you provide me with a failing test?

--
You received this message because you are subscribed to the Google Groups "nhprof" group.
To view this discussion on the web visit https://groups.google.com/d/msg/nhprof/-/RVF0Ys5XQw4J.
To post to this group, send email to nhp...@googlegroups.com.
To unsubscribe from this group, send email to nhprof+un...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/nhprof?hl=en.

[Joseph Daigle]

I've uploaded a console-app project here: https://github.com/jdaigle/ProfilerBreakingTest

Really simple. two entities: Bar references Foo. Query for Bar by using proxy of Foo with a random Id.

When the profiler is initialized, the code fails because it attempts to load the Foo entity. When the profile is not initialized, the code does not fail: the query simply returns the expected amount of rows.

Interested side note: If NHibernate were to through an exception executing the query, it appears to do a ToString() on the proxy object as part of building the exception message, which results in an extraneous database read.

I'm pretty convinced that this is a bug or a design flaw in NHibernate's new internal proxy factory.

[Joseph Daigle]

I've actually updated the previously mentioned link to follow the pattern used for submitting bugs with NHibernate. It demonstrates a few failing use cases, some related specifically to the use of the profiler.

[Joseph Daigle]

I can actually confirm that this problem also occurs with the NHibernate <= 3.1 when using the LinFu ProxyFactory.

Both LinFu and the new build-in ProxyFactory for 3.2 actually initialize the proxy object when doing a ToString(). This causes the entity to be loaded when you didn't want it to be loaded.

Something about the Castle ProxyFactory causes the ToString() to not cause the entity to load.

-- 

Joseph Daigle

[Ayende Rahien]

Okay, I figured out what the problem, the problem exists all the time, the difference is that if we fail to generate the message in log4net, for example, we silently ignore the issue.

I believe that this is an issue that should be handled by NH, as per your patch.

I'll fix NH Prof so you wouldn't see the exception, but the actual extra call will happen whenever you have logging enabled, regardless if you have NH Prof there or not.

--

You received this message because you are subscribed to the Google Groups "nhprof" group.

To view this discussion on the web visit https://groups.google.com/d/msg/nhprof/-/30Qrlep9kZkJ.

[Joseph Daigle]

Awesome. Thanks.

-- 

Joseph Daigle