Query slow from application, fast in SSMS

Please start any new threads on our new site at https://forums.sqlteam.com. We've got lots of great SQL Server experts to answer whatever question you can come up with.

All Forums

SQL Server 2008 Forums

Transact-SQL (2008)

Query slow from application, fast in SSMS

Author

Topic

andrzej.simin
Starting Member

6 Posts

Posted - 2013-08-20 : 06:26:45

Hi all,

I have big problem with single select query.

Quick DB/app description:
DB stores documents information and parameters for processes assigned to this documents.
Query is supposed to find all processes for selected document, and return in single row process information and document information.

Query code:

SELECT DISTINCT
	P.NAME NAME, 
	P.START_ STARTDATE, 
	(
		SELECT 
			par.PARAMVALUE 
		FROM 
			PARAMS AS par 
		WHERE 
			par.PROCID=P.DBID_ 
			AND par.PARAMNAME='val1'
	), 
	COL8, 
	COL4, 
	COL6, 
	COL5, 
	d.BARCODE 
FROM 
	PROCESSES AS P 
	LEFT JOIN 
		PARAMS AS par1 ON P.DBID_=par1.PROCID 
	LEFT JOIN 
		PARAMS AS par2 ON P.DBID_=par2.PROCID
	LEFT JOIN 
		(
		SELECT 
			DOCID, 
			COL1, 
			COL2, 
			COL3, 
			COL4, 
			COL5, 
			COL6, 
			COL7, 
			COL8, 
			PROCNAME 
		FROM DOCTYPE1 
		UNION 
		SELECT 
			DOCID, 
			COL1, 
			COL2, 
			COL3, 
			COL4,
			COL5, 
			COL6, 
			COL7, 
			COL8, 
			PROCNAME 
		FROM DOCTYPE2 
		UNION 
		SELECT 
			DOCID, 
			COL1, 
			COL2, 
			COL3, 
			COL4, 
			COL5, 
			COL6, 
			COL7, 
			COL8, 
			PROCNAME 
		FROM DOCTYPE3
		) AS DocDetails ON CAST (DocDetails.DOCID AS VARCHAR(50)) = par2.PARAMVALUE 
	LEFT JOIN 
		DOCS d ON DocDetails.DOCID=d.DOCID 
WHERE  
	LOWER(P.NAME) LIKE '%val2%' 
	AND (  (LOWER(DocDetails.DOCID) = 123456) )  
	AND  par2.PARAMNAME='DOCID'

Problem is query executes in 3-5 seconds in SSMS, but when I execute it from application database cpu usage grows to 100% and stays there for few minutes, and i get timeouut in app.

java app, sql execute code:

NamedParameterJdbcTemplate jdbcTemplate = new NamedParameterJdbcTemplate(ds);
((JdbcTemplate)jdbcTemplate.getJdbcOperations()).setMaxRows(limit);
return jdbcTemplate.queryForList(sql, params);

Also - strange thing is, that when i change line:

) AS DocDetails ON CAST (DocDetails.DOCID as VARCHAR(50)) = par2.PARAMVALUE

to:

) AS DocDetails ON DocDetails.PROCNAME = par2.PROCNAME

query ecexutes fine in few seconds. But since this wouldn't return me more than 1 process for each document i cannot use it.

I've already read much about parameter sniffing, and i've already modified my code to check it (parameters not forwarded as parameters but in query itself - just test thing) but there was no change.

Does anyone have an idea why would exacly same query work fine in SSMS and hang whole SQL Server when executed from application?

I'm out of ideas.

Thanks in advance!
Simin

denis_the_thief
Aged Yak Warrior

596 Posts

Posted - 2013-08-20 : 10:37:21

Can you trace it through SQL Profiler?

Maybe your Java is calling it a bit differently. What do you get for the Duration in SQL Profiler?

andrzej.simin
Starting Member

6 Posts

Posted - 2013-08-20 : 16:51:20

Hi, thanks for reply!

Sql profiler after timeout occures shows me:
RCP Completed:


declare @p1 int
set @p1=NULL
exec sp_prepexec @p1 output,NULL,N'select distinct  
	P.NAME NAME,
	e.START_ STARTDATE, 
	(
		SELECT 
			par.PARAMVALUE 
		FROM 
			PARAMS AS par 
		WHERE 
			par.PROCID=P.DBID_ 
			AND par.PARAMNAME=''val1''
	), 
	COL8, 
	COL4, 
	COL6, 
	COL5, 
	d.BARCODE 
from 
	PROCESSES AS P 
	LEFT JOIN 
		PARAMS AS par1 ON P.DBID_=par1.PROCID 
	LEFT JOIN 
		PARAMS AS par2 ON P.DBID_=par2.PROCID
	LEFT JOIN 
		(
		SELECT 
			DOCID, 
			COL1, 
			COL2, 
			COL3, 
			COL4, 
			COL5, 
			COL6, 
			COL7, 
			COL8, 
			PROCNAME 
		FROM DOCTYPE1 
		UNION 
		SELECT 
			DOCID, 
			COL1, 
			COL2, 
			COL3, 
			COL4,
			COL5, 
			COL6, 
			COL7, 
			COL8, 
			PROCNAME 
		FROM DOCTYPE2 
		UNION 
		SELECT 
			DOCID, 
			COL1, 
			COL2, 
			COL3, 
			COL4, 
			COL5, 
			COL6, 
			COL7, 
			COL8, 
			PROCNAME 
		FROM DOCTYPE3
		) AS DocDetails ON CAST (DocDetails.DOCID AS VARCHAR(50)) = par2.PARAMVALUE 
	LEFT JOIN 
		DOCS d ON DocDetails.DOCID=d.DOCID 
		WHERE  
	LOWER(P.NAME) LIKE ''%val2%'' AND (  (LOWER(DocDetails.DOCID) = 123456) )  
	AND  par2.PARAMNAME=''DOCID''  '
select @p1

So query seems fine.

CPU: 300489
Reads: 1635371
Writes: 1
Duration: 310693

When executing exackly same SQL in SSMS it takes about 3.5 seconds to get full result.

Any ideas what may be wrong, or what to check next?

robvolk
Most Valuable Yak

15732 Posts

Posted - 2013-08-20 : 20:05:32

This is a guess, but it's possible the JDBC components are using cursors to iterate through the results. Did you collect SP:Starting and SP:Completed events in your profiler trace? You might want to include those, see if there are calls to sp_cursor* procedures.

Which JDBC driver are you using?

andrzej.simin
Starting Member

6 Posts

Posted - 2013-08-21 : 14:24:31

driver:

com.microsoft.sqlserver.jdbc.SQLServerXADataSource

Trace doesn't show any operations after RCP Started. Just CPU up to 100% and nothing else.

Duration is time of timeout, as i didn't get query to return any results from application.

I guess i'll try to cut some functionalities and simplify query...

lazerath
Constraint Violating Yak Guru

343 Posts

Posted - 2013-08-21 : 14:51:34

I've seen queries generate wildly different plans if the app is connecting with non-default connection settings (ANSI_WARNINGS OFF, ARITH_ABORT OFF,CONCAT_NULLS_EQUAL_NULL OFF, etc...). Maybe check that?

andrzej.simin
Starting Member

6 Posts

Posted - 2013-08-21 : 15:06:42

I have additional info.

Just checked SP_lock on DB during execution of query, and i get following result:


spid	dbid	ObjId		IndId	Type	Resource	Mode	Status
58	7	0        	0	DB			S	GRANT
58	2	0        	0	DB	ENCRYPTION_SCAN	S	GRANT
58	7	1483152329	0	TAB	                Sch-S	GRANT
58	7	935674381	0	TAB	                Sch-S	GRANT
58	7	640721335	0	HBT	BULK_OPERATION  S	GRANT
58	7	1360723900	0	TAB	                Sch-S	GRANT
58	7	55671246	0	TAB	                Sch-S	GRANT
58	7	1250103494	0	TAB	                Sch-S	GRANT
58	7	1488724356	0	TAB	                Sch-S	GRANT
58	7	640721335	0	TAB	                Sch-S	GRANT

When executed from SSMS:


spid	dbid	ObjId		IndId	Type	Resource	Mode	Status
90	7	0		0	DB			S	GRANT
90	7	1483152329	0	TAB			Sch-S	GRANT
90	7	935674381	0	TAB			Sch-S	GRANT
90	7	1360723900	0	TAB			Sch-S	GRANT
90	7	55671246	0	TAB	 	 	Sch-S	GRANT
90	7	1250103494	0	TAB	 	      	Sch-S	GRANT
90	7	1488724356	0	TAB	  		Sch-S	GRANT
90	7	640721335	0	TAB	 	    	Sch-S	GRANT

After i kill test application that executes that query, cpu utilisation on DB is still high.

When i kill that session on DB - it goes back down. Maybe this will help to find solution...

EDIT:
After testing few times, i get Bulk operation in SSMS as well (for short time), but no encryption scan.

andrzej.simin
Starting Member

6 Posts

Posted - 2013-08-21 : 15:26:30

Sorry for double post combo, but i think it'll be more clear this way:

From profiler:
-- network protocol: TCP/IP
set quoted_identifier on
set arithabort off
set numeric_roundabort off
set ansi_warnings on
set ansi_padding on
set ansi_nulls on
set concat_null_yields_null on
set cursor_close_on_commit off
set implicit_transactions off
set language us_english
set dateformat mdy
set datefirst 7
set transaction isolation level read committed

+ SET ROWCOUNT 100

- start query

- Lock:Acquired [Encryption_Scan]

- Lock:Acquired number (for example: 1:122040) (many times)

- Sort Warnings

- Lock:Acquired [BULK_OPERATION] (all the time - loop or something)

ADDED:

When running from SSMS after adding the same parameters query crashes too!!

lazerath
Constraint Violating Yak Guru

343 Posts

Posted - 2013-08-22 : 10:10:27

Great! Now you can look into the execution plan and see whats up or find & change the setting that is giving you problems.

andrzej.simin
Starting Member

6 Posts

Posted - 2013-08-22 : 10:57:47

I've found already major bug in query itself...

Someone add (LOWER(DocDetails.DOCID) = 123456) causing multiple unnecessary casts , as DOCID is integer :O

I still don't know why in SSMS it was working fine, but after fixing this, and removing one join from query (as value could be loaded later) i got results in 250 ms in SSMS and about 350 ms in application.

Shame on me for not noticing it earlier

Thanks all for help!

Subscribe to SQLTeam.com

SQLTeam.com Articles via RSS

SQLTeam.com Weblog via RSS

- Advertisement -

Resources