Execution timeout when detaching MetaField from CatalogEntry

Milos Malic

Vote:

Hi all,

I am trying to detach (uncheck) meta field from a Variant in Episerver Commerce Manager.

1) With local SQL Server and catalog with some 40k entries it works without any problems.

2) In Azure against SQL in Elastic Poll (200 DTU) it fails with "[SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.]" That catalog has approx 120k entries.

I have tried to extend connection timeout, but that has no effect. The execution pumps up DTUs to 100% and then fails.

I have tried with 300 DTU, and then with 800 DTU. Same error after some 30 seconds.

Does this problem ring any bells for any of you guys? Why is this save of the meta class ramping up DB so high? Also the period when I get Execution Timeout looks like another timeout setting somewhere, that I did not find. But still, it wouldn't be of many help as this is how resources go, increase after increase of DTU.

Consumed DTU as we kept increasing it.

Increasing DTU in Elastic Pool and tries to save VAriant

No matter is it 200, 300 or 800 DTU database maxes to 100% and then execution timeout happens.

Tries to do save with 200, 300 and 800 DTU go to 100%

Version of Commerce is 13.16.0

[SqlException (0x80131904): Execution 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) +3306108
   System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) +736
   System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) +4061
   System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted) +496
   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) +3303
   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) +667
   System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) +535
   System.Data.SqlClient.SqlCommand.ExecuteNonQuery() +380
   EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute(Func`1 method) +699
   Mediachase.Data.Provider.SqlDataProvider.ExecuteNonExec(DataCommand command) +416
   Mediachase.MetaDataPlus.Common.DBHelper.ExecuteNonQuery(String connectionString, CommandType commandType, String commandText, Int32 commandTimeout, DataParameter[] commandParameters) +236
   Mediachase.MetaDataPlus.Configurator.StoredProcedure.ExecuteNonQuery(MetaDataContext context) +54
   Mediachase.MetaDataPlus.Configurator.MetaClass.DoDeleteField(MetaField metaField) +133
   Mediachase.Commerce.Manager.Core.MetaData.Admin.MetaClassesControl.UpdateAttributes(MetaClass mc) +763
   Mediachase.Commerce.Manager.Core.MetaData.Admin.MetaClassesControl.SaveButton_Click(Object sender, EventArgs e) +117
   Mediachase.Commerce.Manager.Core.SaveControl.OnSaveChanges(Object sender, EventArgs e) +64
   System.Web.UI.WebControls.Button.OnClick(EventArgs e) +11760128
   System.Web.UI.WebControls.Button.RaisePostBackEvent(String eventArgument) +150
   System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) +5028

#222736

Edited, May 12, 2020 7:46

Quan Mai

Vote:

Could you use Sql profiler to capture exactly what query caused the time out?

#222741

May 12, 2020 9:15

Milos Malic

Vote:

Hi Quan, thanks for picking up interest. Unfortunately I didn't find option to export or save log from Azure Data Studio profiler, but here are screenshots and info.

When it fails, it just after mdpsp_sys_DeleteMetaFieldFromMetaClass is logged as rpc_completed and attention shows up in next row.

This is duration in printscreen whith another field. It is usually microsecond value between 30 and 31 seconds.

This is how profiling log looks like when removing field succeeds. Duration is below some 19 seconds.

Two behaviours that I cannot get control of are:

If I try to detach field from class enough times (like while profiling this) eventully I manage to save it. Looked at SP briefly to see if it actually does some changes chunk by chunk every time so maybe after retries it has less work to do and it completes. But there is Transaction context inside with ROLLBACK so it is less likely.
SqlClient inside commerce manager uses default timeut value? Cannot figure out where else that 30 second timeout could come from. I have set it much higher value in connection string during this fixing.

#222868

Edited, May 12, 2020 21:17

Quan Mai

Vote:

If you want to run it as one-time thing, then the setting is here

https://vimvq1987.com/episerver-commerce-commandtimeout-configuration/

#222891

May 13, 2020 7:01

Milos Malic

Vote:

Yes. After extending commandTimeout on SqlDataProvider configuration I was able to detach field from meta class. First to 300, wasn't enough. Then to 600 sec and it worked. It of course timed out web request so commerce app showed 503, but still finished DB task in the background.

Thanks to team Quan Mai for help!

#222898

Edited, May 13, 2020 9:37

Quan Mai

Vote:

As a side note, the time out probably comes from this query

DELETE FROM CatalogContentProperty WHERE MetaFieldId = @MetaFieldId AND MetaClassId = @MetaClassId
DELETE FROM ecfVersionProperty WHERE MetaFieldId = @MetaFieldId AND MetaClassId = @MetaClassId

So you can add a non clustered index on (MetaFieldId, MetaClassId) on both tables to make the query runs faster, then drop them :)

#222899

May 13, 2020 9:54