I have quite a strange problem on my hands: the database is apparently giving me timeouts, but that's not the whole story... I'm betting I'm doing something wrong somewhere, but for the life of me I can't think of anything and no amount of search on the internet has helped me.
You can check the details below, but nhibernate is complaining that the SQL Server timeouts on some SQL. I've run that same SQL in a query window and the execution time is laughable (<1s), so that's not it.
From the log code example, you can see that the problem happens during the lazy-loading of the array Events.Entries.
I tried many many things, including rebooting servers, but this problem is consistent (what you are seeing here is the problem as it relates to the test page, but I found it happening in the code as well). Starting with an empty database, I can recreate that problem 100% of the time by creating some entries in a specific order. I don't know what is the straw that breaks the camel's back because before entering the fateful entry, all the application behaves correctly... To be clear, let me repeat that: I enter 2 values and the site behaves perfectly normal. I enter the 3rd entry and bamn, I can't lazily load the Entries array anymore. Completely wierd to me.
Anyway, I've tested many things as I said. At one point I thought I might have a problem with a circular reference involving 3 objects in my diagram (which I still don't know if it is a problem with NHibernate, but I figured it cannot really help). So I've started laying down the diagram in a different way and reworked the mapping file.
So I've got it to a point where if I take one line of the mapping file off, the site behaves normally (and the test) and there is no problem. If I put the ling back, I've got the problem. That line is highlighted in the mapping file and it is a Int32 field, of all things! How can that changes anything?
I've suspected database corruption, but that isn't it (I've reproduced the bug on a fresh db as I mentionned). I'm at the end of my options, which is why I'm posting here. I hope I'm just being silly and someone can tell me which stupid mistake I've made.
Thanks in advance,
Alain-Daniel
Hibernate version: 1.2 RC1
Mapping documents:
I'll copy the appropriate section.
Code:
<joined-subclass name="Competition.Business.CompetitionEntry, Competition.Business" table="t_competition_entries">
<key column="CompetitionEntryID"/>
<many-to-one name="Event" column="CompetitionEventID" not-null="true"/>
[color=darkred]<!--PROBLEM HERE <many-to-one name="Category" column="CompetitionEventCategoryID" not-null="true"/>-->[/color]
<property name="CategoryID" column="CompetitionEventCategoryID" not-null="true"/>
<property name="PublicID" column="PublicID" type="String" length="20" not-null="true" />
<bag name="Inscriptions" table="t_rel_competition_inscriptions_entries" where="Code = ' '" inverse="true" cascade="all">
<key column="CompetitionEntryID"/>
<many-to-many class="Competition.Business.CompetitionInscription, Competition.Business" column="CompetitionInscriptionID"/>
</bag>
</joined-subclass>
The previous object is loaded by this object:
Code:
<joined-subclass name="Competition.Business.CompetitionEvent, Competition.Business" table="t_competition_events">
<key column="CompetitionEventID"/>
<property name="Description" type="String" length="1000" not-null="false" />
<many-to-one name="ParentCompetition" column="CompetitionID" not-null="true"/>
<bag name="Checkpoints" order-by="SequenceNo asc" inverse="true" cascade="all" >
<key column="CompetitionEventID"/>
<one-to-many class="Competition.Business.Checkpoint, Competition.Business"/>
</bag>
<bag name="Classes" inverse="true" cascade="all">
<key column="CompetitionEventID"/>
<one-to-many class="Competition.Business.CompetitionEventClass, Competition.Business"/>
</bag>
<bag name="Categories" inverse="true" cascade="all" >
<key column="CompetitionEventID"/>
<one-to-many class="Competition.Business.CompetitionEventCategory, Competition.Business"/>
</bag>
<set name="Entries" inverse="true" >
<key column="CompetitionEventID"/>
<one-to-many class="Competition.Business.CompetitionEntry, Competition.Business"/>
</set>
</joined-subclass>
(in the Entries relationship).
Code between sessionFactory.openSession() and session.close():I've created a test for it but it involves the visitor pattern, so it is a bit long:
Code:
public partial class Tests_testDAL : System.Web.UI.Page
{
protected void Page_Load(object sender, EventArgs e)
{
DisplayVisitor vis = new DisplayVisitor();
vis.Response = Response;
Response.Write("Loading all competitions<br />");
IList comps = EntityDataSourceUtils.GetCompetitions();
foreach (Competition.Business.Competition comp in comps)
{
comp.Accept(vis);
}
}
}
public class DisplayVisitor : Visitor
{
public HttpResponse Response = null;
int indent = 0;
public override void Visit(object visitable)
{
AddIndent();
base.Visit(visitable);
RemoveIndent();
}
public virtual void Visit(Competition.Business.Competition entity)
{
WriteLine("Competition " + entity.Name + " (ID:" + entity.ID + ")");
foreach (CompetitionEvent ev in entity.Events)
{
ev.Accept(this);
}
}
public virtual void Visit(CompetitionEvent entity)
{
WriteLine("Event " + entity.Name + " (ID:" + entity.ID + ")");
[color=darkred] foreach (CompetitionEntry ev in entity.Entries) // PROBLEM HAPPENS HERE[/color]
{
ev.Accept(this);
}
foreach (CompetitionEventCategory cat in entity.Categories)
{
cat.Accept(this);
}
}
public virtual void Visit(CompetitionEntry entity)
{
WriteLine("Event " + entity.Name + " (ID:" + entity.ID + ")");
}
public virtual void Visit(CompetitionEventCategory entity)
{
WriteLine("Category " + entity.Name + " (ID:" + entity.ID + ")");
}
void AddIndent() { indent++; }
void RemoveIndent() { indent--; }
void Write( string str )
{
int count = 0;
while (count < indent)
{
Response.Write(" ");
count++;
}
Response.Write(str);
}
void WriteLine(string str)
{
Write(str + "<br />");
}
}
It is a web page that displays the content of the objects.
Full stack trace of any exception that occurs:Here we go. The innermost exception says Timeout Expired. Here is the debug info from the logger:
17:07:54.953 [4] ERROR NHibernate.LazyInitializationException - Failed to lazily initialize a collection
NHibernate.LazyInitializationException: Failed to lazily initialize a collection ---> NHibernate.ADOException: could not initialize a collection: [Competition.Business.CompetitionEvent.Entries#4][SQL: SELECT entries0_.CompetitionEventID as Competit2___1_, entries0_.CompetitionEntryID as Competit1_1_, entries0_.CompetitionEntryID as EntityID1_0_, entries0_.CompetitionEventID as Competit2_10_0_, entries0_.CompetitionEventCategoryID as Competit3_10_0_, entries0_.PublicID as PublicID10_0_, entries0_1_.Name as Name1_0_, entries0_1_.IsPrivate as IsPrivate1_0_ FROM t_competition_entries entries0_ inner join t_entities entries0_1_ on entries0_.CompetitionEntryID=entries0_1_.EntityID WHERE entries0_.CompetitionEventID=?] ---> System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
at System.Data.SqlClient.TdsParserStateObject.ReadSni(DbAsyncResult asyncResult, TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadPacket(Int32 bytesExpected)
at System.Data.SqlClient.TdsParserStateObject.ReadBuffer()
at System.Data.SqlClient.TdsParserStateObject.ReadByte()
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
at System.Data.SqlClient.SqlDataReader.get_MetaData()
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
at NHibernate.Impl.BatcherImpl.ExecuteReader(IDbCommand cmd)
at NHibernate.Loader.Loader.GetResultSet(IDbCommand st, RowSelection selection, ISessionImplementor session)
at NHibernate.Loader.Loader.DoQuery(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies)
at NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies)
at NHibernate.Loader.Loader.LoadCollection(ISessionImplementor session, Object id, IType type)
--- End of inner exception stack trace ---
at NHibernate.Loader.Loader.LoadCollection(ISessionImplementor session, Object id, IType type)
at NHibernate.Loader.Collection.CollectionLoader.Initialize(Object id, ISessionImplementor session)
at NHibernate.Persister.Collection.AbstractCollectionPersister.Initialize(Object key, ISessionImplementor session)
at NHibernate.Impl.SessionImpl.InitializeCollection(IPersistentCollection collection, Boolean writing)
at NHibernate.Collection.AbstractPersistentCollection.Initialize(Boolean writing)
--- End of inner exception stack trace ---
Name and version of the database you are using:SQL 2005 Express
The generated SQL (show_sql=true):As you can see in the log here is the SQL generated and which supposedly causes a timeout:
Code:
SQL: SELECT entries0_.CompetitionEventID as Competit2___1_, entries0_.CompetitionEntryID as Competit1_1_, entries0_.CompetitionEntryID as EntityID1_0_, entries0_.CompetitionEventID as Competit2_10_0_, entries0_.CompetitionEventCategoryID as Competit3_10_0_, entries0_.PublicID as PublicID10_0_, entries0_1_.Name as Name1_0_, entries0_1_.IsPrivate as IsPrivate1_0_ FROM t_competition_entries entries0_ inner join t_entities entries0_1_ on entries0_.CompetitionEntryID=entries0_1_.EntityID WHERE entries0_.CompetitionEventID=?
Debug level Hibernate log excerpt:
DEBUG
Login
FAQ
Search