U4-9752 - Very slow indexing after 7.5.12 update

Created by Vilen 07 Apr 2017, 10:58:42 Updated by Dan Booth 10 Apr 2017, 15:14:17

Tags: Unscheduled Regression

Subtask of: U4-9609

After the 7.5.12 update I've faced VERY slow indexing problems. I can provide the database if it is needed. See the attached logs and files:

What did you do? I've tried to rebuild internal index

What did you expect to happen? Rebuild time in 5-10 minutes as it has been with 7.5.x This msg has been since 6.x btw

Field "parentID" is listed multiple times in the index set "InternalIndexSet". Please ensure all names are unique, Provider=InternalIndexer

What actually happened? Rebuilding for 60+ minutes

 2017-04-07 13:46:18,053 [P6764/D2/T8] INFO  UmbracoExamine.DataServices.UmbracoLogService - PerformIndexAll - End data queries - content, took 4446568ms, Provider=InternalIndexer, NodeId=-1

5 Attachments

Download ExamineIndex.config

Download ExamineSettings.config

Download UmbracoTraceLog.tambovtsev-pc.zip

Download 7.5.12-examine-sql.txt

Download UmbracoExamine.zip

Comments

Dan Booth 07 Apr 2017, 11:41:39

I've not done any tests but my subjective opinion is that the 7.5.12 seems to have regressed the speed improvements that had previously been made in (7.5.8?) Indexing. See related issue: http://issues.umbraco.org/issue/U4-9420


Jbam4d 07 Apr 2017, 14:18:55

Same issue here, upgraded our staging environment to 7.5.12 and rebuilding the examine indexes has been slow, with timeouts becoming an issue as well. MSSQL seems to be experiencing a heavy load during this process, I'll run query analyzer and post some findings.


Jbam4d 07 Apr 2017, 18:22:02

Attached is a sample of the sql server events I'm seeing when the examine indexes are rebuilt. We have around 25k published nodes, process takes around an hour. We're using a smaller SQL Server instance for our dev environment, but nonetheless this is a drastic decrease in performance from our previous version (7.5.6).

Each node gets hit with 2 queries:

18ms average execution time:

{code:lang=scala|title=Query 1}exec sp_executesql N'SELECT umbracoNode.id, cmsContentXml.[xml] FROM umbracoNode INNER JOIN cmsContentXml ON cmsContentXml.nodeId = umbracoNode.id WHERE (umbracoNode.nodeObjectType = @0) ORDER BY (umbracoNode.id) OFFSET @1 ROWS FETCH NEXT @2 ROWS ONLY',N'@0 nvarchar(40),@1 bigint,@2 bigint',@0=N'b796f64c-1f99-4ffb-b886-4bf4bc011a9c',@1=16632,@2=2 go}

7ms average execution time: {code:lang=scala|title=Query 2} exec sp_executesql N'SELECT COUNT(*) FROM umbracoNode INNER JOIN cmsContentXml ON cmsContentXml.nodeId = umbracoNode.id WHERE (umbracoNode.nodeObjectType = @0) ',N'@0 nvarchar(40)',@0=N'b796f64c-1f99-4ffb-b886-4bf4bc011a9c' go


Shannon Deminick 08 Apr 2017, 03:50:27

I sincerely apologize for this, it is absolutely my own fault and while testing this issue http://issues.umbraco.org/issue/U4-9598

I accidentally committed test values :( https://github.com/umbraco/Umbraco-CMS/blob/dev-v7/src/UmbracoExamine/UmbracoContentIndexer.cs#L39

I'll post a patch DLL to this issue asap


Shannon Deminick 08 Apr 2017, 03:59:19

You can fix this by dropping in this DLL into your /bin folder, 7.5.13 will be out by the 18th


Dan Booth 08 Apr 2017, 17:20:27

@Shandem No worries, mate! I'm sure there's not a dev alive who doesn't make the occasional cock-up. Thanks for the quick fix :)


Jbam4d 09 Apr 2017, 14:20:24

@Shandem Thanks I verified the patch has resolved our issues, indexes are built in under 15 secs now.


Shannon Deminick 10 Apr 2017, 04:47:50

thanks for testing, i'll move this to fixed and we'll get a new release out


Dan Booth 10 Apr 2017, 15:14:17

@Shandem I can also confirm that the patch fixes the issue - thanks!


Priority: Critical

Type: Bug

State: Fixed

Assignee:

Difficulty: Normal

Category:

Backwards Compatible: True

Fix Submitted:

Affected versions: 7.5.12

Due in version: 7.5.13

Sprint: Sprint 56

Story Points:

Cycle: