SQL Timeout

Topics: Troubleshooting
Oct 29, 2013 at 1:05 PM
I'm getting the below error all the time. I'm running Orchard v.1.3.10.0.
Any ideas? Do I have to upgrade?

My site is great otherwise and I don't want to go through the painful process of upgrading if I can fix this issue some other way.

It's running on a shared hosting SQL Server. I've previously raised a ticket with my hosting provider and they've said that there's nothing wrong with the performance of SQL Server.
Obviously if there's an index missing then the query could still be so slow that it times out.
However the site is pretty small. Less than 50 pages.

2013-10-24 04:43:22,554 [238] NHibernate.Util.ADOExceptionReporter - Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
2013-10-24 04:43:22,570 [238] NHibernate.Util.ADOExceptionReporter - The wait operation timed out
2013-10-24 04:43:22,570 [238] NHibernate.Util.ADOExceptionReporter - Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
2013-10-24 04:43:22,570 [238] NHibernate.Util.ADOExceptionReporter - The wait operation timed out
2013-10-24 04:43:22,570 [238] Orchard.Tasks.BackgroundService - Error while processing background task
NHibernate.ADOException: could not execute query
[ SELECT this_.Id as Id26_0_, this_.TaskType as TaskType26_0_, this_.ScheduledUtc as Schedule3_26_0_, this_.ContentItemVersionRecord_id as ContentI4_26_0_ FROM tbsorchard_Scheduling_ScheduledTaskRecord this_ WHERE this_.ScheduledUtc <= ? ]
Positional parameters: #0>10/24/2013 8:43:02 AM
[SQL: SELECT this_.Id as Id26_0_, this_.TaskType as TaskType26_0_, this_.ScheduledUtc as Schedule3_26_0_, this_.ContentItemVersionRecord_id as ContentI4_26_0_ FROM tbsorchard_Scheduling_ScheduledTaskRecord this_ WHERE this_.ScheduledUtc <= ?] ---> System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception: The wait operation timed out
--- End of inner exception stack trace ---
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction)
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action
1 wrapCloseInAction)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
at System.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
at System.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
at System.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
at System.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte& value)
at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest)
at System.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
at System.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransaction(TransactionRequest transactionRequest, String name, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)
at System.Data.SqlClient.SqlDelegatedTransaction.Initialize()
at System.Transactions.TransactionStatePSPEOperation.PSPEInitialize(InternalTransaction tx, IPromotableSinglePhaseNotification promotableSinglePhaseNotification)
at System.Transactions.TransactionStateActive.EnlistPromotableSinglePhase(InternalTransaction tx, IPromotableSinglePhaseNotification promotableSinglePhaseNotification, Transaction atomicTransaction)
at System.Transactions.Transaction.EnlistPromotableSinglePhase(IPromotableSinglePhaseNotification promotableSinglePhaseNotification)
at System.Data.SqlClient.SqlInternalConnection.EnlistNonNull(Transaction tx)
at System.Data.SqlClient.SqlInternalConnection.Enlist(Transaction tx)
at System.Data.SqlClient.SqlInternalConnectionTds.Activate(Transaction transaction)
at System.Data.ProviderBase.DbConnectionInternal.ActivateConnection(Transaction transaction)
at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)
at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)
at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource
1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)
at System.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions)
at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource
1 retry)
at System.Data.SqlClient.SqlConnection.Open()
at NHibernate.Connection.DriverConnectionProvider.GetConnection()
at NHibernate.AdoNet.ConnectionManager.GetConnection()
at NHibernate.AdoNet.AbstractBatcher.Prepare(IDbCommand cmd)
at NHibernate.AdoNet.AbstractBatcher.ExecuteReader(IDbCommand cmd)
at NHibernate.Loader.Loader.GetResultSet(IDbCommand st, Boolean autoDiscoverTypes, Boolean callable, 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.DoList(ISessionImplementor session, QueryParameters queryParameters)
--- End of inner exception stack trace ---
at NHibernate.Loader.Loader.DoList(ISessionImplementor session, QueryParameters queryParameters)
at NHibernate.Loader.Loader.ListIgnoreQueryCache(ISessionImplementor session, QueryParameters queryParameters)
at NHibernate.Loader.Loader.List(ISessionImplementor session, QueryParameters queryParameters, ISet1 querySpaces, IType[] resultTypes)
at NHibernate.Impl.SessionImpl.List(CriteriaImpl criteria, IList results)
at NHibernate.Impl.CriteriaImpl.List(IList results)
at NHibernate.Impl.CriteriaImpl.List()
at NHibernate.Linq.CriteriaResultReader
1.<GetEnumerator>d__0.MoveNext()
at System.Collections.Generic.List1..ctor(IEnumerable1 collection)
at System.Linq.Enumerable.ToList[TSource](IEnumerable1 source)
at Orchard.Utility.Extensions.ReadOnlyCollectionExtensions.ToReadOnlyCollection[T](IEnumerable
1 enumerable)
at Orchard.Data.Repository1.Orchard.Data.IRepository<T>.Fetch(Expression1 predicate)
at Orchard.Core.Scheduling.Services.ScheduledTaskExecutor.Sweep() in c:\Users\sebros\My Projects\Orchard\src\Orchard.Web\Core\Scheduling\Services\ScheduledTaskExecutor.cs:line 36
at Orchard.Tasks.BackgroundService.Sweep()
Coordinator
Oct 30, 2013 at 7:36 AM
I'd say this stack trace is not where the real problem is. My guess would be that you have a bad module that is eating connections away. This is just the healthy part of the system not being able to get a free connection out of the pool.
Nov 5, 2013 at 1:12 PM
I'm not sure how to proceed. I've copied the database to my local machine and it runs fine. I can't reproduce the error locally.

I'm also getting this error. Why is there a deadlock on a read? Could it be the isolation level is wrong?

2013-11-04 05:22:44,327 [381] NHibernate.Util.ADOExceptionReporter - Transaction (Process ID 330) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
2013-11-04 05:22:44,342 [381] Orchard.Tasks.BackgroundService - Error while processing background task
NHibernate.ADOException: could not execute query
[ SELECT this_.Id as Id30_1_, this_.Title as Title30_1_, this_.Slug as Slug30_1_, this_.Path as Path30_1_, this_.ContentItemRecord_id as ContentI5_30_1_, contentite1_.Id as Id57_0_, contentite1_.Number as Number57_0_, contentite1_.Published as Published57_0_, contentite1_.Latest as Latest57_0_, contentite1_.Data as Data57_0_, contentite1_.ContentItemRecord_id as ContentI6_57_0_ FROM tbsorchard_Routable_RoutePartRecord this_ left outer join tbsorchard_Orchard_Framework_ContentItemVersionRecord contentite1_ on this_.Id=contentite1_.Id WHERE ((contentite1_.Published = @p0 and not (this_.Path = @p1)) and this_.Path is not null) ]
Positional parameters: #0>True #1>
[SQL: SELECT this_.Id as Id30_1_, this_.Title as Title30_1_, this_.Slug as Slug30_1_, this_.Path as Path30_1_, this_.ContentItemRecord_id as ContentI5_30_1_, contentite1_.Id as Id57_0_, contentite1_.Number as Number57_0_, contentite1_.Published as Published57_0_, contentite1_.Latest as Latest57_0_, contentite1_.Data as Data57_0_, contentite1_.ContentItemRecord_id as ContentI6_57_0_ FROM tbsorchard_Routable_RoutePartRecord this_ left outer join tbsorchard_Orchard_Framework_ContentItemVersionRecord contentite1_ on this_.Id=contentite1_.Id WHERE ((contentite1_.Published = @p0 and not (this_.Path = @p1)) and this_.Path is not null)] ---> System.Data.SqlClient.SqlException: Transaction (Process ID 330) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action1 wrapCloseInAction)
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action
1 wrapCloseInAction)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
at System.Data.SqlClient.SqlDataReader.TryHasMoreRows(Boolean& moreRows)
at System.Data.SqlClient.SqlDataReader.TryReadInternal(Boolean setTimeout, Boolean& more)
at System.Data.SqlClient.SqlDataReader.Read()
at NHibernate.Driver.NHybridDataReader.Read()
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.DoList(ISessionImplementor session, QueryParameters queryParameters)
--- End of inner exception stack trace ---
at NHibernate.Loader.Loader.DoList(ISessionImplementor session, QueryParameters queryParameters)
at NHibernate.Loader.Loader.ListIgnoreQueryCache(ISessionImplementor session, QueryParameters queryParameters)
at NHibernate.Loader.Loader.List(ISessionImplementor session, QueryParameters queryParameters, ISet1 querySpaces, IType[] resultTypes)
at NHibernate.Impl.SessionImpl.List(CriteriaImpl criteria, IList results)
at NHibernate.Impl.CriteriaImpl.List(IList results)
at NHibernate.Impl.CriteriaImpl.List()
at NHibernate.Linq.CriteriaResultReader
1.<GetEnumerator>d__0.MoveNext()
at System.Collections.Generic.List1..ctor(IEnumerable1 collection)
at System.Linq.Enumerable.ToList[TSource](IEnumerable1 source)
at Orchard.Utility.Extensions.ReadOnlyCollectionExtensions.ToReadOnlyCollection[T](IEnumerable
1 enumerable)
at Orchard.Data.Repository1.Orchard.Data.IRepository<T>.Fetch(Expression1 predicate)
at Orchard.Core.Routable.Services.RoutablePathConstraintUpdator.Refresh() in c:\Users\sebros\My Projects\Orchard\src\Orchard.Web\Core\Routable\Services\RoutablePathConstraintUpdator.cs:line 31
at Orchard.Core.Routable.Services.RoutablePathConstraintUpdator.Orchard.Tasks.IBackgroundTask.Sweep() in c:\Users\sebros\My Projects\Orchard\src\Orchard.Web\Core\Routable\Services\RoutablePathConstraintUpdator.cs:line 27
at Orchard.Tasks.BackgroundService.Sweep()
Coordinator
Nov 6, 2013 at 6:19 AM
Enable perf counters on sql connections to make sure that's the problem. Then you can try to find what keeps connections open by doing some SQL profiling.