AI OnAI Off

"Execution timeout Expired" when publishing content in Commerce 9.24.1

Henrik S
Henrik S
Vote:
 

Hi,

after upgrading from 8.16 to 9.24.1 we're having issues periodically with publishing products in Episerver.

When clicking "Publish" - nothing happens, and after a while we see an error message stating

Something went wrong
-----------------------------------
Execution timeout Expired. The timeout  period elapsed prior to completion of the operation or the server is not responding. The wait operation timed out.

Here's the related stack trace:

System.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out
   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 EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute[TResult](Func`1 method)
   at Mediachase.Data.Provider.SqlDataProvider.ExecuteNonExec(DataCommand command)
   at Mediachase.MetaDataPlus.Common.DBHelper.ExecuteNonQuery(String connectionString, CommandType commandType, String commandText, Int32 commandTimeout, DataParameter[] commandParameters)
   at Mediachase.MetaDataPlus.Configurator.MetaObjectDB.UpdateMetaObject(MetaDataContext context, MetaObject metaObject, Dictionary`2 metaParams, Boolean disableSync)
   at Mediachase.MetaDataPlus.MetaObject.AcceptChanges(MetaDataContext context)
   at EPiServer.Commerce.Catalog.Provider.Persistence.MetaDataCommitter.CommitMetaAttributes[T](T content, Int32 objectId)
   at EPiServer.Commerce.Catalog.Provider.Persistence.EntryContentBaseCommitter.UpdateExisting(EntryContentBase content, Int32 entryId, Boolean syncDraft)
   at EPiServer.Commerce.Catalog.Provider.Persistence.EntryContentBaseCommitter.Save(CatalogContentBase content, Boolean syncDraft)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentCommitterHandler.SaveVersionInternal(CatalogContentBase content, SaveAction action, String currentUser)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentCommitterHandler.Save(CatalogContentBase content, SaveAction action, String currentUser)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentProvider.Save(IContent content, SaveAction action)
   at EPiServer.Core.DefaultContentRepository.Save(IContent content, SaveAction action, AccessLevel access)
   at EPiServer.Cms.Shell.Service.ContentService.Save(IContent content, SaveAction saveAction)
   at EPiServer.Cms.Shell.Workspace.Committers.ContentDataCommitter.Commit(EditContentData change, CommitArguments argument)

At first we thought this was solved by creating a missing index (https://world.episerver.com/forum/developer-forum/Episerver-Commerce/Thread-Container/2021/3/spikes-in-sql-cpu-usage-after-upgrading-to-commerce-9-24-1/) but we're still seeing this issue quite often.

Any advice on how to proceed with troubleshooting?

#251083
Mar 22, 2021 9:15
Naveed Ul-Haq
Naveed Ul-Haq
Vote:
 

Do you have any post publish events?

Have you upgraded database without issues while upgrading episerver databases?

Are you on dxc? Can you check error telemetry from application insight?

#251089
Mar 22, 2021 10:28
Quan Mai
Quan Mai
Vote:
 

The general approach is to use a profiler to see what happens under the hood. If you can replicate the issue locally, then SQL Profiler can be a very good choice in this case.

Also, how is your SQL Server behaving during the publish? Is it overloaded (CPU/mem) at all? 

#251092
Mar 22, 2021 10:43
Henrik S
Henrik S
Vote:
 

Thanks, Naveed!

Yes, we did finish the upgrade without any migration errors. 

As far as I can see we do not have any publish events. There's no sign of subscribing to any content event in the initialization modules.

We're not on DXC, we're on-prem.

#251094
Mar 22, 2021 10:49
Henrik S
Henrik S
Vote:
 

We're not seeing any high CPU/Memory usage during the periods when publishing fails

#251095
Mar 22, 2021 10:50
Henrik S
Henrik S
Vote:
 

I ran a query to get suggested indexes - I should probably not create all of these. Would creating any of these indexes maybe help with our problem publishing content?

I wasn't able to present the data in a more readable way - however, if you copy the table underneath and paster into Excel - it should be readable:

Suggested_Indexes User_Impact User_Seeks
CREATE NONCLUSTERED INDEX IX1_CatalogNodeF90F2 on [Commerce].[dbo].[CatalogNode]([ContentGuid]) 86,71 4831105
CREATE NONCLUSTERED INDEX IX1_ecfVersionB9088 on [Commerce].[dbo].[ecfVersion]([CurrentLanguageRemoved], [Status],[StartPublish])Include ([WorkId], [ObjectId], [ObjectTypeId]) 97,34 3053
CREATE NONCLUSTERED INDEX IX1_CatalogContentEx22AD2 on [Commerce].[dbo].[CatalogContentEx]([ObjectTypeId],[Modified])Include ([ObjectId]) 64,54 2072
CREATE NONCLUSTERED INDEX IX1_CatalogContentProperty64D3A on [Commerce].[dbo].[CatalogContentProperty]([MetaClassId])Include ([ObjectId], [ObjectTypeId], [MetaFieldName], [LongString]) 81,93 1423
CREATE NONCLUSTERED INDEX IX1_CatalogNode8ACF8 on [Commerce].[dbo].[CatalogNode]([CatalogId])Include ([CatalogNodeId], [ParentNodeId]) 46,28 726
CREATE NONCLUSTERED INDEX IX1_CatalogContentProperty94200 on [Commerce].[dbo].[CatalogContentProperty]([MetaClassId])Include ([ObjectId], [ObjectTypeId], [MetaFieldName], [Boolean]) 63,19 456
CREATE NONCLUSTERED INDEX IX1_CatalogNode476F8 on [Commerce].[dbo].[CatalogNode]([ParentNodeId]) 28,84 431
CREATE NONCLUSTERED INDEX IX1_CatalogContentPropertyB4360 on [Commerce].[dbo].[CatalogContentProperty]([MetaFieldName])Include ([pkId], [ObjectId], [LongString]) 89,63 265
CREATE NONCLUSTERED INDEX IX1_CatalogContentPropertyA1ED9 on [Commerce].[dbo].[CatalogContentProperty]([MetaFieldName], [Boolean])Include ([ObjectId]) 98,27 233
CREATE NONCLUSTERED INDEX IX1_CatalogContentProperty72CFE on [Commerce].[dbo].[CatalogContentProperty]([MetaFieldName])Include ([ObjectId], [LongString]) 95,18 215
CREATE NONCLUSTERED INDEX IX1_CatalogContentPropertyABC7D on [Commerce].[dbo].[CatalogContentProperty]([ObjectTypeId])Include ([ObjectId]) 69,2 170
CREATE NONCLUSTERED INDEX IX1_CatalogContentProperty75F0F on [Commerce].[dbo].[CatalogContentProperty]([MetaFieldName])Include ([LongString]) 97,93 120
CREATE NONCLUSTERED INDEX IX1_CatalogContentProperty36B6C on [Commerce].[dbo].[CatalogContentProperty]([MetaClassId])Include ([ObjectId], [ObjectTypeId]) 65,38 52
CREATE NONCLUSTERED INDEX IX1_CatalogContentProperty05E04 on [Commerce].[dbo].[CatalogContentProperty]([MetaFieldName])Include ([pkId], [ObjectId], [ObjectTypeId], [MetaFieldId], [MetaClassId], [LanguageName], [Boolean], [Number], [FloatNumber], [Money], [Date], [Binary], [String], [LongString], [Guid], [Decimal]) 76,66 48
CREATE NONCLUSTERED INDEX IX1_PriceDetail01F39 on [Commerce].[dbo].[PriceDetail]([ValidFrom], [ValidUntil],[PriceCode])Include ([CatalogEntryCode]) 99,43 21
CREATE NONCLUSTERED INDEX IX1_CatalogContentPropertyF9E9A on [Commerce].[dbo].[CatalogContentProperty]([MetaClassId])Include ([ObjectId], [ObjectTypeId], [MetaFieldName], [Number], [LongString]) 82,26 20
CREATE NONCLUSTERED INDEX IX1_PriceDetail98C43 on [Commerce].[dbo].[PriceDetail]([PriceCode], [ValidFrom])Include ([CatalogEntryCode], [UnitPrice]) 98,37 8
CREATE NONCLUSTERED INDEX IX1_CatalogContentPropertyCF148 on [Commerce].[dbo].[CatalogContentProperty]([MetaClassId])Include ([ObjectId], [ObjectTypeId], [MetaFieldName], [Boolean], [LongString]) 67,54 7
CREATE NONCLUSTERED INDEX IX1_PriceDetailB4AD6 on [Commerce].[dbo].[PriceDetail]([ValidFrom], [ValidUntil])Include ([CatalogEntryCode]) 99,84 6
CREATE NONCLUSTERED INDEX IX1_CatalogEntryB7202 on [Commerce].[dbo].[CatalogEntry]([CatalogId])Include ([CatalogEntryId], [StartDate], [EndDate], [Name], [Code], [ClassTypeId], [IsActive]) 63,8 4
CREATE NONCLUSTERED INDEX IX1_CatalogContentProperty16C27 on [Commerce].[dbo].[CatalogContentProperty]([MetaFieldName])Include ([pkId], [ObjectId]) 89,78 2
CREATE NONCLUSTERED INDEX IX1_PriceDetail3EA75 on [Commerce].[dbo].[PriceDetail]([PriceCode], [ValidUntil])Include ([CatalogEntryCode]) 51,07 2
CREATE NONCLUSTERED INDEX IX1_OrderGroupAddress96D32 on [Commerce].[dbo].[OrderGroupAddress]([Name])Include ([OrderGroupId], [Email]) 57,16 2
CREATE NONCLUSTERED INDEX IX1_PriceDetailD8A3D on [Commerce].[dbo].[PriceDetail]([ValidUntil])Include ([CatalogEntryCode]) 99,19 2
CREATE NONCLUSTERED INDEX IX1_PriceDetail2D997 on [Commerce].[dbo].[PriceDetail]([PriceCode],[ValidFrom], [ValidUntil])Include ([CatalogEntryCode], [UnitPrice]) 20,03 2
CREATE NONCLUSTERED INDEX IX1_CatalogContentProperty9C1D1 on [Commerce].[dbo].[CatalogContentProperty]([MetaFieldId])Include ([ObjectId], [LongString]) 95,54 1
CREATE NONCLUSTERED INDEX IX1_CatalogNodeC461D on [Commerce].[dbo].[CatalogNode]([CatalogId], [ParentNodeId]) 22,05 1
CREATE NONCLUSTERED INDEX IX1_CatalogEntry773AD on [Commerce].[dbo].[CatalogEntry]([Name]) 99,89 1
CREATE NONCLUSTERED INDEX IX1_PriceDetailD3223 on [Commerce].[dbo].[PriceDetail]([PriceCode],[ValidUntil])Include ([CatalogEntryCode], [UnitPrice]) 35,52 1
#251114
Edited, Mar 22, 2021 15:46
Quan Mai
Quan Mai
Vote:
 

As mentioned above, you wwould neeed to understand why the query is timed out. Sql Profiler is a very good way to capture the query (with parameter), and then you can run that against SQL Server Managment Studio to get the execution plan. Only then you know what tuning you'll need. 

#251115
Mar 22, 2021 15:58
* 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.