OrchardCMS / Orchard

Orchard is a free, open source, community-focused Content Management System built on the ASP.NET MVC platform.
https://orchardproject.net
BSD 3-Clause "New" or "Revised" License
2.37k stars 1.12k forks source link

Nhibernate error messages in Azure SQL Managed Instance and on prem SQL server #8778

Open andrewmadueke opened 3 months ago

andrewmadueke commented 3 months ago

Has anyone encountered similar issues? The exception below just started popping up out of nowhere after many years of using Orchard. The site gets locked and no one is able to navigate for periods of time. Would it help to upgrade Nhibernate to a newer version? Should I also look at upgrading orchard Framework to version 1.10.3? Moving to Orchard Core is out of question for now due to budget.

Current Orchard Framework Version: 1.10.2 Current Nhibernate version: 4.0.4.4000

Exception NHibernate.Exceptions.GenericADOException: could not execute batch command.[SQL: SQL not available] ---> System.Data.SqlClient.SqlException: Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.  Operation cancelled by user.  The statement has been terminated. ---> 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.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)     
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.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)     
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()     
at System.Data.SqlClient.SqlCommandSet.ExecuteNonQuery()     
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps)     --- End of inner exception stack trace ---     
at NHibernate.AdoNet.SqlClientBatchingBatcher.DoExecuteBatch(IDbCommand ps)     
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatchWithTiming(IDbCommand ps)     
at NHibernate.AdoNet.AbstractBatcher.ExecuteBatch()     
at NHibernate.Engine.ActionQueue.ExecuteActions()     
at NHibernate.Event.Default.AbstractFlushingEventListener.PerformExecutions(IEventSource session)     
at NHibernate.Event.Default.DefaultAutoFlushEventListener.OnAutoFlush(AutoFlushEvent event)     
at NHibernate.Impl.SessionImpl.AutoFlushIfRequired(ISet`1 querySpaces)     
at NHibernate.Impl.SessionImpl.List(CriteriaImpl criteria, IList results)     
at NHibernate.Impl.CriteriaImpl.List(IList results)     
at NHibernate.Impl.CriteriaImpl.List[T]()     
at Orchard.ContentManagement.DefaultContentQuery.Slice(Int32 skip, Int32 count)     
at Orchard.ContentManagement.DefaultContentQuery.ContentQuery`1.Orchard.ContentManagement.IContentQuery<T>.List()     
at Orchard.Widgets.Services.DefaultLayerEvaluationService.PopulateActiveLayers() in D:\a\1\s\GMS_Portal\Workforce\KLP_Branch_GMS_Portal\src\Modules\Orchard.Widgets\Services\DefaultLayerEvaluationService.cs:line 45     
at Orchard.ContentManagement.Utilities.LazyField`1.GetValue()     
at Orchard.ContentManagement.Utilities.LazyField`1.get_Value()     
at Orchard.Widgets.Services.DefaultLayerEvaluationService.GetActiveLayerIds() in D:\a\1\s\GMS_Portal\Workforce\KLP_Branch_GMS_Portal\src\Modules\Orchard.Widgets\Services\DefaultLayerEvaluationService.cs:line 38     
at Orchard.Widgets.Filters.WidgetFilter.OnResultExecuting(ResultExecutingContext filterContext) in D:\a\1\s\GMS_Portal\Workforce\KLP_Branch_GMS_Portal\src\Modules\Orchard.Widgets\Filters\WidgetFilter.cs:line 52     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)     
at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultWithFilters(ControllerContext controllerContext, IList`1 filters, ActionResult actionResult)     
at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass3_1.<BeginInvokeAction>b__1(IAsyncResult asyncResult) has been thrown in controller Tax.Core.Framework.Controllers.HomeController redirecting user to '~/Login/ApplicationError'
damongroenveld commented 3 months ago

We are using azure sql without an issue. Some things to note:1. Depending on setup sql connections that are idle may timeout (we only use repositories within I singleton using work<> to overcome this - can be configured to use azure sql direct rather than through a gateway - it’s the gateway that times out the session)2. There is a mandatory request timeout at something like 15mins on http requests to the app service

Regards, Damon GroenveldOn

andrewmadueke commented 3 months ago

Let me also mention that we're not using the Orchard.sdf. We're reading the orchard settings from databases in a Sql Managed Instance and Sql Server on Prem. Thanks

sebastienros commented 2 months ago

There was a perf improvement in 1.10.3 for the query that is the issue in your logs, due to a SELECT n+1 problem, which could explain why it's timing out. You could try to apply this fix or move to 1.10.3.

The dev branch (1.11) also added some caching on top of this improvement, which is something you could also try, and would probably help a lot.

Check the DefaultLayerEvaluationService.PopulateActiveLayers in both 1.10.3 tags and dev branch to see these two improvements.

andrewmadueke commented 2 months ago

I'll look into this Sebastien. Thanks for the quick reply.