These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 16 posts ]  Go to page 1, 2  Next
Author Message
 Post subject: Speed issues in populating objects
PostPosted: Fri Mar 07, 2008 1:14 pm 
Newbie

Joined: Fri Mar 07, 2008 12:45 pm
Posts: 5
I've inherited an old system for which I am trying to recreate parts using asp.net. I'm considering using NHibernate to act as the DAL but initial tests are producing some poor performance results. I'm confident that the mistake is all mine so if someone could point me in the right direction i'd appreciate it.

I've created a template using MyGeneration and have generated all my mappings and class files. Everything compiles and I can access my data as I wish to.

However the object graph I am using is quite large (385 objects) and i'm wondering if this is the cause of the performance issues.

Working with one of the larger objects "Job" which references many others Employee, Customer, Site, etc.. I use the following mapping

-----------------------------------------------------------------------
Mapping for Job
-----------------------------------------------------------------------

<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2" assembly="PS.Core" namespace="PS.Core.Domain">

<class name="Job" table="Job">

<id name="Jobid" column="JobID" type="Int32" unsaved-value="0">
<generator class="native"/>
</id>

<bag name="AttachmentViewerList" inverse="true" lazy="true" >
<key column="JobID" />
<one-to-many class="AttachmentViewer" />
</bag>

<bag name="InvoiceDetailList" inverse="true" lazy="true" >
<key column="JobID" />
<one-to-many class="InvoiceDetail" />
</bag>

<bag name="InvoiceHeaderList" inverse="true" lazy="true" >
<key column="JobID" />
<one-to-many class="InvoiceHeader" />
</bag>

<bag name="InvoiceLineList" inverse="true" lazy="true" >
<key column="JobID" />
<one-to-many class="InvoiceLine" />
</bag>

<bag name="JobJournalList" inverse="true" lazy="true" >
<key column="JobID" />
<one-to-many class="JobJournal" />
</bag>

<bag name="JobLinkList" inverse="true" lazy="true" >
<key column="JobID" />
<one-to-many class="JobLink" />
</bag>

<bag name="JobTechnicianList" inverse="true" lazy="true" >
<key column="JobID" />
<one-to-many class="JobTechnician" />
</bag>

<many-to-one name="SkillSetid" column="SkillSetID" class="SkillSet" />
<many-to-one name="Custid" column="CustID" class="Customer" />
<many-to-one name="Siteid" column="SiteID" class="Site" />

<property column="SiteName" type="String" name="SiteName" not-null="true" length="50" />
<property column="ContactID" type="Int32" name="Contactid" not-null="true" />
<property column="ContactName" type="String" name="ContactName" not-null="true" length="50" />
<property column="ContactPhone" type="String" name="ContactPhone" not-null="true" length="30" />

.......plus 50ish other properties

-----------------------------------------------------------------------

------------------------------------------------------------------------
Method to load Jobs by Status (Returns roughly 100 Jobs)
with customers preloaded.
------------------------------------------------------------------------

public IList<Job> GetJobsByStatus(Job.JobStatus jobStatus)
{
ICriteria criteria = base.NHibernateSession.CreateCriteria(typeof(Job));

criteria.SetFetchMode(Job.ColumnNames.Custid, FetchMode.Eager);

criteria.Add(Expression.Eq(Job.ColumnNames.Status, (byte)jobStatus));

return criteria.List<Job>();
}

------------------------------------------------------------------------

By using a profiler I can see the query that executes is perfect and includes the customer join and takes only a split second to execute.

However on the line....

return criteria.List<Job>();

...I have to wait about 30 seconds for my objects to be loaded.

Again using profiler during this time I can see that no other queries are run against the database.

If I instantly run the method again (on the same page) I can see the query hit the database again and run just as quickly. This time however the jobs are loaded along with the customer records in a split second.

My question is why does it take so long to populate my objects initially? What happens during the first use of nHibernate that is slowing me down. Is there anything I can do to decrease this initial load time. If someone could explain what i'm seeing it would be a big help. I have turned off logging and this did increase performance to the point that I am at now.

I am using the open session in view pattern.


Top
 Profile  
 
 Post subject:
PostPosted: Sat Mar 08, 2008 4:44 am 
Beginner
Beginner

Joined: Fri Aug 10, 2007 3:34 am
Posts: 44
i had a similar experience: nhibernate waited like 10 seconds before a query... in this time the output didn't show anything


Top
 Profile  
 
 Post subject:
PostPosted: Sat Mar 08, 2008 5:24 am 
Senior
Senior

Joined: Sat Sep 03, 2005 12:54 am
Posts: 139
You could use the second level cache so that after the initial hit to the DB, things will be lightning fast.


Top
 Profile  
 
 Post subject:
PostPosted: Sat Mar 08, 2008 6:05 am 
Newbie

Joined: Fri Mar 07, 2008 12:45 pm
Posts: 5
I think thats what i'm seeing. Once i've been to a page already its very quick in navigating back, requesting new data, etc...

I just want to check there isn't a better way to do things as this is really going to slow down my development as having wait half a minute before I can see if a change to a web page has worked isn't really ideal.

What i'm trying to work out is where the bottle neck is. The sql is very quick, populating the classes is very quick (on the second load) so where is the slow down on first access?


Top
 Profile  
 
 Post subject:
PostPosted: Sat Mar 08, 2008 1:57 pm 
Beginner
Beginner

Joined: Fri Jan 12, 2007 1:08 am
Posts: 41
Are you seeing the slowdown if you return less data (1, 10, 100 records etc.)?

Have you used Log4Net to capture all of the debugging output? There is going to be a lot (and that's an understatement) of output if you return the full dataset but you should be able to see where the slowdown is happening.


Top
 Profile  
 
 Post subject:
PostPosted: Sat Mar 08, 2008 6:21 pm 
Senior
Senior

Joined: Sat Sep 03, 2005 12:54 am
Posts: 139
Sorry...didn't fully absorb the initial question!

That is pretty weird because I am loading a lot more than 385 objects in my app during startup and this all occurs really quickly even though it is hitting the DB lots.

Try inspecting the session cache in the debugger before and after the call to criteria.List<Job>() and see how many objects are in there. Maybe it is loading a lot more than you think it is. However, you would expect there to be lots of DB access if it was loading a lot of other objects so it doesn't really make sense.

You could also try using session.Get() to retrieve a single Job and see if you have the same problem.

Where are you opening the session factory and how long is its lifetime being maintained?

Looking at the supplied mapping XML, it doesn't appear that you are using the second level cache. This requires a <cache> tag on the classes and collections that you want to enable caching. This won't help your initial load problem but something worth considering for overall improved performance of the app.


Top
 Profile  
 
 Post subject:
PostPosted: Sun Mar 09, 2008 4:00 am 
Expert
Expert

Joined: Thu Dec 14, 2006 5:57 am
Posts: 1185
Location: Zurich, Switzerland
Do you use the reflection optimizer ? That may cost some time the during startup.

_________________
--Wolfgang


Top
 Profile  
 
 Post subject:
PostPosted: Sun Mar 09, 2008 12:05 pm 
Newbie

Joined: Fri Mar 07, 2008 12:45 pm
Posts: 5
Not intentionally, how would I go about finding out?

Thanks to everyone for their help so far. I'm away for a few weeks now but will try all your suggestion when I return and update you on my findings.


Top
 Profile  
 
 Post subject:
PostPosted: Sun Mar 09, 2008 3:55 pm 
Expert
Expert

Joined: Thu Dec 14, 2006 5:57 am
Posts: 1185
Location: Zurich, Switzerland
hibernate.use_reflection_optimizer set to true in your configuration file.

_________________
--Wolfgang


Top
 Profile  
 
 Post subject:
PostPosted: Tue Mar 25, 2008 12:50 pm 
Newbie

Joined: Fri Mar 07, 2008 12:45 pm
Posts: 5
I've made some changes so that i'm only loading one object (no others are fetched anymore) and I still get a major slow down on populating the data of one job.

The slow down appears to happen in the log file at .............

-----------------------------------------------------------------------------

2008-03-25 16:34:21,282 [9] NHibernate.Impl.SessionImpl.GetCollection(:0) - creating collection wrapper:[PS.Core.Domain.Job.JobJournalList#123456]

2008-03-25 16:34:21,282 [9] NHibernate.Impl.SessionImpl.GetCollection(:0) - creating collection wrapper:[PS.Core.Domain.Job.JobLinkList#123456]

2008-03-25 16:34:21,282 [9] NHibernate.Impl.SessionImpl.GetCollection(:0) - creating collection wrapper:[PS.Core.Domain.Job.JobTechnicianList#123456]

[---- HERES WHEN IT SLOWS DOWN ---]

2008-03-25 16:34:21,298 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [SkillSet#2]

2008-03-25 16:34:22,063 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Customer#152]

2008-03-25 16:34:24,078 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Site#17100]

2008-03-25 16:34:24,984 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [JobType#2]

2008-03-25 16:34:26,249 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [CreatedSource#1]

2008-03-25 16:34:26,858 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [JobRequestType#8]

2008-03-25 16:34:27,545 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Occupier#15467]

2008-03-25 16:34:28,388 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Person#28542]

2008-03-25 16:34:30,340 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Employee#288]

[---- A NINE SECOND WAIT HERE ---]

2008-03-25 16:34:39,305 [9] NHibernate.Impl.SessionImpl.InitializeEntity(:0) - done materializing entity [PS.Core.Domain.Job#123456]

-----------------------------------------------------------------------------

As stated before if I reload this page then then exact same code is put into the logfile but with almost no time in between the "DoLoadByClass" calls.

Could someone please explain what this piece of code is doing? No sql is fired at the database during these DoLoadByClass statements.

The performance is great once this initial hit is taken. I would just love to know what its doing during this time. Any help appreciated.


Top
 Profile  
 
 Post subject:
PostPosted: Tue Mar 25, 2008 1:40 pm 
Expert
Expert

Joined: Thu Dec 14, 2006 5:57 am
Posts: 1185
Location: Zurich, Switzerland
Can you step through the hibernate code to isolate the location where that happens ?

_________________
--Wolfgang


Top
 Profile  
 
 Post subject:
PostPosted: Wed Mar 26, 2008 3:37 am 
Beginner
Beginner

Joined: Fri Aug 10, 2007 3:34 am
Posts: 44
jason.hill wrote:
You could use the second level cache so that after the initial hit to the DB, things will be lightning fast.

it depends on the cache providers. some are slow. i used the memcached
provider and it was slow :(


Top
 Profile  
 
 Post subject:
PostPosted: Wed Mar 26, 2008 3:40 am 
Senior
Senior

Joined: Sat Sep 03, 2005 12:54 am
Posts: 139
That's interesting. From what I have read memcached seemed to be quick.

I was thinking about using memcached in a cluster but will have to investigate it more fully before jumping in! Were you running in a cluster of standalone?


Top
 Profile  
 
 Post subject:
PostPosted: Wed Mar 26, 2008 3:45 am 
Beginner
Beginner

Joined: Fri Aug 10, 2007 3:34 am
Posts: 44
standalone

also made a test, and I noticed the cache didn't have any impact
although I've checked SQL profiler to see that the DB gets hit and it seemed OK.

maybe i didn't used the cache provider right...


Top
 Profile  
 
 Post subject:
PostPosted: Fri Apr 04, 2008 10:01 am 
Newbie

Joined: Fri Mar 07, 2008 12:45 pm
Posts: 5
Just a quick update on my findings....

Where I am using lazy loading for all my objects the DoLoadByClass method is creating a proxy object for each of the dependent objects.

Therefore when I load a job it needs to create proxies for these objects...

2008-03-25 16:34:22,063 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Customer#152]

2008-03-25 16:34:24,078 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Site#17100]

2008-03-25 16:34:24,984 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [JobType#2]

2008-03-25 16:34:26,249 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [CreatedSource#1]

2008-03-25 16:34:26,858 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [JobRequestType#8]

2008-03-25 16:34:27,545 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Occupier#15467]

2008-03-25 16:34:28,388 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Person#28542]

2008-03-25 16:34:30,340 [9] NHibernate.Impl.SessionImpl.DoLoadByClass(:0) - loading [Employee#288]

Depending upon the references contained within these proxy objects they can take anywhere upto 10 seconds to be created.

The main slow down happens on objects like employee which in turn reference a massive number of objects. Employee links to about 100 other tables.

Does anyone know how to speed up this proxy generation or if you can turn it off (or would that be defeating the whole point of nhibernate)?


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 16 posts ]  Go to page 1, 2  Next

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
cron
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.