NHibernate suddenly very slow - inexplicable behaviour

Question

I know this is a popular issue and various solutions have been proposed to others, but mine is slightly different.

Firstly it started happening suddenly since two days ago and nothing has changed in the NHibernate layer to explain such a change in behaviour.

I used dotTrace and drill down to it and found that certain cached queries take up to 70 seconds to perform (i.e. a GetAllCountries() method that returns a list of country objects).

70 seconds is pretty insane for such a simple query that doesn't have external references.

dotTrace reveals that it called the CachedCountryService which should return the list immediately. Instead it eventually leads to the CountryService which performs the 70 second read.

The database is mySQL.

An attached image of the dotTrace report

The Country object looks like this:

   public class CountryMapping : ClassMap<Country>
    {
        public CountryMapping()
        {
            Table("ma_tbl_country");

            Id(t => t.Id, "id");
            Map(t => t.Code, "code");
            Map(t => t.Name, "name");
            Map(t => t.Match, "`match`");

            References(t => t.RiskGroup).Column("RiskId");

            HasManyToMany(t => t.PaymentOptions)
                .Table("ma_tbl_country_payment_option")
                .ParentKeyColumn("country_id")
                .ChildKeyColumn("payment_option_id").Cascade.SaveUpdate();
        }
    }

The Initializer doesn't affect the country object although Office and Account are used in anoher NHibernate query that performs really poorly (takes 30 seconds).

 public NHibernateInitializer()
        {
            base.
            ExtraConfiguration =
                t =>
                    t.Mappings(s => s.FluentMappings.AddFromAssemblyOf<DAL.Mappings.OfficeMapping>().Conventions.Add(typeof(DisableLazyLoadConvention)))
                    .Mappings(s => s.FluentMappings.AddFromAssemblyOf<AccountMapping>().Conventions.Add(AutoImport.Never()));
        }

And the DefaultLazyConvention is part of an internal library that does this:

  public class DisableLazyLoadConvention : IHibernateMappingConvention, IConvention<IHibernateMappingInspector, IHibernateMappingInstance>, IConvention
  {
    public void Apply(IHibernateMappingInstance instance)
    {
      instance.Not.DefaultLazy();
    }
  }

UPDATE:

I added SQL level profiling and the results are buffling.

I have two different projects running the same almost code and I get 324 sql queries in the slow projects taking 100 seconds to run and then 324 IDENTICAL queries in the other project taking 1 second!

So I believe the problem is NHibernate configuration, rather than code because these two set of queries are identical using the same domain models. They're also using the same database with the same db user.

Do you have your NHibernate logging level set to "DEBUG"? Try changing it to "WARN" or "ERROR". — Daniel Schilling, Sep 04 '13 at 15:09
I have it to ALL because I am trying to see the queries. Before it was on ERROR and it logged nothing. The queries don't fail, they just take forever. And it's only specific queries — Nick, Sep 04 '13 at 15:10
Does `Country` have any collections that are marked `lazy="false"`? — Daniel Schilling, Sep 04 '13 at 15:30
No it doesn't. I've added the code for the Mapping of Country and the Initializer. Lazy loading is disabled on one object only — Nick, Sep 04 '13 at 15:41
Sure, I added it. All this started happening two days ago, I can't in the life of me figure out why, but it is either configuration related or some database issue? maybe foreign keys gone missing.. no idea — Nick, Sep 04 '13 at 15:52

score 0 · Answer 1 · answered Sep 04 '13 at 16:26

0

From your dotTrace screenshot, please notice that InitializeNonLazyCollections is taking almost all of the time.

The DisableLazyLoadConvention is being applied to more than just Office. It is being applied to all ClassMaps in the same assembly as OfficeMapping. Conventions are used to apply mappings in wide paintbrush strokes across your entire application. For example, you can use them to say things like "Whenever you see a DateTime property whose name ends with 'Utc', map it using .CustomType("UtcDateTime")."

If you need to apply special mappings to just one class, do so in the ClassMap (for fluent mappings) or in an IAutoMappingOverride (for auto mapping). If you want to change the mapping for every class, that's when you use conventions.

Remove .Conventions.Add(typeof(DisableLazyLoadConvention)) from your NHibernate initialization code, and replace it with more targeted calls to .Not.LazyLoad() in OfficeMapping.

answered Sep 04 '13 at 16:26

Daniel Schilling

4,829
28
60

Very promising. Let me check – Nick Sep 04 '13 at 16:29
If I remove that convention then I get: "method get_Id should be 'public/protected virtual' or 'protected internal virtual'" on all the entity classes in the system. – Nick Sep 04 '13 at 16:48
This line has the problem: CurrentSessionContext.Bind(nHibernateContext.SessionFactory.OpenSession()); – Nick Sep 04 '13 at 16:48
Yes. In order for lazy loading to work (and you really want it to work - see [ayende's blog post](http://ayende.com/blog/4573/nhibernate-is-lazy-just-live-with-it)), all public and protected members of your entities must be marked virtual. – Daniel Schilling Sep 04 '13 at 16:50
1

See [Davy Brion's article explaining why everything must be virtual](http://thatextramile.be/blog/2009/03/must-everything-be-virtual-with-nhibernate/). – Daniel Schilling Sep 04 '13 at 16:57
I'm afraid that can't be it. These domain objects are shared by other projects all of which have the same NHibernate configuation and do not exhibit these delays. Only my project does. Not only I cannot change them, but I am pretty sure it's not what's making my project different to the others that are performing well. – Nick Sep 04 '13 at 17:02
You have cold hard proof in the form of the above screenshot that `lazy="false"` is the source of your performance problems. `GetAllCountries` takes 67.7 seconds, and `InitializeNonLazyCollections` is 64.4 of that. That's 95%! – Daniel Schilling Sep 04 '13 at 17:17
But of course, you're quite right that if this initialization code is common to other projects, but the other projects don't have performance problems, then there must be something else that's different. What's different must be the way they are executing their queries. – Daniel Schilling Sep 04 '13 at 17:21
If you never ever allow the entities to load, then you could still get good performance out of this, but your NHibernate code would just be a sad shadow of what it could be. I.e. - if you use a query like: `session.Query().Select(x => new { x.Id, x.Code, x.Name })`, where you tell NHibernate "only fetch these columns, nothing more", then you will be OK. But you won't be able to do things like `country.RiskGroup.Name`, and you won't be able to make changes to the entity and save it, because you never actually loaded the entity. – Daniel Schilling Sep 04 '13 at 17:26

score 0 · Accepted Answer · answered Sep 10 '13 at 11:06

FINALLY got this resolved.

It wasn't NHibernate related! That's why it was so impossible to resolve.

The problem was caused by this package called Combres. It is installed via Nuget with a lot of dependencies. In one of my projects, one of the dependencies was slightly higher version than it expected.

When I uninstalled it and re-installed it, it put the correct DLL versions in place (the slightly older ones) and that made the project work lightning fast!

If anyone is ever caught in such a difficult problem, I hope this might help them to resolve it.

NHibernate suddenly very slow - inexplicable behaviour

2 Answers2