2

Our production environment that uses NHibernate v3.1.0.4000 suddenly started giving this error when searching with full-text search:

[SqlException (0x80131904): Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.] System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection) +404 System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning() +412 System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj) +1363 System.Data.SqlClient.SqlDataReader.ConsumeMetaData() +59 System.Data.SqlClient.SqlDataReader.get_MetaData() +118 System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString) +6388257 System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async) +6389826 System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result) +538 System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method) +28 System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method) +256 System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior) +19 System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader() +23 NHibernate.AdoNet.AbstractBatcher.ExecuteReader(IDbCommand cmd) +845 NHibernate.Loader.Loader.GetResultSet(IDbCommand st, Boolean autoDiscoverTypes, Boolean callable, RowSelection selection, ISessionImplementor session) +580 NHibernate.Loader.Loader.DoQuery(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies) +275 NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(ISessionImplementor session, QueryParameters queryParameters, Boolean returnProxies) +205 NHibernate.Loader.Loader.DoList(ISessionImplementor session, QueryParameters queryParameters) +195

[GenericADOException: could not execute query [ SELECT count(distinct this_.IdDocument) as y0_ FROM Document.Document this_ inner join Document.DocumentCopy documentc1_ on this_.IdDocument=documentc1_.IdDocument WHERE ((@p0 = @p1 and contains(this_.Title, @p2)) and this_.IsDeleted = @p3) and (((@p4 = @p5 and documentc1_.CreationDate >= @p6) and documentc1_.CreationDate <= @p7) and (documentc1_.IdOwnedByGroup = @p8 or documentc1_.IdCreatedByGroup = @p9)) ] Positional parameters: #0>0 #1>0 #2>"ýÿýÿýÿýÿýÿýÿýÿýÿ*" #3>False #4>0 #5>0 #6>12/5/2015 12:00:00 ýÿýÿ #7>12/5/2016 11:59:00 ýÿýÿ #8>1 #9>1 [SQL: SELECT count(distinct this_.IdDocument) as y0_ FROM Document.Document this_ inner join Document.DocumentCopy documentc1_ on this_.IdDocument=documentc1_.IdDocument WHERE ((@p0 = @p1 and contains(this_.Title, @p2)) and this_.IsDeleted = @p3) and (((@p4 = @p5 and documentc1_.CreationDate >= @p6) and documentc1_.CreationDate <= @p7) and (documentc1_.IdOwnedByGroup = @p8 or documentc1_.IdCreatedByGroup = @p9))]] NHibernate.Loader.Loader.DoList(ISessionImplementor session, QueryParameters queryParameters) +637 NHibernate.Loader.Loader.ListIgnoreQueryCache(ISessionImplementor session, QueryParameters queryParameters) +23 NHibernate.Loader.Criteria.CriteriaLoader.List(ISessionImplementor session) +60 NHibernate.Impl.SessionImpl.List(CriteriaImpl criteria, IList results) +1025 NHibernate.Impl.CriteriaImpl.List(IList results) +63 NHibernate.Impl.CriteriaImpl.UniqueResult() +57 Domain.Repositories.DocumentRepository.Domain.Abstract.IDocumentRepository.GetAll(Criteria1 criteria, Int32& count, Dictionary2 openFieldCriteria) +272 ServicesImplementation.DocumentService.GetDocuments(Criteria1 criteria, Int32& count, String metadataSearchTerm) +510 Docman.Models.List.ListModel.GetDocuments(Int32& count) +102 ASP._Page_Views_List_Index_cshtml.Execute() in d:\wwwroot\inetpub\docman\Views\List\Index.cshtml:27 System.Web.WebPages.WebPageBase.ExecutePageHierarchy() +280 System.Web.Mvc.WebViewPage.ExecutePageHierarchy() +104 System.Web.WebPages.StartPage.ExecutePageHierarchy() +143 System.Web.WebPages.WebPageBase.ExecutePageHierarchy(WebPageContext pageContext, TextWriter writer, WebPageRenderingBase startPage) +157 System.Web.Mvc.ViewResultBase.ExecuteResult(ControllerContext context) +384 System.Web.Mvc.<>c__DisplayClass1c.<InvokeActionResultWithFilters>b__19() +33 System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilter(IResultFilter filter, ResultExecutingContext preContext, Func1 continuation) +826372 System.Web.Mvc.ControllerActionInvoker.InvokeActionResultWithFilters(ControllerContext controllerContext, IList`1 filters, ActionResult actionResult) +265 System.Web.Mvc.ControllerActionInvoker.InvokeAction(ControllerContext controllerContext, String actionName) +827248 System.Web.Mvc.Controller.ExecuteCore() +159 System.Web.Mvc.ControllerBase.Execute(RequestContext requestContext) +335 System.Web.Mvc.<>c__DisplayClassb.b__5() +62 System.Web.Mvc.Async.<>c__DisplayClass1.b__0() +20 System.Web.Mvc.<>c__DisplayClasse.b__d() +54 System.Web.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() +469 System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) +375

I have tried the above listed query on SSMS and it seemed running fine and fast.

A similar error is mentioned here: Nhibernate FieldNameLookup throws IndexOutOfRangeException, although my error message does not contain any IndexOutOfRangeException in it.

Can anyone tell me what could be the cause of this?

UPDATE:

More info :

We are using projections.

According to the error log, the error originates from some query that only returns a count and not many rows with many fields.

As I have said before, the same query (listed in the error log) runs fast and with no issues when I run it from SSMS. Yet, all queries made from the app that execute this SQL query seem to fail with the above error.

The code might not be clear to you since we use a custom wrapper for NH.

I think I am wrong on the order of exceptions and first the timeout happens and then the ADO.net reports the other error. So, I guess it is a timeout after all...

UPDATE 2:

After some extra research, it seems this is related to this issue and the query is indeed timing out, just not from SSMS:

Query times out when executed from web, but super-fast when executed from SSMS

Community
  • 1
  • 1
user2173353
  • 4,316
  • 4
  • 47
  • 79
  • The datails says is Timeout issue. – Najera May 12 '16 at 15:57
  • how much data are you bringing back? what does the code that is doing this look like? are you using projections? – Fran May 12 '16 at 18:33
  • @Najera If you look below that 1st exception, there is another exception that seems to be the inner exception. – user2173353 May 13 '16 at 07:11
  • @Najera But maybe you are right: first it must be the SQL exception and then the ADO one. :^) I wish people just wrote `Inner exception :\r\n` in their exception logging. It would make things much more obvious... – user2173353 May 13 '16 at 09:29
  • @Fran I have added some more details. I am thinking now that MAYBE this indeed is a timeout issue. I am a bit confused with the order of the two exceptions... – user2173353 May 13 '16 at 09:29

1 Answers1

-1

That turned out to be a timeout which could not be reproduced from SSMS because there it was using a different value for ARITHABORT (between my app session and the SSMS session).

Once I had set the default value for it to ON/1 for the DB, everything was fixed:

USE [master];
GO
ALTER DATABASE [{database_name}] SET ARITHABORT ON WITH NO_WAIT;
GO

See here: https://dba.stackexchange.com/a/95090/71232

Community
  • 1
  • 1
user2173353
  • 4,316
  • 4
  • 47
  • 79
  • Wrong, terribly wrong. You have just temporarily evict a bad query plan from your used query plan cache. The trouble will come back and bite you again some time later. The fact you have found [this answer](/a/2248566/1178314) was promising, but it looks like you have read it too fast. Your actual trouble is very probably an index trouble, causing SQL Server to sometime generates and put in cache a bad query plan. – Frédéric May 16 '16 at 21:47
  • @Frédéric However, MS suggests to have this setting to ON anyway (https://msdn.microsoft.com/en-us/library/ms190306.aspx). So, I don't think it's a bad thing to do what I did. Also, the query contains a full-text search query inside it and most of the full-text indexes are over 70% fragmented in the DB (that's what happens when you run a system with no DBA...). The same query, without the full-text search part was running fast, so I guess F.T.S. is what made the difference. Our non-full-text-search indexes MAY need adjustments, but I don't think they were the cause here. :) – user2173353 May 17 '16 at 07:33
  • Having it to `on` is not a bad thing, granted, but believing it actually fully solves the trouble you have encountered is likely to be a bad thing. See [here](/a/10175455/1178314). In all the cases I have encountered, the actual trouble was always an index trouble, not solely this `ARITHABORT` setting. – Frédéric May 17 '16 at 07:50
  • @Frédéric OK. I see. I will try to check the indexes as well. :) – user2173353 May 17 '16 at 09:16