Help me tune the long-running query

Question

I have a problem with the following query executing from the application (Microsoft Dynamics AX):

DECLARE @p1 INT;
SET @p1 = NULL;
DECLARE @p2 INT;
SET @p2 = 0;
DECLARE @p5 INT;
SET @p5 = 2 + 4096;
DECLARE @p6 INT;
SET @p6 = 8193;
DECLARE @p7 INT;
SET @p7 = 0;
EXEC sp_cursorprepexec
     @p1 OUTPUT,
     @p2 OUTPUT,
     N'@P1 nvarchar(5),@P2 int,@P3 nvarchar(5),@P4 int,@P5 nvarchar(5),@P6 nvarchar(5),@P7 datetime,@P8 nvarchar(21),@P9 numeric(28, 12)',
     N'SELECT A.INVENTTRANSIDFATHER,B.INVENTTRANSID,B.TRANSREFID,C.MODELGROUPID,C.COSTGROUPID,C.DIMENSION,C.DIMENSION2_,C.DIMENSION3_ FROM INVENTTRANS A,INVENTTRANS B,INVENTTABLE C WHERE ((A.DATAAREAID=@P1) AND (A.TRANSTYPE=@P2)) AND ((B.DATAAREAID=@P3) AND (((B.INVENTTRANSID=A.INVENTTRANSIDFATHER) AND (B.TRANSREFID=A.TRANSREFID)) AND (B.TRANSTYPE=@P4))) AND ((C.DATAAREAID=@P5) AND (C.ITEMID=B.ITEMID)) 
AND EXISTS (SELECT ''x'' FROM INVENTSETTLEMENT D WHERE ((D.DATAAREAID=@P6) AND ((((D.TRANSDATE=@P7) AND (D.VOUCHER=@P8)) AND (D.TRANSRECID=A.RECID)) AND (D.COSTAMOUNTADJUSTMENT<>@P9))))
 GROUP BY A.INVENTTRANSIDFATHER,B.INVENTTRANSID,B.TRANSREFID,C.MODELGROUPID,C.COSTGROUPID,C.DIMENSION,C.DIMENSION2_,C.DIMENSION3_ ORDER BY B.INVENTTRANSID,B.TRANSREFID,C.MODELGROUPID,C.COSTGROUPID,C.DIMENSION,C.DIMENSION2_,C.DIMENSION3_',
     @p5 OUTPUT,
     @p6 OUTPUT,
     @p7 OUTPUT,
     N'dat',
     8,
     N'dat',
     2,
     N'dat',
     N'dat',
     '2017-05-17 00:00:00.000',
     N'IM17008141934',
     '0.000000000000';
EXEC sp_cursorfetch
     @p2,
     2,
     1,
     1;

The estimated plan for this query is here

XML version here

The query keeps running for almost 3 hours. I have also captured metrics from WhoIsActive sp for this queries session:

wait_info                       (2ms)PAGEIOLATCH_SH:ecc_wrk:4(*)     
CPU                             88,765
CPU_delta                       47
tempdb_allocations              0
tempdb_current                  0
tempdb_allocations_delta        0   
tempdb_current_delta            0
blocking_session_id             NULL
blocked_session_count           16
reads                           26,610,593
reads_delta                     20,903
writes                          0
writes_delta                    0
physical_reads                  1,212,764
physical_reads_delta            418 
used_memory used_memory_delta   276 
status                          0
open_tran_count                 1
host_name                       ***
database_name                   ***
program_name                    Microsoft Dynamics AX

As I can see it reads huge amount of data and executes for enormous amount of time. I also captured the query and executed it in management studio where it took 1 second to complete. The actual execution plan is here:

XML version here

I cannot understand what the problem might me and where to dig. Any help on what to do next will be deeply appreciated.

score 10 · Accepted Answer · answered May 23 '17 at 13:37

First of all, the code you posted is not the code executed by the application. There is no Fetch Queryoperator so you aren't retrieving any rows.

As you noted in chat you constructed the code yourself but it's hard to guess what exactly will be the code executed by AX, that depends on some settings and calculations done by the AX kernel.

First of all, your cursor is likely to be FAST_FORWARD and the number of rows fetched could either be everything at once, or a number of records at a time.

The number of rows fetched at once is defined by the Maximum Buffer Size parameter/the row size. See Microsoft Dynamics AX 2012 Server Configuration

The cursor definition will look something like this

declare @p1 int
set @p1=189527589
declare @p3 int
set @p3=16
declare @p4 int
set @p4=1
declare @p5 int
set @p5=2
exec sp_cursoropen @p1 output,N'SELECT A.JOBTYPE FROM PRODROUTEJOB A WHERE ((A.DATAAREAID=N''IW'') AND ((A.CALCTIMEHOURS<>0) AND (A.JOBTYPE<>3))) AND EXISTS (SELECT ''X'' FROM PRODROUTE B WHERE ((B.DATAAREAID=N''IW'') AND (((((B.PRODID=A.PRODID) AND ((B.PROPERTYID=N''PR1526157'') OR (B.PRODID=N''PR1526157''))) AND (B.OPRNUM=A.OPRNUM)) AND (B.OPRPRIORITY=A.OPRPRIORITY)) AND (B.OPRID=N''GRIJZEN''))) AND NOT EXISTS (SELECT ''X'' FROM ADUSHOPFLOORROUTE C WHERE ((C.DATAAREAID=N''IW'') AND ((((((C.WRKCTRID=A.WRKCTRID) AND (C.PRODID=B.PRODID)) AND (C.OPRID=B.OPRID)) AND (C.JOBTYPE=A.JOBTYPE)) AND (C.FROMDATE>{TS ''1900-01-01 00:00:00.000''})) AND ((C.TODATE={TS ''1900-01-01 00:00:00.000''})))))) GROUP BY A.JOBTYPE ORDER BY A.JOBTYPE ',@p3 output,@p4 output,@p5 output
select @p1, @p3, @p4, @p5

or this

declare @p1 int
set @p1=NULL
declare @p2 int
set @p2=0
declare @p5 int
--
-- Fast Forward(16)+Parameterized(4096)+AutoFetch(8192)+AutoClose(16384)
--
set @p5=16+4096+8192
declare @p6 int
set @p6=8193
declare @p7 int
--
-- Number of Rows for AutoFetch. 
-- This is calculated by Maximum Buffer Size (24K default) / Row Length
--
set @p7=4
exec sp_cursorprepexec @p1 output,@p2 output,N'@P1 nvarchar(5),@P2 nvarchar(21)',N'SELECT A.SALESID,A.RECID FROM SALESLINE A WHERE ((DATAAREAID=@P1) AND (SALESID>@P2))',@p5 output,@p6 output,@p7 output,N'ceu',N'SO-100004'
-- @p2 contains cursor handle for fetch call
exec sp_cursorfetch @p2,2,1,@p7

That being said, most of the time when I get a poor performing query in AX the query behaves the same with or without a cursor, and it's rare that I need the actual code including the cursors to be able to reproduce the problem in Management Studio, however if you really need the cursor definition the easiest is if you can reproduce it in a test environment.

Once you can reproduce the issue you need to locate the offending query in code.
If you can reproduce the issue in a test environment (because AX is fairly prone to parameter sniffing) you can use the built-in SQL Statement trace log to find the call stack for the query.

You can also look into the Trace Parser tool to capture traces with the actual parameter values and the code trace up to the query. That can help a lot too.

Once you know where the query is executed you could put a breakpoint just before the query and when you hit it fire up SQL Server Profiler to capture the exact code being executed while you step through the select in your AX debugger.

Once you have the problematic code (if you really need it including cursors) the regular tuning principles are valid.

Your first attempts should be indexing because your options to change the query are a bit limited in AX. Then again the estimated plan you posted only has an estimated cost of 0.04 and uses index seeks I'm not sure this is your problem.

AX is very prone to parameter sniffing because of all the select * resulting in a lot of key lookups.

You could try to use some keywords to influence the plan, namely forceliterals to disable parameterization and force a new plan to be compiled for each execution or you could set some row goals using firstfast and that's about it.

See the Select statement syntax documentation to see which options you have, but don't overdo it with the keywords (as I suggested in my answer to your other question). My first guess is you are running into parameter sniffing.

score 2 · Answer 2 · answered Jun 09 '17 at 14:31

I have managed to resolve the problem. I have run a trace and captured what was happening on the server. Tom V, thanks a lot. It was actually some form of parameter sniffing. AX first executed a query like this:

declare @p1 int
set @p1=NULL
declare @p2 int
set @p2=0
declare @p5 int
set @p5=28688
declare @p6 int
set @p6=8193
declare @p7 int
set @p7=9
exec sp_cursorprepexec @p1 output,@p2 output,N'@P1 nvarchar(5),@P2 int,@P3 nvarchar(5),@P4 int,@P5 nvarchar(5),@P6 nvarchar(5),@P7 datetime,@P8 nvarchar(21),@P9 numeric(28, 12)',N'SELECT A.INVENTTRANSIDFATHER,B.INVENTTRANSID,B.TRANSREFID,C.MODELGROUPID,C.COSTGROUPID,C.DIMENSION,C.DIMENSION2_,C.DIMENSION3_ FROM INVENTTRANS A,INVENTTRANS B,INVENTTABLE C WHERE ((A.DATAAREAID=@P1) AND (A.TRANSTYPE=@P2)) AND ((B.DATAAREAID=@P3) AND (((B.INVENTTRANSID=A.INVENTTRANSIDFATHER) AND (B.TRANSREFID=A.TRANSREFID)) AND (B.TRANSTYPE=@P4))) AND ((C.DATAAREAID=@P5) AND (C.ITEMID=B.ITEMID)) AND EXISTS (SELECT ''x'' FROM INVENTSETTLEMENT D WHERE ((D.DATAAREAID=@P6) AND ((((D.TRANSDATE=@P7) AND (D.VOUCHER=@P8)) AND (D.TRANSRECID=A.RECID)) AND (D.COSTAMOUNTADJUSTMENT<>@P9)))) GROUP BY A.INVENTTRANSIDFATHER,B.INVENTTRANSID,B.TRANSREFID,C.MODELGROUPID,C.COSTGROUPID,C.DIMENSION,C.DIMENSION2_,C.DIMENSION3_ ORDER BY B.INVENTTRANSID,B.TRANSREFID,C.MODELGROUPID,C.COSTGROUPID,C.DIMENSION,C.DIMENSION2_,C.DIMENSION3_',@p5 output,@p6 output,@p7 output,N'dat',8,N'dat',2,N'dat',N'dat','2017-06-05 00:00:00',N'IM17008151695',0.000000000000
select @p1, @p2, @p5, @p6, @p7

And then (RPC Starting event):

declare @p2 int
set @p2=0
declare @p3 int
set @p3=24592
declare @p4 int
set @p4=8193
declare @p5 int
set @p5=9
exec sp_cursorexecute 1073741872,@p2 output,@p3 output,@p4 output,@p5 output,N'dat',9,N'dat',10,N'dat',N'dat','2017-06-05 00:00:00',N'IM17008151695',0.000000000000
select @p2, @p3, @p4, @p5

Then the Profiler throwed Sort Warning and after 2 hours finally finished. As you can see in the first statement the parameter value for TransType field was "8", in the second case - "9". We resolved the issue by using forceliterals as you suggested.

Help me tune the long-running query

2 Answers2

Linked