The wait operation timed out - ERROR

Vote:
 

Hi Everyone,
I'm in the process of upgrading from Episerver Commerce 9, to 11. I've made a lot of progress with this upgrade. The CMS admin and homepage loads, but when I go to view any categories, or products in either the admin or the front end, the API appears to time out.

My first thought was my connection strings, but I've double/triple checked my connection strings and I see no cause to this. My credentials all work well.  

Here is the error I'm getting specifically...

Server Error in '/' Application.

The wait operation timed out

Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code. 

Exception Details: System.ComponentModel.Win32Exception: The wait operation timed out

Source Error: 

Line 261:                // On tier one categories, the left hand nav shows children tier two categories
Line 262:                PrimaryCategoryList = new List();
Line 263:                foreach (CategoryContentType item in contentLoader.GetChildren(CurrentCategory.ContentLink).ToList())
Line 264:                {
Line 265:                    PrimaryCategoryList.Add(FallbackLanguages.GetCategory(item.ContentLink, currentCulture));


Source File: C:\eo-sites\Projects\Episerver\cms.www\Models\ViewModels\Commerce\NonFacetedNavModel.cs    Line: 263 

Stack Trace: 

[Win32Exception (0x80004005): The wait operation timed out]

[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, Action`1 wrapCloseInAction) +2442234
   System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction) +5737028
   System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) +628
   System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) +3731
   System.Data.SqlClient.SqlDataReader.TryConsumeMetaData() +58
   System.Data.SqlClient.SqlDataReader.get_MetaData() +89
   System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString) +379
   System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, SqlDataReader ds, Boolean describeParameterEncryptionRequest) +2026
   System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite) +375
   System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method) +53
   System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method) +240
   System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior) +41
   System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader(CommandBehavior behavior) +12
   System.Data.Common.DbDataAdapter.FillInternal(DataSet dataset, DataTable[] datatables, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior) +139
   System.Data.Common.DbDataAdapter.Fill(DataSet dataSet, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior) +136
   System.Data.Common.DbDataAdapter.Fill(DataSet dataSet) +88
   Mediachase.Data.Provider.<>c__DisplayClass17_2.b__0() +92
   EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute(Func`1 method) +591
   Mediachase.Data.Provider.SqlDataProvider.WithRetry(Func`1 action) +32
   Mediachase.Data.Provider.SqlDataProvider.LoadDataSet(DataCommand command) +527

[Exception: Exception in CatalogContentProperty_LoadBatch: ]
   Mediachase.Data.Provider.SqlDataProvider.LoadDataSet(DataCommand command) +963
   Mediachase.MetaDataPlus.Common.DBHelper.ExecuteDataSet(String connectionString, CommandType commandType, String commandText, DataParameter[] commandParameters) +156
   Mediachase.MetaDataPlus.Configurator.MetaObjectDB.LoadBatchOfMetaObjectData(MetaDataContext context, CatalogMetaObjectLoadSet loadSet) +159
   Mediachase.MetaDataPlus.Internal.d__13.MoveNext() +294
   System.Collections.Generic.List`1..ctor(IEnumerable`1 collection) +381
   System.Linq.Enumerable.ToList(IEnumerable`1 source) +58
   Mediachase.MetaDataPlus.Internal.d__10.MoveNext() +685
   System.Linq.Enumerable.ToDictionary(IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer) +157
   EPiServer.Commerce.Catalog.Provider.Construction.MetaDataContentBuilder.GetMetaObjects(IDictionary`2 metaObjectIdsByClassId, String language) +333
   EPiServer.Commerce.Catalog.Provider.Construction.NodeBuilder.GetMetaObjects(IEnumerable`1 nodeRows, String language) +318
   EPiServer.Commerce.Catalog.Provider.Construction.NodeBuilder.ConstructNodes(CatalogNodeDto nodeDto, IDictionary`2 versionForUnpublishedContent, String language) +502
   EPiServer.Commerce.Catalog.Provider.Construction.NodeBuilder.Create(IList`1 contentLinks, String language) +604
   EPiServer.Commerce.Catalog.Provider.<>c__DisplayClass10_0.b__0(ICatalogContentBuilder builder, IList`1 links) +16
   EPiServer.Commerce.Catalog.Provider.CatalogContentLoader.ConstructContent(IList`1 contentLinks, Func`3 createContentFunc) +339
   EPiServer.Commerce.Catalog.Provider.CatalogContentLoader.LoadSpecificContentInstances(IList`1 contentLinks, String language) +453
   EPiServer.Commerce.Catalog.Provider.<>c__DisplayClass29_0.b__0(IList`1 refs) +44
   EPiServer.Commerce.Catalog.Provider.CatalogContentProvider.BatchLoad(IList`1 contentLinks, Func`2 dbLoader) +141
   EPiServer.Commerce.Catalog.Provider.CatalogContentProvider.LoadContents(IList`1 contentReferences, ILanguageSelector selector) +425
   EPiServer.Core.ContentProvider.GetContentBatch(IList`1 batch, ILanguageSelector selector, List`1& contents, Dictionary`2& contentMap) +85
   EPiServer.Core.ContentProvider.GetScatteredContents(IEnumerable`1 contentLinks, ILanguageSelector selector) +732
   EPiServer.Core.ContentProvider.LoadBatched(IList`1 contentReferences, ILanguageSelector selector) +61
   EPiServer.Core.Internal.ProviderPipelineImplementation.GetItems(ContentProvider provider, IList`1 contentLinks, LoaderOptions loaderOptions) +225
   EPiServer.Core.Internal.DefaultContentLoader.GetChildren(ContentReference contentLink, LoaderOptions loaderOptions, Int32 startIndex, Int32 maxRows) +1169
   EPiServer.Core.Internal.DefaultContentLoader.GetChildren(ContentReference contentLink, LoaderOptions loaderOptions) +67
   EPiServer.Core.Internal.DefaultContentLoader.GetChildren(ContentReference contentLink) +69
   CMS.Models.ViewModels.Commerce.NonFacetedNavModel..ctor(CategoryContentType category) in C:\eo-sites\Projects\Episerver\cms.www\Models\ViewModels\Commerce\NonFacetedNavModel.cs:263
   ASP._Page_Views_Commerce_Product_Category_Index_cshtml.Execute() in c:\eo-sites\Projects\Episerver\cms.www\Views\Commerce\Product\Category\Index.cshtml:47
   System.Web.WebPages.WebPageBase.ExecutePageHierarchy() +197
   System.Web.Mvc.WebViewPage.ExecutePageHierarchy() +105
   System.Web.WebPages.StartPage.RunPage() +17
   System.Web.WebPages.StartPage.ExecutePageHierarchy() +64
   System.Web.WebPages.WebPageBase.ExecutePageHierarchy(WebPageContext pageContext, TextWriter writer, WebPageRenderingBase startPage) +78
   System.Web.Mvc.RazorView.RenderView(ViewContext viewContext, TextWriter writer, Object instance) +256
   System.Web.Mvc.BuildManagerCompiledView.Render(ViewContext viewContext, TextWriter writer) +107
   System.Web.Mvc.ViewResultBase.ExecuteResult(ControllerContext context) +291
   System.Web.Mvc.ControllerActionInvoker.InvokeActionResult(ControllerContext controllerContext, ActionResult actionResult) +13
   System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult) +56
   System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult) +420
   System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult) +420
   System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult) +420
   System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult) +420
   System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult) +420
   System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult) +420
   System.Web.Mvc.ControllerActionInvoker.InvokeActionResultWithFilters(ControllerContext controllerContext, IList`1 filters, ActionResult actionResult) +52
   System.Web.Mvc.Async.<>c__DisplayClass2b.b__1c() +173
   System.Web.Mvc.Async.<>c__DisplayClass21.b__1e(IAsyncResult asyncResult) +100
   System.Web.Mvc.Async.WrappedAsyncResult`1.CallEndDelegate(IAsyncResult asyncResult) +10
   System.Web.Mvc.Async.WrappedAsyncResultBase`1.End() +49
   System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeAction(IAsyncResult asyncResult) +27
   System.Web.Mvc.Controller.b__1d(IAsyncResult asyncResult, ExecuteCoreState innerState) +13
   System.Web.Mvc.Async.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult) +29
   System.Web.Mvc.Async.WrappedAsyncResultBase`1.End() +49
   System.Web.Mvc.Controller.EndExecuteCore(IAsyncResult asyncResult) +36
   System.Web.Mvc.Controller.b__15(IAsyncResult asyncResult, Controller controller) +12
   System.Web.Mvc.Async.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult) +22
   System.Web.Mvc.Async.WrappedAsyncResultBase`1.End() +49
   System.Web.Mvc.Controller.EndExecute(IAsyncResult asyncResult) +26
   System.Web.Mvc.Controller.System.Web.Mvc.Async.IAsyncController.EndExecute(IAsyncResult asyncResult) +10
   System.Web.Mvc.MvcHandler.b__5(IAsyncResult asyncResult, ProcessRequestState innerState) +21
   System.Web.Mvc.Async.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult) +29
   System.Web.Mvc.Async.WrappedAsyncResultBase`1.End() +49
   System.Web.Mvc.MvcHandler.EndProcessRequest(IAsyncResult asyncResult) +28
   System.Web.Mvc.MvcHandler.System.Web.IHttpAsyncHandler.EndProcessRequest(IAsyncResult result) +9
   System.Web.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() +9744373
   System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) +155


Version Information: Microsoft .NET Framework Version:4.0.30319; ASP.NET Version:4.6.1073.0

#181087
Aug 08, 2017 15:09
Vote:
 

In this case I would suggest you to contact Episerver support services and file a support case. I'd say this is related to your database and/or catalog structure

#181094
Aug 08, 2017 17:33
Vote:
 

I've been spinning my wheels for this for awhile, and Episerver Expert services isn't an option. Our current production website uses the same exact catalog. I just re-pulled down the commercemanager database from production to dev and reupgraded the sql. I'm still having this issue. Any ideas where you would start with this issue?

-Paul

#181250
Aug 14, 2017 22:21
Vote:
 

Let me ask you something, is it possible that the new versions of Commerce aren't compatable with a catalog of our size? We've got 33,000 products.

This issue appears to occur when calling the function CatalogContentProperty_LoadBatch. Looking at the CatalogContentProperties table, we've got 1.5 million records. Could this be causing the issue here? I pulled in the quicksilver commerce demo and it worked for me.

-Paul

#181251
Aug 14, 2017 22:48
Vote:
 

Worth noting, I'm connecting to a database on my dev environment that went through the sql upgrade, but the data is exactly the same. This data works on production, but no dev.

#181252
Aug 14, 2017 22:52
Vote:
 

Try setting the commandTimeout higher to see if it alleviates the problem for now.

<dataService defaultProvider="SqlDataProvider">
      <providers>
        <add name="SqlDataProvider" type="Mediachase.Data.Provider.SqlDataProvider, Mediachase.SqlDataProvider" connectionStringName="EcfSqlConnection" applicationName="ECApplication" commandTimeout="120" />
      </providers>
    </dataService>
#181253
Aug 14, 2017 23:30
Vote:
 

33k products and 1.5M rows in CatalogProperty are not something particular big, and they are in well supported size of catalog.

However your dev machine might be less powerful than your production server, which makes SQL Server takes longer time to process the request.

As I said, it'd be best if we get a hand on your database. Or you can use SQL Profiler to see which parameters cause timeout on that SP, and try to get an execution plan on that. 

#181258
Aug 15, 2017 7:24
Vote:
 

Hey Guys,
Thanks for your help with this issue. I put that line into the web.config and it didn't fix the issue. I repulled out production database to our dev enviornment and reran the migration scripts and still no go.

#181289
Aug 15, 2017 22:26
Vote:
 

So I've been looking into this issue for awhile now and I've narrowed it down to a single stored procedure. That procedure takes FOREVER to run.

When I run the following query it takes a long time.

declare @p1 dbo.udttCatalogContentPropertyReference
insert into @p1 values(602,1,44,N'en')
insert into @p1 values(604,1,44,N'en')
insert into @p1 values(605,1,44,N'en')
insert into @p1 values(606,1,44,N'en')
insert into @p1 values(625,1,44,N'en')
insert into @p1 values(626,1,44,N'en')
insert into @p1 values(698,1,44,N'en')
insert into @p1 values(786,1,44,N'en')
insert into @p1 values(787,1,44,N'en')
insert into @p1 values(788,1,44,N'en')
insert into @p1 values(1000,1,44,N'en')
insert into @p1 values(1012,1,44,N'en')
insert into @p1 values(1099,1,44,N'en')
insert into @p1 values(1104,1,44,N'en')

exec CatalogContentProperty_LoadBatch @PropertyReferences=@p1
go

#181291
Aug 15, 2017 22:29
Vote:
 

This is what my CatalogContentProperty Stored proc looks like.

CREATE PROCEDURE [dbo].[CatalogContentProperty_LoadBatch]
	@PropertyReferences [udttCatalogContentPropertyReference] READONLY
AS
BEGIN
	
	IF dbo.mdpfn_sys_IsAzureCompatible() = 0  --Fields will be encrypted only when DB does not support Azure
		BEGIN
		EXEC mdpsp_sys_OpenSymmetricKey
		
		;WITH CTE1 AS (
			SELECT R.*, E.CatalogId
			FROM @PropertyReferences R
			INNER JOIN CatalogEntry E ON E.CatalogEntryId = R.ObjectId AND R.ObjectTypeId = 0
		UNION ALL
			SELECT R.*, N.CatalogId
			FROM @PropertyReferences R
			INNER JOIN CatalogNode N ON N.CatalogNodeId = R.ObjectId AND R.ObjectTypeId = 1
		),
		CTE2 AS (
			SELECT CTE1.ObjectId, CTE1.ObjectTypeId, CTE1.MetaClassId, ISNULL(L.LanguageCode, C.DefaultLanguage) AS LanguageName, C.DefaultLanguage
			FROM CTE1
			INNER JOIN [Catalog] C ON C.CatalogId = CTE1.CatalogId
			LEFT OUTER JOIN CatalogLanguage L ON L.CatalogId = CTE1.CatalogId AND L.LanguageCode = CTE1.LanguageName
		)
		-- Select CatalogContentProperty data
		SELECT P.ObjectId, P.ObjectTypeId, P.MetaFieldId, P.MetaClassId, P.MetaFieldName, P.LanguageName,
							P.Boolean, P.Number, P.FloatNumber, P.[Money], P.[Decimal], P.[Date], P.[Binary], P.[String], 
							CASE WHEN (F.IsEncrypted = 1 AND dbo.mdpfn_sys_IsLongStringMetaField(F.DataTypeId) = 1) 
								THEN dbo.mdpfn_sys_EncryptDecryptString(P.LongString, 0) 
								ELSE P.LongString END 
							AS LongString,
							P.[Guid]  
		FROM dbo.CatalogContentProperty P
		INNER JOIN MetaField F ON P.MetaFieldId = F.MetaFieldId
		INNER JOIN CTE2 ON
			P.ObjectId = CTE2.ObjectId AND
			P.ObjectTypeId = CTE2.ObjectTypeId AND
			P.MetaClassId = CTE2.MetaClassId AND
			((F.MultiLanguageValue = 1 AND P.LanguageName = CTE2.LanguageName COLLATE DATABASE_DEFAULT) OR ((F.MultiLanguageValue = 0 AND P.LanguageName = CTE2.DefaultLanguage COLLATE DATABASE_DEFAULT)))
		EXEC mdpsp_sys_CloseSymmetricKey
		END
	ELSE
		BEGIN
		
		;WITH CTE1 AS (
			SELECT R.*, E.CatalogId
			FROM @PropertyReferences R
			INNER JOIN CatalogEntry E ON E.CatalogEntryId = R.ObjectId AND R.ObjectTypeId = 0
		UNION ALL
			SELECT R.*, N.CatalogId
			FROM @PropertyReferences R
			INNER JOIN CatalogNode N ON N.CatalogNodeId = R.ObjectId AND R.ObjectTypeId = 1
		),
		CTE2 AS (
			SELECT CTE1.ObjectId, CTE1.ObjectTypeId, CTE1.MetaClassId, ISNULL(L.LanguageCode, C.DefaultLanguage) AS LanguageName, C.DefaultLanguage
			FROM CTE1
			INNER JOIN [Catalog] C ON C.CatalogId = CTE1.CatalogId
			LEFT OUTER JOIN CatalogLanguage L ON L.CatalogId = CTE1.CatalogId AND L.LanguageCode = CTE1.LanguageName
		)	
		SELECT P.ObjectId, P.ObjectTypeId, P.MetaFieldId, P.MetaClassId, P.MetaFieldName, P.LanguageName,
							P.Boolean, P.Number, P.FloatNumber, P.[Money], P.[Decimal], P.[Date], P.[Binary], P.[String], P.LongString LongString,
							P.[Guid]  
		FROM dbo.CatalogContentProperty P
		INNER JOIN MetaField F ON P.MetaFieldId = F.MetaFieldId
		INNER JOIN CTE2 ON
			P.ObjectId = CTE2.ObjectId AND
			P.ObjectTypeId = CTE2.ObjectTypeId AND
			P.MetaClassId = CTE2.MetaClassId AND
			((F.MultiLanguageValue = 1 AND P.LanguageName = CTE2.LanguageName COLLATE DATABASE_DEFAULT) OR ((F.MultiLanguageValue = 0 AND P.LanguageName = CTE2.DefaultLanguage COLLATE DATABASE_DEFAULT)))
		END
	-- Select CatalogContentEx data
	SELECT *
	FROM dbo.CatalogContentEx Ex 
	INNER JOIN @PropertyReferences R ON Ex.ObjectId = R.ObjectId AND Ex.ObjectTypeId = R.ObjectTypeId
END


GO


#181292
Aug 15, 2017 22:31
Vote:
 

The crazy thing about this, is that when I run the query SQL contents straight from the stored procedure it's fast!

declare @PropertyReferences dbo.udttCatalogContentPropertyReference
insert into @PropertyReferences values(602,1,44,N'en')
insert into @PropertyReferences values(604,1,44,N'en')
insert into @PropertyReferences values(605,1,44,N'en')
insert into @PropertyReferences values(606,1,44,N'en')
insert into @PropertyReferences values(625,1,44,N'en')
insert into @PropertyReferences values(626,1,44,N'en')
insert into @PropertyReferences values(698,1,44,N'en')
insert into @PropertyReferences values(786,1,44,N'en')
insert into @PropertyReferences values(787,1,44,N'en')
insert into @PropertyReferences values(788,1,44,N'en')
insert into @PropertyReferences values(1000,1,44,N'en')
insert into @PropertyReferences values(1012,1,44,N'en')
insert into @PropertyReferences values(1099,1,44,N'en')
insert into @PropertyReferences values(1104,1,44,N'en')


	IF dbo.mdpfn_sys_IsAzureCompatible() = 0  --Fields will be encrypted only when DB does not support Azure
		BEGIN
		EXEC mdpsp_sys_OpenSymmetricKey
		
		;WITH CTE1 AS (
			SELECT R.*, E.CatalogId
			FROM @PropertyReferences R
			INNER JOIN CatalogEntry E ON E.CatalogEntryId = R.ObjectId AND R.ObjectTypeId = 0
		UNION ALL
			SELECT R.*, N.CatalogId
			FROM @PropertyReferences R
			INNER JOIN CatalogNode N ON N.CatalogNodeId = R.ObjectId AND R.ObjectTypeId = 1
		),
		CTE2 AS (
			SELECT CTE1.ObjectId, CTE1.ObjectTypeId, CTE1.MetaClassId, ISNULL(L.LanguageCode, C.DefaultLanguage) AS LanguageName, C.DefaultLanguage
			FROM CTE1
			INNER JOIN [Catalog] C ON C.CatalogId = CTE1.CatalogId
			LEFT OUTER JOIN CatalogLanguage L ON L.CatalogId = CTE1.CatalogId AND L.LanguageCode = CTE1.LanguageName
		)
		-- Select CatalogContentProperty data
		SELECT P.ObjectId, P.ObjectTypeId, P.MetaFieldId, P.MetaClassId, P.MetaFieldName, P.LanguageName,
							P.Boolean, P.Number, P.FloatNumber, P.[Money], P.[Decimal], P.[Date], P.[Binary], P.[String], 
							CASE WHEN (F.IsEncrypted = 1 AND dbo.mdpfn_sys_IsLongStringMetaField(F.DataTypeId) = 1) 
								THEN dbo.mdpfn_sys_EncryptDecryptString(P.LongString, 0) 
								ELSE P.LongString END 
							AS LongString,
							P.[Guid]  
		FROM dbo.CatalogContentProperty P
		INNER JOIN MetaField F ON P.MetaFieldId = F.MetaFieldId
		INNER JOIN CTE2 ON
			P.ObjectId = CTE2.ObjectId AND
			P.ObjectTypeId = CTE2.ObjectTypeId AND
			P.MetaClassId = CTE2.MetaClassId AND
			((F.MultiLanguageValue = 1 AND P.LanguageName = CTE2.LanguageName COLLATE DATABASE_DEFAULT) OR ((F.MultiLanguageValue = 0 AND P.LanguageName = CTE2.DefaultLanguage COLLATE DATABASE_DEFAULT)))
		EXEC mdpsp_sys_CloseSymmetricKey
		END
	ELSE
		BEGIN
		
		;WITH CTE1 AS (
			SELECT R.*, E.CatalogId
			FROM @PropertyReferences R
			INNER JOIN CatalogEntry E ON E.CatalogEntryId = R.ObjectId AND R.ObjectTypeId = 0
		UNION ALL
			SELECT R.*, N.CatalogId
			FROM @PropertyReferences R
			INNER JOIN CatalogNode N ON N.CatalogNodeId = R.ObjectId AND R.ObjectTypeId = 1
		),
		CTE2 AS (
			SELECT CTE1.ObjectId, CTE1.ObjectTypeId, CTE1.MetaClassId, ISNULL(L.LanguageCode, C.DefaultLanguage) AS LanguageName, C.DefaultLanguage
			FROM CTE1
			INNER JOIN [Catalog] C ON C.CatalogId = CTE1.CatalogId
			LEFT OUTER JOIN CatalogLanguage L ON L.CatalogId = CTE1.CatalogId AND L.LanguageCode = CTE1.LanguageName
		)	
		SELECT P.ObjectId, P.ObjectTypeId, P.MetaFieldId, P.MetaClassId, P.MetaFieldName, P.LanguageName,
							P.Boolean, P.Number, P.FloatNumber, P.[Money], P.[Decimal], P.[Date], P.[Binary], P.[String], P.LongString LongString,
							P.[Guid]  
		FROM dbo.CatalogContentProperty P
		INNER JOIN MetaField F ON P.MetaFieldId = F.MetaFieldId
		INNER JOIN CTE2 ON
			P.ObjectId = CTE2.ObjectId AND
			P.ObjectTypeId = CTE2.ObjectTypeId AND
			P.MetaClassId = CTE2.MetaClassId AND
			((F.MultiLanguageValue = 1 AND P.LanguageName = CTE2.LanguageName COLLATE DATABASE_DEFAULT) OR ((F.MultiLanguageValue = 0 AND P.LanguageName = CTE2.DefaultLanguage COLLATE DATABASE_DEFAULT)))
		END
	-- Select CatalogContentEx data
	SELECT *
	FROM dbo.CatalogContentEx Ex 
	INNER JOIN @PropertyReferences R ON Ex.ObjectId = R.ObjectId AND Ex.ObjectTypeId = R.ObjectTypeId



This is litterally exactly the same query/parameters as what the stored proc runs, except running this code through the stored proc is slow as heck, and it's like 0 seconds doing it here.

#181293
Aug 15, 2017 22:33
Vote:
 

Ha, you might be one victim of what called "parameter sniffing" 

Try

ATER PROCEDURE [dbo].[CatalogContentProperty_LoadBatch]
	@PropertyReferences [udttCatalogContentPropertyReference] READONLY
WITH RECOMPILE 
AS ....
#181294
Aug 15, 2017 22:38
Vote:
 

Thanks for your help with this Quan. I did that, but still no go. It's still ridiculously slow. I made the below change, and it seems to have fixed everything however I'm not really a huge fan of rewriting EPiserver stored procedures. Though, worth noting this one was way over engineered.

ALTER PROCEDURE [dbo].[CatalogContentProperty_LoadBatch]
	@PropertyReferences [udttCatalogContentPropertyReference] READONLY
AS
BEGIN
	

SELECT ccp.objectId, ccp.objectTypeId, ccp.MetaFieldId, ccp.MetaClassId, ccp.MetaFieldName, ccp.LanguageName, ccp.Boolean, ccp.Number, ccp.FloatNumber, ccp.[Money], ccp.[Decimal], ccp.[Date], ccp.[Binary], ccp.[String], ccp.[LongString], ccp.[Guid]	
FROM CatalogContentProperty ccp 
	INNER JOIN @PropertyReferences pr ON ccp.ObjectId = pr.ObjectId 
		AND ccp.LanguageName = pr.LanguageName 
		AND ccp.MetaClassId = pr.MetaClassId


	-- Select CatalogContentEx data
	SELECT *
	FROM dbo.CatalogContentEx Ex 
	INNER JOIN @PropertyReferences R ON Ex.ObjectId = R.ObjectId AND Ex.ObjectTypeId = R.ObjectTypeId
END

GO





#181295
Aug 15, 2017 22:44
Vote:
 

No rewriting Episerver SPs should not be the solution.

Care to run with execution plan to see the difference? 

#181296
Aug 15, 2017 22:49
Vote:
 

I agree 100%. But the current stored proc isn't working. I'll work through this with you though, I'd love to come up with a better solution.

#181297
Aug 15, 2017 22:51
Vote:
 

Do you want a screenshot of the execution plan, or an xml dump?

#181298
Aug 15, 2017 22:51
Vote:
 

why not both? one for a quick glance and one for detail investigation

#181299
Aug 15, 2017 22:57
Vote:
 

This is the execution plan that occurs when I run the contents of the sql.

This is the execution plan from the stored proc execution.

#181300
Aug 15, 2017 22:58
Vote:
 

It's crazy how different these execution plans are despite the fact that it's litterally exactly the same database/code. The only difference between these, is that one is in a stored proc and the other is the code that's inside the stored proc that I pulled out and added the execution variables at the top.

#181301
Aug 15, 2017 23:02
Vote:
 

Not sure if this is a cuprit, or a symptom, but when I run this stored procedure and view the execution plan, I notice that there is a hash match, with a warning in the execution plan. Mousing over this is says this...

#181302
Aug 15, 2017 23:05
Vote:
 

The records returned between the adhoc and stored procedure are exactly the same, except the execution plan is different, the adhoc one is 0 seconds while the other one is about 40. Also the records returned are the same, except the adhoc one is sorted by objectid, while the other one isn't sorted by anything really.

-Paul

#181303
Aug 15, 2017 23:07
Vote:
 

You can view the full sql execution plan here...

Adhoc Query
https://filebin.net/037p73eu0aaqiscp/Episerver.CatalogContentProperty_LoadBatch_Adhoc_Execution_Plan.sqlplan

Stored Procedure
https://filebin.net/037p73eu0aaqiscp/Episerver.CatalogContentProperty_LoadBatch_StoredProcedure_Execution_Plan.sqlplan

#181305
Aug 15, 2017 23:25
Vote:
 

Where is the xml dump. It looks like for the SP SQL Server did not use the clustered index, but trying to use some other indexes instead. It was unclear which index was used from the screenshot 

#181306
Aug 15, 2017 23:26
Vote:
 

I just posted the full sql execution plans for both the adhock and the stored procedure.

#181307
Aug 15, 2017 23:28
Vote:
 

I still believe this is the doing of parameter sniffing - Can you execute the SP with the WITH RECOMPILE option? 

EXECUTE sp params WITH RECOMPILE
#181309
Aug 15, 2017 23:51
Vote:
 

I ran the stored procedure with WITH RECOMPILE, as you mentioned and it still took 40 seconds.

Here is the full Execution Plan.

https://filebin.net/r54svoy1knnojfr4/Episerver.CatalogContentProperty_LoadBatch_StoredProcedure_Execution_Plan_WITH_RECOMPILE.sqlplan

#181310
Aug 16, 2017 0:22
Vote:
 

Mind trying to drop the execution plan for the procedure and try again? 

https://serverfault.com/questions/91285/how-do-i-remove-a-specific-bad-plan-from-the-sql-server-query-cache 

#181334
Aug 16, 2017 14:09
Vote:
 

I just dropped all execution plans related to this query. After making this change, I ran the query again and it still took a very long time. Slightly longer than before. Definilty no improvement and the execution plan looks the same to me.

#181343
Aug 16, 2017 15:36
Vote:
 

This is an interesting case and I'd like to help. However this remote, async diagnose will take (long) time. As I said it would be better if we can get a hand on your db for proper investigation, via official channel :)

#181344
Aug 16, 2017 15:42
Vote:
 

I actually just made some progress with this. It definitly looks like some type of parameter sniffing. I modified the CatalogContentProperty_LoadBatch stored procedure, and change the incoming @PropertyReferences user defined table, to insert into a temp table. Then I changed all references to that variable to be use my temp table, as opposed to the @PropertyReferences udt.

USE [EPiServer.CommerceManager]
GO

/****** Object:  StoredProcedure [dbo].[CatalogContentProperty_LoadBatch]    Script Date: 8/16/2017 9:17:58 AM ******/
SET ANSI_NULLS ON
GO

SET QUOTED_IDENTIFIER ON
GO


ALTER PROCEDURE [dbo].[CatalogContentProperty_LoadBatch]
	@PropertyReferences [udttCatalogContentPropertyReference] READONLY
AS
BEGIN

SELECT *
INTO #TempPropertyReference
FROM @PropertyReferences

	IF dbo.mdpfn_sys_IsAzureCompatible() = 0  --Fields will be encrypted only when DB does not support Azure
		BEGIN
		EXEC mdpsp_sys_OpenSymmetricKey
		
		;WITH CTE1 AS (
			SELECT R.*, E.CatalogId
			FROM #TempPropertyReference R
			INNER JOIN CatalogEntry E ON E.CatalogEntryId = R.ObjectId AND R.ObjectTypeId = 0
		UNION ALL
			SELECT R.*, N.CatalogId
			FROM #TempPropertyReference R
			INNER JOIN CatalogNode N ON N.CatalogNodeId = R.ObjectId AND R.ObjectTypeId = 1
		),
		CTE2 AS (
			SELECT CTE1.ObjectId, CTE1.ObjectTypeId, CTE1.MetaClassId, ISNULL(L.LanguageCode, C.DefaultLanguage) AS LanguageName, C.DefaultLanguage
			FROM CTE1
			INNER JOIN [Catalog] C ON C.CatalogId = CTE1.CatalogId
			LEFT OUTER JOIN CatalogLanguage L ON L.CatalogId = CTE1.CatalogId AND L.LanguageCode = CTE1.LanguageName
		)
		-- Select CatalogContentProperty data
		SELECT P.ObjectId, P.ObjectTypeId, P.MetaFieldId, P.MetaClassId, P.MetaFieldName, P.LanguageName,
							P.Boolean, P.Number, P.FloatNumber, P.[Money], P.[Decimal], P.[Date], P.[Binary], P.[String], 
							CASE WHEN (F.IsEncrypted = 1 AND dbo.mdpfn_sys_IsLongStringMetaField(F.DataTypeId) = 1) 
								THEN dbo.mdpfn_sys_EncryptDecryptString(P.LongString, 0) 
								ELSE P.LongString END 
							AS LongString,
							P.[Guid]  
		FROM dbo.CatalogContentProperty P
		INNER JOIN MetaField F ON P.MetaFieldId = F.MetaFieldId
		INNER JOIN CTE2 ON
			P.ObjectId = CTE2.ObjectId AND
			P.ObjectTypeId = CTE2.ObjectTypeId AND
			P.MetaClassId = CTE2.MetaClassId AND
			((F.MultiLanguageValue = 1 AND P.LanguageName = CTE2.LanguageName COLLATE DATABASE_DEFAULT) OR ((F.MultiLanguageValue = 0 AND P.LanguageName = CTE2.DefaultLanguage COLLATE DATABASE_DEFAULT)))
		EXEC mdpsp_sys_CloseSymmetricKey
		END
	ELSE
		BEGIN
		
		;WITH CTE1 AS (
			SELECT R.*, E.CatalogId
			FROM #TempPropertyReference R
			INNER JOIN CatalogEntry E ON E.CatalogEntryId = R.ObjectId AND R.ObjectTypeId = 0
		UNION ALL
			SELECT R.*, N.CatalogId
			FROM #TempPropertyReference R
			INNER JOIN CatalogNode N ON N.CatalogNodeId = R.ObjectId AND R.ObjectTypeId = 1
		),
		CTE2 AS (
			SELECT CTE1.ObjectId, CTE1.ObjectTypeId, CTE1.MetaClassId, ISNULL(L.LanguageCode, C.DefaultLanguage) AS LanguageName, C.DefaultLanguage
			FROM CTE1
			INNER JOIN [Catalog] C ON C.CatalogId = CTE1.CatalogId
			LEFT OUTER JOIN CatalogLanguage L ON L.CatalogId = CTE1.CatalogId AND L.LanguageCode = CTE1.LanguageName
		)	
		SELECT P.ObjectId, P.ObjectTypeId, P.MetaFieldId, P.MetaClassId, P.MetaFieldName, P.LanguageName,
							P.Boolean, P.Number, P.FloatNumber, P.[Money], P.[Decimal], P.[Date], P.[Binary], P.[String], P.LongString LongString,
							P.[Guid]  
		FROM dbo.CatalogContentProperty P
		INNER JOIN MetaField F ON P.MetaFieldId = F.MetaFieldId
		INNER JOIN CTE2 ON
			P.ObjectId = CTE2.ObjectId AND
			P.ObjectTypeId = CTE2.ObjectTypeId AND
			P.MetaClassId = CTE2.MetaClassId AND
			((F.MultiLanguageValue = 1 AND P.LanguageName = CTE2.LanguageName COLLATE DATABASE_DEFAULT) OR ((F.MultiLanguageValue = 0 AND P.LanguageName = CTE2.DefaultLanguage COLLATE DATABASE_DEFAULT)))
		END
	-- Select CatalogContentEx data
	SELECT *
	FROM dbo.CatalogContentEx Ex 
	INNER JOIN #TempPropertyReference R ON Ex.ObjectId = R.ObjectId AND Ex.ObjectTypeId = R.ObjectTypeId

END


GO


#181345
Aug 16, 2017 15:46
Vote:
 

This solution isn't ideal, as I'm modifying an Episerver stored procedure. But at this point I'm seeing no other options.

#181346
Aug 16, 2017 15:46
Vote:
 

Yes, it's definitely a parameter sniffing problem. It might also affect other customers - but it's currently not-reproducible on our test environment. The right way to fix it is to contact developer support service and provide the db. We will work on this to find a solution that we all can be happy with.

#181347
Aug 16, 2017 15:57
Vote:
 

When you get a moment, check your gmail. We've gone through Episerver Expert services and it wasn't a viable avenue for us.

#181349
Aug 16, 2017 16:04
Vote:
 

Hi,

I can see that you contacted Episerver support service, how is it going? 

#182126
Sep 11, 2017 14:03
Vote:
 

This issue is resolved. I cleared database statistics and this resolved the issue.

-Paul

#182129
Sep 11, 2017 14:52
Vote:
 

But worth noting, is I replicated this three times. I pulled down our production server to our dev and re-ran the database upgrade, and had this problem all three times.

#182130
Sep 11, 2017 14:52
Vote:
 

Yes, updating statistics is a way to resolve it - but perhaps you might want to try to turn on auto statistics update?

Now I have more time to look at your execution plans you attached, and it's now quite clear (I learned a lot since last time) SQL Server choosed the very bad plan. Instead of using CTE2 which would filter the rows a lot, it uses the MetaFieldId join which is very heavy (Index seek and look up 1.5M rows). This can be explained that the statistics were heavily out of date and the execution plan was based on the assumption that MetaFieldId is very selective (which it is not)

#182132
Edited, Sep 11, 2017 15:00
Vote:
 

Auto update statistics were on. :/

#182145
Sep 11, 2017 16:50
This topic was created over six months ago and has been resolved. If you have a similar question, please create a new topic and refer to this one.
* You are NOT allowed to include any hyperlinks in the post because your account hasn't associated to your company. User profile should be updated.