November Happy Hour will be moved to Thursday December 5th.

AI OnAI Off

Publishing Terribly Slow

Paul A
Paul A
Vote:
 

Hey Guys,

I'm upgrading from Commerce 9.11, to commerce 11.1.1. Everything is looking great and we're ready to go live today, except one, huge issue.

Our publishing.. is terribly slow. 

One thing I've noticed, is that on publish we get a 500 error on the back end. 

#182082
Sep 08, 2017 16:50
Paul A
Paul A
Vote:
 

Here is a full stack trace on that error.

Server Error in '/' Application.

A catalog content reference of type Catalog is invalid in this operation, only entries and nodes have codes.
Parameter name: contentLink

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.ArgumentException: A catalog content reference of type Catalog is invalid in this operation, only entries and nodes have codes.
Parameter name: contentLink

Source Error: 

An unhandled exception was generated during the execution of the current web request. Information regarding the origin and location of the exception can be identified using the exception stack trace below.


Stack Trace: 

[ArgumentException: A catalog content reference of type Catalog is invalid in this operation, only entries and nodes have codes.
Parameter name: contentLink]
   Mediachase.Commerce.Catalog.ReferenceConverter.GetCode(ContentReference contentLink) +430
   EPiServer.Commerce.Shell.Rest.RelationStore.CreateModel(Relation relation, RelationRequestMode relationRequestMode) +516
   System.Linq.WhereSelectEnumerableIterator`2.MoveNext() +223
   System.Collections.Generic.List`1..ctor(IEnumerable`1 collection) +436
   System.Linq.Enumerable.ToList(IEnumerable`1 source) +70
   EPiServer.Shell.Services.Rest.ItemRange.ApplyTo(IEnumerable`1 items) +216
   EPiServer.Shell.Services.Rest.RestControllerBase.Rest(IEnumerable`1 data, ItemRange range) +21
   lambda_method(Closure , ControllerBase , Object[] ) +334
   System.Web.Mvc.ReflectedActionDescriptor.Execute(ControllerContext controllerContext, IDictionary`2 parameters) +229
   System.Web.Mvc.ControllerActionInvoker.InvokeActionMethod(ControllerContext controllerContext, ActionDescriptor actionDescriptor, IDictionary`2 parameters) +35
   System.Web.Mvc.Async.AsyncControllerActionInvoker.<BeginInvokeSynchronousActionMethod>b__39(IAsyncResult asyncResult, ActionInvocation innerInvokeState) +39
   System.Web.Mvc.Async.WrappedAsyncResult`2.CallEndDelegate(IAsyncResult asyncResult) +67
   System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethod(IAsyncResult asyncResult) +42
   System.Web.Mvc.Async.AsyncInvocationWithFilters.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3d() +72
   System.Web.Mvc.Async.<>c__DisplayClass46.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3f() +385
   System.Web.Mvc.Async.<>c__DisplayClass46.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3f() +385
   System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethodWithFilters(IAsyncResult asyncResult) +42
   System.Web.Mvc.Async.<>c__DisplayClass2b.<BeginInvokeAction>b__1c() +38
   System.Web.Mvc.Async.<>c__DisplayClass21.<BeginInvokeAction>b__1e(IAsyncResult asyncResult) +185
   System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeAction(IAsyncResult asyncResult) +38
   EPiServer.Shell.Services.Rest.RestControllerBase.EndExecute(IAsyncResult asyncResult) +60
   System.Web.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() +607
   System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) +134


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

#182083
Sep 08, 2017 16:51
Paul A
Paul A
Vote:
 

And the url that's being called on the back end is.. 
/EPiServer/EPiServer.Commerce.Shell/Stores/relation/?referenceId=1073742426_469854_CatalogContent&relationTypes=1&dojo.preventCache=1504881943177

#182084
Sep 08, 2017 16:52
Quan Mai
Quan Mai
Vote:
 

Hi,

We are aware of this problem (the exception), it was filed as bug COM-5404 and will be fixed in upcoming releases.

Sorry for this inconvenience.

/Q

#182086
Sep 08, 2017 17:03
Quan Mai
Quan Mai
Vote:
 

I, in other hands, tested publishing content and it's fine (there is no noticable slowness). Can you do a profiling to see why it's slow? Perhaps because you have some event listeners somewhere?

#182088
Sep 08, 2017 17:12
Paul A
Paul A
Vote:
 

I'm working on the profiler now. One thing I have seen is the hangup appears to occur while sending a Requestion Payload of..

{action: 3}

To the url... /EPiServer/cms/Stores/contentdata/1079_466551_CatalogContent

I'm guessing that action = 3 is publish, and this is the HTTP call out to your api to publish this content, correct?

-Paul

#182089
Sep 08, 2017 17:36
Paul A
Paul A
Vote:
 

Using SQL Express profiler I pinpointed the issue. For some reason when I run [ecfVersion_ListFiltered], it crawls. It takes about 36 seconds. I confirmed in SQL profiler that this is executed every publish. I saw there was a bug (COM-4792) reported for this stored procedure, but I'm still seeing very poor performance with this even though this bug was marked as being closed in 11.1.0, and I'm on 11.1.1.

What is this stored procedure anyway?

I have like 1.5 million rows in the ecfversion table and I think it doesn't like this. Every instance of where this stored proc was hit, it returned 0 records and took forever. To test, I commented out the innards of the stored procedure, and replaced it with an empty query that returned the same columns. My publish is flying now.

Obviously this isn't a long term solution. What should my next steps be? Contact Episerver support services?

-Paul

#182097
Sep 08, 2017 21:45
Quan Mai
Quan Mai
Vote:
 

<p>That is very strange. I suspect you might be experiencing "parameter sniff" problem. If you run the query which takes 36 seconds, how does the execution plan look like? Can you export it and post it here?</p>

#182098
Sep 09, 2017 0:17
Paul A
Paul A
Vote:
 

I had a simular issue before with a different stored proc, but that issue was resolved when I cleared statistics. I tried clearing it again to see if it would fix this issue, and it did nothing.

-Paul

#182131
Sep 11, 2017 14:54
Quan Mai
Quan Mai
Vote:
 

If you have few minutes to spare (to grab the execution plans and post them here) - I'd be happy to look into them :) 

#182133
Sep 11, 2017 15:02
Paul A
Paul A
Vote:
 

I just got an execution plan. You can find it here.

https://drive.google.com/file/d/0B8wuTg7wzPjYbGVtTVlRZ1lpLTA/view?usp=sharing

I uploaded it to my google drive, which makes it show up as an audio file but if you download it, it should open correctly.

Once again, thanks for you help with this Quan.

-Paul

#182136
Sep 11, 2017 15:38
Paul A
Paul A
Vote:
 

Just a heads up, I did just submit a support request for this issue.

#182137
Sep 11, 2017 15:48
Quan Mai
Quan Mai
Vote:
 

I'm looking into the execution plan. However this is running with status = 6, so this is to load the delayed publish versions (i.e. it's used to run the Publish deplayed publish versions scheduled job).

I'm not sure why this is related to your publishing ...

#182139
Sep 11, 2017 16:14
Paul A
Paul A
Vote:
 

Not sure what you mean by a status = 6. The stored procedure I'm running to test/the one I've seen in sql profiler while publishing is..

declare @p3 dbo.udttIdTable 
insert into @p3 values(6)

exec ecfVersion_ListFiltered @StartIndex=0,@MaxRows=2147483646,@Statuses=@p3 
go

#182143
Sep 11, 2017 16:44
Paul A
Paul A
Vote:
 

ah, I just realized what you're saying. You're refering too... insert into @p3 values(6).

I'm not sure exactly why this is being called, but it is. Consistantly. And we've edited nothing that should change this.

#182144
Sep 11, 2017 16:45
Quan Mai
Quan Mai
Vote:
 

One way to resolve the problem, is to run the scheduled job I mentioned - Publish Delayed Content Versions - which will publish the delayed publish versions and make that specific query very fast (as there is no "Delayed publish version" in ecfVersion)

I'll look into why it's called. I would say it has no reason to run - but there might be something I don't know. 

#182146
Sep 11, 2017 16:54
Paul A
Paul A
Vote:
 

Would you be able to point me to a good resource on how to run this job? 

I do see something that sounds like what you're saying in the CMS admin, but it says it's running with no issues.

#182147
Sep 11, 2017 16:59
Quan Mai
Quan Mai
Vote:
 

Now it's the interesting part, I modified the SP to be like this

ALTER PROCEDURE [dbo].[ecfVersion_ListFiltered]
(
    @ObjectId INT = NULL,
    @ObjectTypeId INT = NULL,
    @ModifiedBy NVARCHAR(255) = NULL,
    @Languages [udttLanguageCode] READONLY,
    @Statuses [udttIdTable] READONLY,
    @StartIndex INT,
    @MaxRows INT
)
AS

BEGIN    
    SET NOCOUNT ON

    DECLARE @StatusCount INT
    SELECT @StatusCount = COUNT(*) FROM @Statuses

    DECLARE @LanguageCount INT
    SELECT @LanguageCount = COUNT(*) FROM @Languages

	DECLARE @status INT 
	SET @status = (SELECT TOP 1 Id FROM @Statuses)
	IF (@StatusCount = 1 AND @status = 6)
	BEGIN
	 RAISERROR (15600,-1,-1, 'Whyyyy');  

	END

    
    IF @StartIndex = 0 AND @MaxRows = 2147483646
    BEGIN
        SELECT WorkId, ObjectId, ObjectTypeId, Name, LanguageName, MasterLanguageName, IsCommonDraft, StartPublish, ModifiedBy, Modified, [Status]
        FROM
            dbo.ecfVersion vn
        WHERE
            [dbo].ecf_IsCurrentLanguageRemoved(vn.CatalogId, vn.LanguageName) = 0 AND
            ((@ObjectId IS NULL) OR vn.ObjectId = @ObjectId) AND
            ((@ObjectTypeId IS NULL) OR vn.ObjectTypeId = @ObjectTypeId) AND
            ((@ModifiedBy IS NULL) OR vn.ModifiedBy = @ModifiedBy) AND
            ((@StatusCount = 0) OR (vn.[Status] IN (SELECT ID FROM @Statuses))) AND
            ((@LanguageCount = 0) OR (vn.LanguageName IN (SELECT LanguageCode FROM @Languages)))
    END
    ELSE
    BEGIN
    ;WITH TempResult as
    (
        SELECT ROW_NUMBER() OVER(ORDER BY vn.Modified DESC) as RowNumber, vn.*
        FROM
            dbo.ecfVersion vn
        WHERE
            [dbo].ecf_IsCurrentLanguageRemoved(vn.CatalogId, vn.LanguageName) = 0 AND
            ((@ObjectId IS NULL) OR vn.ObjectId = @ObjectId) AND
            ((@ObjectTypeId IS NULL) OR vn.ObjectTypeId = @ObjectTypeId) AND
            ((@ModifiedBy IS NULL) OR vn.ModifiedBy = @ModifiedBy) AND
            ((@StatusCount = 0) OR (vn.[Status] IN (SELECT ID FROM @Statuses))) AND
            ((@LanguageCount = 0) OR (vn.LanguageName IN (SELECT LanguageCode FROM @Languages)))
    )
    
    SELECT  WorkId, ObjectId, ObjectTypeId, Name, LanguageName, MasterLanguageName, IsCommonDraft, StartPublish, ModifiedBy, Modified, [Status], (SELECT COUNT(*) FROM TempResult) AS TotalRows
    FROM    TempResult
    WHERE    RowNumber BETWEEN (@StartIndex + 1) AND (@MaxRows + @StartIndex)
    END
           
END

So if it's called with the parameter as you tried, it would raise an error. 

  • Tried with the scheduled job, it throws error, so it works as expected.
  • Tried publishing a product. everything went smooth as butter :)

Can you try the same on your machine?

#182148
Sep 11, 2017 17:01
Paul A
Paul A
Vote:
 

That's didn't help performance, but I modified it slightly and now it's great.

The problem was that RAISEERROR doesn't actually stop the stored procedure from continuing to execute, it just raises an error. I added a RETURN below that and it's lightning now.

Here's my full query...

RAISERROR 
USE [EPiServer.CommerceManager]
GO

/****** Object:  StoredProcedure [dbo].[ecfVersion_ListFiltered]    Script Date: 9/11/2017 11:11:26 AM ******/
SET ANSI_NULLS ON
GO

SET QUOTED_IDENTIFIER ON
GO

ALTER PROCEDURE [dbo].[ecfVersion_ListFiltered]
(
    @ObjectId INT = NULL,
    @ObjectTypeId INT = NULL,
    @ModifiedBy NVARCHAR(255) = NULL,
    @Languages [udttLanguageCode] READONLY,
    @Statuses [udttIdTable] READONLY,
    @StartIndex INT,
    @MaxRows INT
)
AS

BEGIN    
    SET NOCOUNT ON

    DECLARE @StatusCount INT
    SELECT @StatusCount = COUNT(*) FROM @Statuses

    DECLARE @LanguageCount INT
    SELECT @LanguageCount = COUNT(*) FROM @Languages

	DECLARE @status INT 
	SET @status = (SELECT TOP 1 Id FROM @Statuses)
	IF (@StatusCount = 1 AND @status = 6)
	BEGIN
	 RAISERROR (15600,-1,-1, 'Whyyyy');  
	 RETURN;

	END

    
    IF @StartIndex = 0 AND @MaxRows = 2147483646
    BEGIN
        SELECT WorkId, ObjectId, ObjectTypeId, Name, LanguageName, MasterLanguageName, IsCommonDraft, StartPublish, ModifiedBy, Modified, [Status]
        FROM
            dbo.ecfVersion vn
        WHERE
            [dbo].ecf_IsCurrentLanguageRemoved(vn.CatalogId, vn.LanguageName) = 0 AND
            ((@ObjectId IS NULL) OR vn.ObjectId = @ObjectId) AND
            ((@ObjectTypeId IS NULL) OR vn.ObjectTypeId = @ObjectTypeId) AND
            ((@ModifiedBy IS NULL) OR vn.ModifiedBy = @ModifiedBy) AND
            ((@StatusCount = 0) OR (vn.[Status] IN (SELECT ID FROM @Statuses))) AND
            ((@LanguageCount = 0) OR (vn.LanguageName IN (SELECT LanguageCode FROM @Languages)))
    END
    ELSE
    BEGIN
    ;WITH TempResult as
    (
        SELECT ROW_NUMBER() OVER(ORDER BY vn.Modified DESC) as RowNumber, vn.*
        FROM
            dbo.ecfVersion vn
        WHERE
            [dbo].ecf_IsCurrentLanguageRemoved(vn.CatalogId, vn.LanguageName) = 0 AND
            ((@ObjectId IS NULL) OR vn.ObjectId = @ObjectId) AND
            ((@ObjectTypeId IS NULL) OR vn.ObjectTypeId = @ObjectTypeId) AND
            ((@ModifiedBy IS NULL) OR vn.ModifiedBy = @ModifiedBy) AND
            ((@StatusCount = 0) OR (vn.[Status] IN (SELECT ID FROM @Statuses))) AND
            ((@LanguageCount = 0) OR (vn.LanguageName IN (SELECT LanguageCode FROM @Languages)))
    )
    
    SELECT  WorkId, ObjectId, ObjectTypeId, Name, LanguageName, MasterLanguageName, IsCommonDraft, StartPublish, ModifiedBy, Modified, [Status], (SELECT COUNT(*) FROM TempResult) AS TotalRows
    FROM    TempResult
    WHERE    RowNumber BETWEEN (@StartIndex + 1) AND (@MaxRows + @StartIndex)
    END
           
END
GO
#182149
Sep 11, 2017 17:23
Paul A
Paul A
Vote:
 

So typically I don't like adding modified stored procedures to my production envionrmnet until it's officially sanctioned? You wrote this, so I do feel better about it than if I'd written it. Is there any way we could get this added to a future epi release?

-Paul

#182150
Sep 11, 2017 17:25
Quan Mai
Quan Mai
Vote:
 

No, the point is not to making it fast. The point is to find out which code called that SP. With that raiseerror you should be able to see the exception, and from stacktrace we can trace which code called that SP.

When we know that we might find a way to fix it, but that change was not intended to fix the performance issue. 

#182151
Sep 11, 2017 17:27
Paul A
Paul A
Vote:
 

Here's my logged error.

Error Number:15600,State:1,Class:15
2017-09-11 11:54:53,983 [7] ERROR EPiServer.Cms.Shell.Workspace.Committers.Internal.ContentDataCommitter: Unexpected error when saving 1073742426_469883_CatalogContent
System.Data.SqlClient.SqlException (0x80131904): An invalid parameter or option was specified for procedure 'Whyyyy'.
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.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
at EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute[TResult](Func`1 method)
at Mediachase.Data.Provider.SqlDataProvider.LoadReader(DataCommand command)
at Mediachase.MetaDataPlus.Common.DBHelper.ExecuteReader(String connectionString, CommandType commandType, String commandText, DataParameter[] commandParameters)
at EPiServer.Commerce.Catalog.DataAccess.CatalogContentVersionDB.ExecuteSproc[T](Func`5 dbExecutor, String sproc, IEnumerable`1 parameters)
at EPiServer.Commerce.Catalog.DataAccess.CatalogContentVersionDB.List(VersionFilter filter, Int32 startIndex, Int32 maxRows)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.<>c__DisplayClass26_0.<List>b__9()
at EPiServer.Framework.Cache.ObjectInstanceCacheExtensions.ReadThroughWithWait[T](IObjectInstanceCache cache, String cacheKey, Func`1 readValue, Func`2 evictionPolicy)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.List(VersionFilter filter, Int32 startIndex, Int32 maxRows, Int32& totalCount)
at EPiServer.Core.IContentVersionRepositoryExtensions.ListDelayedPublish(IContentVersionRepository contentVersionRepository)
at EPiServer.Commerce.Catalog.Provider.CatalogContentProvider.ListDelayedPublish()
at EPiServer.Core.Internal.DefaultContentRepository.<>c__DisplayClass45_0.<ListDelayedPublish>b__0(ContentProvider contentProvider)
at EPiServer.Core.ContentProviderMap.Iterate(Action`1 contentProviderHandler)
at EPiServer.Core.Internal.DefaultContentRepository.ListDelayedPublish()
at EPiServer.ContentCollaboration.CMSContentCollaborationBroadcaster.contentEvents_PublishingContent(Object sender, ContentEventArgs e)
at System.EventHandler`1.Invoke(Object sender, TEventArgs e)
at EPiServer.Core.Internal.DefaultContentEvents.RaiseCancellableContentEvent(String key, String defaultReason, ContentEventArgs eventArgs)
at EPiServer.Core.Internal.DefaultContentRepository.RaisePreSaveEvents(SaveContentEventArgs eventArgs, StatusTransition transition, Boolean isNew, Boolean isNewLanguageBranch)
at EPiServer.Core.Internal.DefaultContentRepository.Save(IContent content, SaveAction action, AccessLevel access)
at EPiServer.Cms.Shell.Service.Internal.ContentService.Save(IContent content, SaveAction saveAction, AccessLevel accessLevel)
at EPiServer.Cms.Shell.Workspace.Committers.Internal.ContentDataCommitter.Commit(EditContentData change, CommitArguments argument)
ClientConnectionId:e2faf39f-64e4-4e1a-92de-d83ab3f4d590
Error Number:15600,State:1,Class:15
System.Data.SqlClient.SqlException (0x80131904): An invalid parameter or option was specified for procedure 'Whyyyy'.
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.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior)
at EPiServer.Data.Providers.SqlTransientErrorsRetryPolicy.Execute[TResult](Func`1 method)
at Mediachase.Data.Provider.SqlDataProvider.LoadReader(DataCommand command)
at Mediachase.MetaDataPlus.Common.DBHelper.ExecuteReader(String connectionString, CommandType commandType, String commandText, DataParameter[] commandParameters)
at EPiServer.Commerce.Catalog.DataAccess.CatalogContentVersionDB.ExecuteSproc[T](Func`5 dbExecutor, String sproc, IEnumerable`1 parameters)
at EPiServer.Commerce.Catalog.DataAccess.CatalogContentVersionDB.List(VersionFilter filter, Int32 startIndex, Int32 maxRows)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.<>c__DisplayClass26_0.<List>b__9()
at EPiServer.Framework.Cache.ObjectInstanceCacheExtensions.ReadThroughWithWait[T](IObjectInstanceCache cache, String cacheKey, Func`1 readValue, Func`2 evictionPolicy)
at EPiServer.Commerce.Catalog.Provider.CatalogContentVersionStore.List(VersionFilter filter, Int32 startIndex, Int32 maxRows, Int32& totalCount)
at EPiServer.Core.IContentVersionRepositoryExtensions.ListDelayedPublish(IContentVersionRepository contentVersionRepository)
at EPiServer.Commerce.Catalog.Provider.CatalogContentProvider.ListDelayedPublish()
at EPiServer.Core.Internal.DefaultContentRepository.<>c__DisplayClass45_0.<ListDelayedPublish>b__0(ContentProvider contentProvider)
at EPiServer.Core.ContentProviderMap.Iterate(Action`1 contentProviderHandler)
at EPiServer.Core.Internal.DefaultContentRepository.ListDelayedPublish()
at EPiServer.ContentCollaboration.CMSContentCollaborationBroadcaster.contentEvents_PublishingContent(Object sender, ContentEventArgs e)
at System.EventHandler`1.Invoke(Object sender, TEventArgs e)
at EPiServer.Core.Internal.DefaultContentEvents.RaiseCancellableContentEvent(String key, String defaultReason, ContentEventArgs eventArgs)
at EPiServer.Core.Internal.DefaultContentRepository.RaisePreSaveEvents(SaveContentEventArgs eventArgs, StatusTransition transition, Boolean isNew, Boolean isNewLanguageBranch)
at EPiServer.Core.Internal.DefaultContentRepository.Save(IContent content, SaveAction action, AccessLevel access)
at EPiServer.Cms.Shell.Service.Internal.ContentService.Save(IContent content, SaveAction saveAction, AccessLevel accessLevel)
at EPiServer.Cms.Shell.Workspace.Committers.Internal.ContentDataCommitter.Commit(EditContentData change, CommitArguments argument)
ClientConnectionId:e2faf39f-64e4-4e1a-92de-d83ab3f4d590

#182155
Sep 11, 2017 17:56
Magnus Rahl
Magnus Rahl
Vote:
 

Apparently this relates to the Content Collaboration add-on. It listens to the events raised when saving content and decides tocall ListDelayedPublish. I guess every time if you consistently see this slowness. 

Are you actively using this add-on or is it something that you could uninstall to be able to move on (then we should of course continue to figure out why the add-on has this behavior)?

#182156
Sep 11, 2017 19:59
Quan Mai
Quan Mai
Vote:
 

I still wonder why the scheduled job was very fast before and then suddenly it took 15 seconds. It's worth noting that it is very hard, if not impossible to optimize the SP when it comes to statuses, because there are only maximum 8 values of them, (normally, only 4 or 5), so adding an index here is not gonna help.

#182161
Sep 12, 2017 8:20
Magnus Rahl
Magnus Rahl
Vote:
 

Unverified speculation: Maybe the scheduled job uses paging when pulling the result and the Content Collaboration code does not? When paging is specified, it uses another branch of the sproc.

#182162
Sep 12, 2017 8:28
Quan Mai
Quan Mai
Vote:
 

That should not be the case - we only have one ecfVersion_ListFiltered, and the paging is actually heavier than without the paging 

#182166
Sep 12, 2017 8:57
Paul A
Paul A
Vote:
 

When this job runs, it takes about 16 to 18 seconds. Because you put that increase into question, I looked into this and that low was artificially deflated because during my testing I commented out the inside of that stored procedure and had it return an empty result set that matched the stored procedures return result.

Then when it went back up was when I restored the original stored proc. You can see now, it's pretty consistant.

#182217
Sep 12, 2017 15:27
Paul A
Paul A
Vote:
 

Removing the content collaboration module fixed this issue for me. Looking at it, it looks like this module hasn't been updated for the most recent version anyway. We removed it and it's working fast now.

#182218
Sep 12, 2017 15:29
Paul A
Paul A
Vote:
 

Could you guys report this as a ContentCollaboration bug? I looked and it doesn't appear I have the ability to submit bugs.

#182219
Sep 12, 2017 15:30
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.