Hi, I’ve been using NHibernate for a while now, and am having trouble with the command_timeout property.

It does not seem to be working at all.

My NHibernate properties are:
File Type: Assembly
Identity: NHibernate
Runtime Version: v2.0.50727
Version: 1.2.0.3001

This is being built and run using .NET Framework 2.0 in Visual Studio 2008.

My NHibernate config is as follows

<hibernate-configuration xmlns="urn:nhibernate-configuration-2.2">
<session-factory>
<property name="show_sql">true</property>
<property name="dialect">NHibernate.Dialect.MsSql2000Dialect</property>
<property name="connection.provider">NHibernate.Connection.DriverConnectionProvider</property>
<property name="connection.driver_class">NHibernate.Driver.SqlClientDriver</property>
<property name="connection.connection_string">Initial Catalog=MYCATALOG;Password=MYPASSWORD;Persist Security Info=True;User ID=USERID;Data Source=192.168.0.32,2433;</property>
<property name="connection.release_mode">on_close</property>
<property name="command_timeout">340</property>
<mapping assembly="TheGuide.Business" />
</session-factory>
</hibernate-configuration>

However, when i bypass NHibernate, I get no problems.


Database db = DatabaseFactory.CreateDatabase("TheConnectionString");
DbConnection connection = db.CreateConnection();

connection.Open();

DbCommand cmd = db.GetStoredProcCommand("procDoStuff");
db.AddInParameter(cmd, "@param1", DbType.Int32, 0);
db.AddInParameter(cmd, "@param2", DbType.Int32, 1);
cmd.CommandTimeout = 600; //10 minutes is heaps.
db.ExecuteNonQuery(cmd);

connection.Close();



If anyone could help with this problem it would be appreciated.

Thank you.

Perhaps the following debug will help.


As you can see by the line
2008-07-02 12:48:06 [13] DEBUG TheGuide.BatchProcessor.PublishAll - Time taken to run Standard SQL: 00:00:50.98
it takes about 50 seconds to run the stored procedure.

Then, I notice that when the NHibernate is configured, the command timeout is set
2008-07-02 12:48:06 [13] INFO NHibernate.Driver.DriverBase - setting ADO.NET command timeout to 340 seconds

Then, the query starts
2008-07-02 12:48:06 [13] INFO NHibernate.Impl.SessionFactoryObjectFactory - no name configured
and about 34 seconds later:
2008-07-02 12:48:40 [13] ERROR TheGuide.BatchProcessor.PublishAll - System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
In this case, the extra 4 seconds are me steping through with the debugger.

but in any case, NHibernate states that the command_timeout is set to 340 seconds, yet it is timing out after about 30 seconds.

Thankyou.



Complete Log File

2008-07-02 12:47:05 [10] INFO TheGuide.BatchProcessor.Program - started
2008-07-02 12:47:05 [10] DEBUG TheGuide.BatchProcessor.Program - Application will now run the following processes
PublishAll
2008-07-02 12:47:15 [13] DEBUG TheGuide.BatchProcessor.PublishAll - started
2008-07-02 12:48:06 [13] DEBUG TheGuide.BatchProcessor.PublishAll - Time taken to run Standard SQL: 00:00:50.98
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Environment - NHibernate 1.2.0.3001 (1.2.0.3001)
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Environment - nhibernate section not found in application configuration file
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Environment - Bytecode provider name : lcg
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Environment - Using reflection optimizer
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Configuration - Searching for mapped documents in assembly: TheGuide.Business
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Configuration - Found mapping document in assembly: TheGuide.Business.TheGuide.hbm.xml
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Configuration - Mapping resource: TheGuide.Business.TheGuide.hbm.xml
2008-07-02 12:48:06 [13] INFO NHibernate.Dialect.Dialect - Using dialect: NHibernate.Dialect.MsSql2000Dialect
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.Account -> Account
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.AccountContact -> AccountContact
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.Member -> Member
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.Address -> Address
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.AccountFeature -> AccountFeature
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.AccountServingTime -> AccountServingTime
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.AccountContent -> AccountContent
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.AccountImage -> AccountImage
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.AccountFunctionService -> AccountFunctionService
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.Advertisement -> Advertisement
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.AccountVoucher -> AccountVoucher
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.MemberVoucher -> MemberVoucher
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.Tracking -> Tracking
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.CompetitionEntry -> CompetitionEntry
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.TabSection -> TabSection
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.AccountRating -> AccountRating
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.Competition -> Competition
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.MyPoints -> MyPoints
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.FunctionRoom -> FunctionRoom
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.Config -> Config
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.ProductCategory -> ProductCategory
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.ProductFeature -> ProductFeature
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.ProductRegion -> ProductRegion
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.ActivityTime -> ActivityTime
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.Product -> Product
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Configuration - Found mapping document in assembly: TheGuide.Business.TheGuideLookup.hbm.xml
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Configuration - Mapping resource: TheGuide.Business.TheGuideLookup.hbm.xml
2008-07-02 12:48:06 [13] INFO NHibernate.Dialect.Dialect - Using dialect: NHibernate.Dialect.MsSql2000Dialect
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.Lookup -> Lookup
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.LookupType -> LookupType
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.ServingTimeLookup -> ServingTimeLookup
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.StateLookup -> StateLookup
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.RegionLookup -> RegionLookup
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.HbmBinder - Mapping class: TheGuide.Business.AccountTypeLookup -> AccountTypeLookup
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Configuration - processing one-to-many association mappings
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Configuration - processing one-to-one association property references
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.Configuration - processing foreign key constraints
2008-07-02 12:48:06 [13] INFO NHibernate.Dialect.Dialect - Using dialect: NHibernate.Dialect.MsSql2000Dialect
2008-07-02 12:48:06 [13] INFO NHibernate.Connection.ConnectionProviderFactory - Initializing connection provider: NHibernate.Connection.DriverConnectionProvider
2008-07-02 12:48:06 [13] INFO NHibernate.Connection.ConnectionProvider - Configuring ConnectionProvider
2008-07-02 12:48:06 [13] INFO NHibernate.Driver.DriverBase - setting ADO.NET command timeout to 340 seconds
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.SettingsFactory - Optimize cache for minimal puts: False
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.SettingsFactory - Connection release mode: on_close
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.SettingsFactory - echoing all SQL to stdout
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.SettingsFactory - Query translator: NHibernate.Hql.Classic.ClassicQueryTranslatorFactory
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.SettingsFactory - Query language substitutions: {}
2008-07-02 12:48:06 [13] INFO NHibernate.Cfg.SettingsFactory - cache provider: NHibernate.Cache.NoCacheProvider, NHibernate, Version=1.2.0.3001, Culture=neutral, PublicKeyToken=aa95f207798dfdb4
2008-07-02 12:48:06 [13] INFO NHibernate.Impl.SessionFactoryImpl - building session factory
2008-07-02 12:48:06 [13] INFO NHibernate.Impl.SessionFactoryObjectFactory - no name configured
2008-07-02 12:48:40 [13] ERROR TheGuide.BatchProcessor.PublishAll - 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.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
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.ExecuteScalar()
at TheGuide.Business.Service.EntityService`1.ExecuteScalar[S](String sql, CommandType commandType, SqlParameter[] parameters) in C:\src\theguide\trunk\TheGuide.Business.Service\EntityService.cs:line 173
at TheGuide.Business.Service.AccountService.PublishAll() in C:\src\theguide\trunk\TheGuide.Business.Service\AccountService.cs:line 151
at TheGuide.BatchProcessor.PublishAll.RunNHibernateVersion() in C:\src\theguide\trunk\TheGuide.BatchProcessor\PublishAll.cs:line 66
at TheGuide.BatchProcessor.PublishAll.Run() in C:\src\theguide\trunk\TheGuide.BatchProcessor\PublishAll.cs:line 31
2008-07-02 12:48:40 [13] DEBUG TheGuide.BatchProcessor.PublishAll - finished
2008-07-02 12:48:40 [13] INFO TheGuide.BatchProcessor.PublishAll - Total Time Taken: 00:01:35.29
2008-07-02 12:48:42 [10] DEBUG TheGuide.BatchProcessor.Program - finished
2008-07-02 12:48:42 [10] INFO TheGuide.BatchProcessor.Program - Total Time Taken: 00:01:35.31

As per usual, look at the problem for days, finaly post something, and then solve the problem.

I am maintaining some code that was written by another firm.

A command object was obtained in the following way:

conn = this.Session.Connection;
cmd = conn.CreateCommand();
cmd.CommandText = sql;

This did not set the Command Timeout within the command.

I used the following

cmd = this.Session.SessionFactory.ConnectionProvider.Driver.GenerateCommand(commandType, new NHibernate.SqlCommand.SqlString(sql), nParameters);
conn = this.Session.Connection;
cmd.Connection = conn;

That seemed to do the trick as the command now contains the timeout from the config setting.

It now seems to boil down to RTFM from here.

Thank you.