sp_cursorprepexec causing 53 million reads?

Question

We are running a Dynamics AX 2012 installation with SQL Server 2012. I know that cursors should not be used anymore but AX is using it and we can't change this behavior so we have to work with it.

Today I caught a very bad query with over 53 million reads and an execution time greater than 20 minutes.

I caught this query via our monitoring tool SentryOne.

declare @p1 int
set @p1=1073773227
declare @p2 int
set @p2=180158805
declare @p5 int
set @p5=16
declare @p6 int
set @p6=1
declare @p7 int
set @p7=2
exec sp_cursorprepexec @p1 output,@p2 output,N'@P1 bigint,@P2 nvarchar(5),@P3 bigint,@P4 nvarchar(8),@P5 bigint,@P6 bigint,@P7 bigint,@P8 bigint,@P9 bigint,@P10 bigint,@P11 bigint,@P12 bigint,@P13 bigint,@P14 bigint,@P15 bigint,@P16 bigint,@P17 bigint,@P18 bigint,@P19 nvarchar(5),@P20 bigint,@P21 bigint,@P22 bigint,@P23 bigint,@P24 bigint',N'SELECT T1.PRODUCT,T1.EXTERNALVENDPARTY,T1.LIFECYCLESTATUS,T1.RECID,T2.ECORESPRODUCT,T2.ECORESDISTINCTPRODUCTVARIANT,T2.SGE,T2.ECORESREFORDERNUM,T2.ORDERNUM,T2.RECID,T3.ECORESREFORDERNUM,T3.NAME1,T3.NAME2,T3.NAME3,T3.RECID,T4.ECORESPRODUCT,T4.EXTERNALITEMID,T4.ECORESDISTINCTPRODUCTVARIANT,T4.RECID,T5.RECID,T5.PERSON,T6.RECID,T6.NAME,T6.INSTANCERELATIONTYPE,T7.RECID,T7.NAME,T7.INSTANCERELATIONTYPE,T8.PARTY,T8.ACCOUNTNUM,T8.RECID,T9.RECID,T9.DISPLAYPRODUCTNUMBER,T9.INSTANCERELATIONTYPE,T10.PRODUCT,T10.CATEGORY,T10.RECID,T11.RECID,T11.CODE,T11.NAME,T11.INSTANCERELATIONTYPE FROM INVENTTABLE T1 CROSS JOIN ECORESPRODUCTORDERNUM T2 CROSS JOIN ECORESPRODUCTORDERNUMTRANSLATION T3 LEFT OUTER JOIN VENDEXTERNALITEM T4 ON ((T4.PARTITION=5637144576) AND ((T2.ECORESPRODUCT=T4.ECORESPRODUCT) AND (T4.ECORESDISTINCTPRODUCTVARIANT=@P1))) CROSS JOIN HCMWORKER T5 CROSS JOIN DIRPARTYTABLE T6 CROSS JOIN DIRPARTYTABLE T7 CROSS JOIN VENDTABLE T8 CROSS JOIN ECORESPRODUCT T9 CROSS JOIN ECORESPRODUCTCATEGORY T10 CROSS JOIN ECORESCATEGORY T11 WHERE (((T1.PARTITION=5637144576) AND (T1.DATAAREAID=N''087'')) AND (T1.DATAAREAID=@P2)) AND ((T2.PARTITION=5637144576) AND ((T2.ECORESPRODUCT=T1.PRODUCT) AND (T2.SGE=@P3))) AND ((T3.PARTITION=5637144576) AND ((T3.ECORESREFORDERNUM=T2.ECORESREFORDERNUM) AND (T3.LANGUAGEID=@P4))) AND ((T5.PARTITION=5637144576) AND (T5.RECID=T2.PRODUCTMANAGER)) AND (((T6.PARTITION=5637144576) AND (T6.INSTANCERELATIONTYPE IN (@P5,@P6,@P7,@P8,@P9,@P10,@P11) )) AND (T6.RECID=T5.PERSON)) AND (((T7.PARTITION=5637144576) AND (T7.INSTANCERELATIONTYPE IN (@P12,@P13,@P14,@P15,@P16,@P17,@P18) )) AND (T1.EXTERNALVENDPARTY=T7.RECID)) AND (((T8.PARTITION=5637144576) AND (T8.DATAAREAID=N''087'')) AND ((T7.RECID=T8.PARTY) AND (T8.DATAAREAID=@P19))) AND (((T9.PARTITION=5637144576) AND (T9.INSTANCERELATIONTYPE IN (@P20,@P21,@P22) )) AND (T9.RECID=T1.PRODUCT)) AND ((T10.PARTITION=5637144576) AND (T10.PRODUCT=T9.RECID)) AND (((T11.PARTITION=5637144576) AND (T11.INSTANCERELATIONTYPE IN (@P23,@P24) )) AND (T11.RECID=T10.CATEGORY))',@p5 output,@p6 output,@p7 output,0,N'087',5637146082,N'de',41,2303,2377,2975,2978,5329,6886,41,2303,2377,2975,2978,5329,6886,N'087',3265,3266,3267,2665,4423
select @p1, @p2, @p5, @p6, @p7

The first thing I noticed is that this query was using a cursor. Out of curiosity I copied the statement and executed it in Management Studio without the cursor stuff (I have to admit that I replaced the parameters for the query so I could run it). Within SSMS the query finished in 30 seconds. Not very fast, but still faster than the cursor alternative.

Here I provide you both plans:

• Plan with cursor: https://www.brentozar.com/pastetheplan/?id=Sk0aMY-Y-
• Plan without cursor: https://www.brentozar.com/pastetheplan/?id=HJ6ImtWK-

The plan without the cursor is still a very bad plan but it is much better. My question here is: Can someone please explain to me why the cursor version needs 53 million reads?

Stats for query with cursor:

Duration    CPU         Reads       Writes  Est Rows    Actual Rows
1.396.212   1.379.157   53.270.895  3.878   30          2

Stats for query without cursor:

Duration    CPU         Reads       Writes  Est Rows    Actual Rows
23.337      1.703       665.113     13      4.287       34.813

It does seem weird to get 34,813 rows instead of 2; but I am pretty sure that I filled in the right parameters. I thought that this was maybe a funny quirk from SQL Sentry since I just copied the stats from there.

I hope I could provide you all the necessary information for you. Also if anyone has some good readings the better understand cursors that would be great.

Answer 1

First of all, it surprises me that the actual number of rows for both queries from SQL Sentry isn't more or less the same.

Second. It's hard to tell how correct your estimates are in the plan with a cursor without an actual plan but some things stand out to me. (P.S.: refer to my answer here to get an actual plan).

That being said, there are a couple of things that can be noted from your estimated plan.

There is a warning about unmatched indexes due to parametrization. Removing parametrization so SQL Server can use those unmatched could dramatically improve I/O.

The estimated number of rows between the 2 plans is off dramatically too. In your plan with a cursor you have an estimated number of rows from vendexternalitem of 11. In your plan without a cursor you have an estimated and actual number of rows of almost 200K. If your 200K records actually go into that spool operator that could be painful.

All the operators have wildly different estimates (much smaller in the plan with a cursor), so maybe your plan was compiled and cached with different parameter values than you are using in the query without a cursor. (known as parameter sniffing)

There is also a very strange choice in the index seek + key lookup on the invent table. The plan is using typeIdx and then does key lookups to the clustered index (itemidx). If your estimates are off there and SQL Server has to do a lot of key lookups that could explain a lot of IO too. I'm not familiar with the stopidx you have in your plan without a cursor but it looks as if it's covering so that's probably a better choice for the parameters you provided. I suppose it picked the typeidx because it's much narrower but that could be due to different compile time values than you are providing with the problematic execution.

In short, I would remove the parametrization for this query in AX so it generates a plan with the actual values so it picks the "better" indexes as evidenced by the plan (and execution times) in SSMS. This would also allow SQL Server to use the filtered indexes. In order to do so, have a developer add the forceliterals keyword in the application code where this query is executed and see what happens.

That would probably still leave you with a query that takes 30 seconds (similar to what you have in SSMS) but that's just a matter of tuning. There are missing index warnings in your plans and I think an index on ecoresproductordernum.sge could help for example but I don't know those tables and think they are added by customizations. General tuning principles would help here but that would probably be too broad for this answer (covering indexes, ...)