NHibernate.Exceptions.GenericADOException: could not execute query

eraj2587 · December 18, 2017, 4:32pm

We are using

NSB.Core : 5.0.0.0
NSB.Host: 6.0.0.0
NHibernate : 4.0.0.4000
Transport : Sql Server

NSB throws below exception.
NHibernate.Exceptions.GenericADOException: could not execute query

Stack trace

[SQL: SELECT this_.Id as Id0_0_, this_.Originator as Originator0_0_, this_.OriginalMessageId as Original3_0_0_, this_.PaymentId as PaymentId4_0_ FROM nsb.PaymentSagaData this_ with (updlock, rowlock) WHERE this_.PaymentId = @p0] ---> System.Data.SqlClient.SqlException: Execution 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, 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.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
   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 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, IResultTransformer forcedResultTransformer)
   at NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies, IResultTransformer forcedResultTransformer)
   at NHibernate.Loader.Loader.DoList(ISessionImplementor session, QueryParameters queryParameters, IResultTransformer forcedResultTransformer)
   --- End of inner exception stack trace ---
   at NHibernate.Loader.Loader.DoList(ISessionImplementor session, QueryParameters queryParameters, IResultTransformer forcedResultTransformer)
   at NHibernate.Loader.Loader.ListIgnoreQueryCache(ISessionImplementor session, QueryParameters queryParameters)
   at NHibernate.Impl.SessionImpl.List(CriteriaImpl criteria, IList results)
   at NHibernate.Impl.CriteriaImpl.List(IList results)
   at NHibernate.Impl.CriteriaImpl.UniqueResult[T]()
   at NServiceBus.SagaPersisters.NHibernate.SagaPersister.<>c__DisplayClass4_0`1.<NServiceBus.Saga.ISagaPersister.Get>b__0(ISession x) in C:\BuildAgent\work\5135de308b2f3016\src\NServiceBus.NHibernate\SagaPersisters\SagaPersister.cs:line 59
   at NServiceBus.SagaPersisters.NHibernate.SagaPersister.NServiceBus.Saga.ISagaPersister.Get[T](String property, Object value) in C:\BuildAgent\work\5135de308b2f3016\src\NServiceBus.NHibernate\SagaPersisters\SagaPersister.cs:line 63
   at NServiceBus.Sagas.PropertySagaFinder`1.Find(IBuilder builder, SagaFinderDefinition finderDefinition, LogicalMessage message) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Sagas\PropertySagaFinder.cs:line 32
   at NServiceBus.SagaPersistenceBehavior.TryLoadSagaEntity(SagaMetadata metadata, LogicalMessage message) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Sagas\SagaPersistenceBehavior.cs:line 248
   at NServiceBus.SagaPersistenceBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Sagas\SagaPersistenceBehavior.cs:line 48
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.SetCurrentMessageBeingHandledBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Behaviors\SetCurrentMessageBeingHandledBehavior.cs:line 17
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.LoadHandlersBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Behaviors\LoadHandlersBehavior.cs:line 45
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.Transports.SQLServer.ReadIncomingCallbackAddressBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\888dd942b44bad5a\src\NServiceBus.SqlServer\ReadIncomingCallbackAddressBehavior.cs:line 18
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.InvokeSagaNotFoundBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Behaviors\InvokeSagaNotFoundBehavior.cs:line 17
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.ExecuteLogicalMessagesBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Messages\ExecuteLogicalMessagesBehavior.cs:line 24
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.Persistence.NHibernate.OpenSessionBehavior.InnerInvoke(BehaviorContext context, Action next, Func`1 connectionRetriever) in C:\BuildAgent\work\5135de308b2f3016\src\NServiceBus.NHibernate\SharedSession\OpenSessionBehavior.cs:line 83
   at NServiceBus.Persistence.NHibernate.OpenSessionBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\5135de308b2f3016\src\NServiceBus.NHibernate\SharedSession\OpenSessionBehavior.cs:line 58
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.UnitOfWorkBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\UnitOfWork\UnitOfWorkBehavior.cs:line 42
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.Persistence.NHibernate.OpenSqlConnectionBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\5135de308b2f3016\src\NServiceBus.NHibernate\SharedSession\OpenSqlConnectionBehavior.cs:line 43
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.ChildContainerBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Behaviors\ChildContainerBehavior.cs:line 17
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.ProcessingStatisticsBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Monitoring\ProcessingStatisticsBehavior.cs:line 23
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.<>c__DisplayClass4_0.<InvokeNext>b__0() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 95
   at NServiceBus.AuditBehavior.Invoke(IncomingContext context, Action next) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Audit\AuditBehavior.cs:line 20
   at NServiceBus.BehaviorChain`1.InvokeNext(T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 107
   at NServiceBus.BehaviorChain`1.Invoke() in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\BehaviorChain.cs:line 52
   at NServiceBus.Pipeline.PipelineExecutor.Execute[T](BehaviorChain`1 pipelineAction, T context) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Pipeline\PipelineExecutor.cs:line 129
   at NServiceBus.Unicast.Transport.TransportReceiver.OnTransportMessageReceived(TransportMessage msg) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 413
   at NServiceBus.Unicast.Transport.TransportReceiver.ProcessMessage(TransportMessage message) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 344
   at NServiceBus.Unicast.Transport.TransportReceiver.TryProcess(TransportMessage message) in C:\BuildAgent\work\3206e2123f54fce4\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 230
   at NServiceBus.Transports.SQLServer.AmbientTransactionReceiveStrategy.TryReceiveFrom(TableBasedQueue queue) in C:\BuildAgent\work\888dd942b44bad5a\src\NServiceBus.SqlServer\AmbientTransactionReceiveStrategy.cs:line 57

ramonsmits · December 18, 2017, 7:02pm

Hi Raj,

In the exception details the reason is listed:

System.Data.SqlClient.SqlException: Execution 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

Meaning the query took too long to execute. Maybe your database is too busy? Can you verify that you have an index on the column that is used to retrieve the saga? If not, add this index. Also verify that you have the [Unique] attribute set to the saga data property PaymentId that is used. This is really important when you are using NServiceBus 5 and sagas:

Message Correlation • NServiceBus • Particular Docs

Is this exception happening all the time? What was the log level of this error?

Regards,
Ramon

eraj2587 · December 18, 2017, 7:48pm

There are around 3K failed messages in service pulse with same error for 3 months. Log level I can not trace out. One more question, Do we have to put unique attribute on all the properties of saga? Currently we have unique attribute on paymentId. I have other properties as well (intentionally not shown in sql query). Do I need unique attribute for all of them? What if individual property value get repeated?

Thanks,
Raj

ramonsmits · December 20, 2017, 1:42pm

Hi Raj,

Ok, so this exception information is copied from ServicePulse and these are actual message failures. I wrongly assumed the exception information was copied from a log file.

The [Unique] attribute is only needed on the properties that you use to correlate sagas to messages. You state that the attribute is already present on PaymentId, could you verify on the SQL Server that this column indeed has an index? If it does not have an index then SQL Server needs to perform a table scan to retrieve the correct record. If it does not have an index then please add a Unique index on the PaymentId column.

Please share any updates.

ramonsmits · January 5, 2018, 2:15pm

Hi Raj,

Have you resolved your Timeout issue?

– Ramon

eraj2587 · January 19, 2018, 11:12am

Hi Ramonsmits,

It was resolved. Thanks.