AI OnAI Off

Database timeout on product/variant update

Kristoffer Lindén
Kristoffer Lindén
Vote:
 

Hi!

This just showed up in our logs. Same code has been running for a long time now without problems.

System.Exception: Exception in ecfVersion_ListByWorkIds:  ---> System.Data.SqlClient.SqlException: Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> 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.SqlDataReader.TryConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption)
   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.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.Common.DbDataAdapter.FillInternal(DataSet dataset, DataTable[] datatables, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)
   at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)
   at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet)
   at Mediachase.Data.Provider.SqlDataProvider.<>c__DisplayClass17_2.b__0()
   at EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute[TResult](Func`1 method)
   at Mediachase.Data.Provider.SqlDataProvider.LoadDataSet(DataCommand command)
   --- End of inner exception stack trace ---
   at Mediachase.Data.Provider.SqlDataProvider.LoadDataSet(DataCommand command)
   at Mediachase.MetaDataPlus.Common.DBHelper.ExecuteDataSet(String connectionString, CommandType commandType, String commandText, DataParameter[] commandParameters)
   at EPiServer.Commerce.Catalog.DataAccess.CatalogContentVersionDB.LoadDraft(IList`1 contentLinks)
   at EPiServer.Commerce.Catalog.Provider.Construction.EntryBuilder.CreateVersions(IList`1 contentLinks)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentLoader.ConstructContent(IList`1 contentLinks, Func`3 createContentFunc)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentLoader.LoadSpecificContentVersions(IList`1 contentVersions)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentProvider.BatchLoad(IList`1 contentLinks, Func`2 dbLoader)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentProvider.LoadContents(IList`1 contentReferences, ILanguageSelector selector)
   at EPiServer.Commerce.Catalog.Provider.CatalogContentProvider.LoadContent(ContentReference contentLink, ILanguageSelector languageSelector)
   at EPiServer.Core.ContentProvider.<>c__DisplayClass116_0.b__0()
   at EPiServer.Framework.Cache.ObjectInstanceCacheExtensions.ReadThroughWithWait[T](IObjectInstanceCache cache, String cacheKey, Func`1 readValue, Func`2 evictionPolicy)
   at EPiServer.Core.ContentProvider.LoadContentFromCacheOrRepository(ContentReference contentreference, ILanguageSelector selector)
   at EPiServer.Core.Internal.ProviderPipelineImplementation.GetItem(ContentProvider provider, ContentReference contentLink, LoaderOptions loaderOptions)
   at EPiServer.Core.Internal.DefaultContentLoader.TryGet[T](ContentReference contentLink, LoaderOptions loaderOptions, T& content)
   at EPiServer.Core.Internal.DefaultContentLoader.Get[T](ContentReference contentLink, LoaderOptions loaderOptions)
   at EPiServer.Core.Internal.DefaultContentRepository.Save(IContent content, SaveAction action, AccessLevel access)

Any idea what could cause this problem? We are running Commerce 10.5

Thanks!

/Kristoffer

#183482
Oct 16, 2017 13:07
Quan Mai
Quan Mai
Vote:
 

How many rows do you have in ecfVersion? Can you get the execution plan for this query? 

#183483
Oct 16, 2017 13:10
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

We have 479098 rows in the table.

How do I get the execution plan, I did it once but have forgotten! :-)

/Kristoffer

#183484
Oct 16, 2017 13:14
Quan Mai
Quan Mai
Vote:
 

LMGTFY: https://stackoverflow.com/questions/7359702/how-do-i-obtain-a-query-execution-plan 

#183485
Edited, Oct 16, 2017 13:17
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

This is excuted:

declare @p1 dbo.udttObjectWorkId
insert into @p1 values(110830,0,1378017,NULL)
insert into @p1 values(110830,0,1356813,NULL)
insert into @p1 values(110830,0,1356812,NULL)
insert into @p1 values(110830,0,1356810,NULL)
insert into @p1 values(110830,0,1356811,NULL)
insert into @p1 values(96861,0,1380113,NULL)
insert into @p1 values(96861,0,1329903,NULL)
insert into @p1 values(96861,0,1281127,NULL)
insert into @p1 values(96861,0,1265426,NULL)
insert into @p1 values(96861,0,1260440,NULL)
insert into @p1 values(96861,0,1247704,NULL)
insert into @p1 values(96861,0,469360,NULL)
insert into @p1 values(96861,0,469359,NULL)
insert into @p1 values(96861,0,444058,NULL)
insert into @p1 values(96861,0,444057,NULL)
insert into @p1 values(96861,0,415689,NULL)
insert into @p1 values(96861,0,415688,NULL)
insert into @p1 values(96861,0,379004,NULL)
insert into @p1 values(96861,0,379003,NULL)
insert into @p1 values(96861,0,236924,NULL)
insert into @p1 values(96861,0,236923,NULL)
insert into @p1 values(96861,0,233462,NULL)
insert into @p1 values(96861,0,233461,NULL)
insert into @p1 values(96861,0,190682,NULL)
insert into @p1 values(96861,0,190681,NULL)
insert into @p1 values(96441,0,1380282,NULL)
insert into @p1 values(96441,0,1330257,NULL)
insert into @p1 values(96441,0,1281483,NULL)
insert into @p1 values(96441,0,1265765,NULL)
insert into @p1 values(96441,0,1260796,NULL)
insert into @p1 values(96441,0,1248075,NULL)
insert into @p1 values(96441,0,468196,NULL)
insert into @p1 values(96441,0,468195,NULL)
insert into @p1 values(96441,0,442894,NULL)
insert into @p1 values(96441,0,442893,NULL)
insert into @p1 values(96441,0,414525,NULL)
insert into @p1 values(96441,0,414524,NULL)
insert into @p1 values(96441,0,377840,NULL)
insert into @p1 values(96441,0,377839,NULL)
insert into @p1 values(96441,0,235664,NULL)
insert into @p1 values(96441,0,235663,NULL)
insert into @p1 values(96441,0,232202,NULL)
insert into @p1 values(96441,0,232201,NULL)
insert into @p1 values(96441,0,189002,NULL)
insert into @p1 values(96441,0,189001,NULL)
insert into @p1 values(96950,0,1381232,NULL)
insert into @p1 values(96950,0,1337237,NULL)
insert into @p1 values(96950,0,1278209,NULL)
insert into @p1 values(96950,0,1277635,NULL)
insert into @p1 values(96950,0,1269243,NULL)
insert into @p1 values(96950,0,1257298,NULL)
insert into @p1 values(96950,0,469585,NULL)
insert into @p1 values(96950,0,469584,NULL)
insert into @p1 values(96950,0,444283,NULL)
insert into @p1 values(96950,0,444282,NULL)
insert into @p1 values(96950,0,415914,NULL)
insert into @p1 values(96950,0,415913,NULL)
insert into @p1 values(96950,0,379229,NULL)
insert into @p1 values(96950,0,379228,NULL)
insert into @p1 values(96950,0,237191,NULL)
insert into @p1 values(96950,0,237190,NULL)
insert into @p1 values(96950,0,233729,NULL)
insert into @p1 values(96950,0,233728,NULL)
insert into @p1 values(96950,0,191038,NULL)
insert into @p1 values(96950,0,191037,NULL)
exec ecfVersion_ListByWorkIds @ContentLinks=@p1
And here you can download the execution plan (10000 rows so I don't want to post it here):
/Kristoffer
#183488
Edited, Oct 16, 2017 13:40
Quan Mai
Quan Mai
Vote:
 

I found something interesting, but I'd have to verify them more closely before filing a bug for us to work on it. 

How long does it take for you to run that query? Is it possible to reduce the batch size?

#183492
Oct 16, 2017 14:36
Quan Mai
Quan Mai
Vote:
 

My suspicion is on your ecfVersion.IDX_ecfVersion_Indexed_ContentId Index. Make sure it gets defragmented, and its statistics are up-to-date 

#183494
Oct 16, 2017 14:45
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

The query took 2 minutes 23 seconds. 

Tried to run this:

declare @p1 dbo.udttObjectWorkId
insert into @p1 values(96265,0,1358777,NULL)
exec ecfVersion_ListByWorkIds @ContentLinks=@p1
It took 2 minutes 14 seconds.
Query 1-4 executes immediatly while 5-9 takes over 2 minutes.
Is there a workaround for this? Our customer cannot use the Commerce edit GUI since they get a timeout?
/Kristoffer
#183495
Oct 16, 2017 14:49
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

I have rebuilt all the indexes on ecfVersion and updated statistics but it still takes 2 minutes.

Should I email developer support with a link to a database backup?

/Kristoffer

#183496
Edited, Oct 16, 2017 15:16
Quan Mai
Quan Mai
Vote:
 

Yes, that should be the proper way to handle it. It might end up in my hands eventually - as I'm generally excited for performance improvements - but we should follow the workflow 

#183497
Oct 16, 2017 15:18
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

Ticket has been created and it would be great if you can look at this as soon as possible since our customer cannot work in Commerce edit mode right now. If you have any other idea how we can work around this for now. Maybe delete old versions or something, that would be great!

Thanks!

/Kristoffer

#183504
Oct 16, 2017 16:26
Quan Mai
Quan Mai
Vote:
 

http://vimvq1987.com/2017/10/curious-case-sql-execution-plan/

This might be of interest to you 

#183541
Oct 17, 2017 9:21
Quan Mai
Quan Mai
Vote:
 

Another update:

http://vimvq1987.com/2017/10/curious-case-sql-execution-plan-part-2/

we will incorporate these changes in an upcoming version 

#183731
Oct 21, 2017 9:25
Kristoffer Lindén
Kristoffer Lindén
Vote:
 

Hi Quan!

Today we got an exception in this function:

Mediachase.Commerce.Catalog.CatalogContent.CatalogContentSync.CreateDraft(CatalogNodeDto nodeDto, String changedBy)

It looks like it was this procedure that caused the timeout:

ecfVersion_SyncCatalogData

Also an ecfVersion procedure. Maybe there is something there that also needs to be updated?

/Kristoffer

#184429
Oct 26, 2017 15:25
Quan Mai
Quan Mai
Vote:
 

That would be not enough for us to look into the problem. As usual an execution plan (and usually the database) is needed. As always support service is the way to go

#184479
Oct 27, 2017 19:09
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.