SQL Server Forums
Profile | Register | Active Topics | Members | Search | Forum FAQ
 
Register Now and get your question answered!
Username:
Password:
Save Password
Forgot your Password?

 All Forums
 SQL Server 2008 Forums
 Transact-SQL (2008)
 Query slow from application, fast in SSMS
 New Topic  Reply to Topic
 Printer Friendly
Author Previous Topic Topic Next Topic  

andrzej.simin
Starting Member

6 Posts

Posted - 08/20/2013 :  06:26:45  Show Profile  Reply with Quote
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

Canada
591 Posts

Posted - 08/20/2013 :  10:37:21  Show Profile  Reply with Quote
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?
Go to Top of Page

andrzej.simin
Starting Member

6 Posts

Posted - 08/20/2013 :  16:51:20  Show Profile  Reply with Quote
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?

Edited by - andrzej.simin on 08/20/2013 16:53:52
Go to Top of Page

robvolk
Most Valuable Yak

USA
15663 Posts

Posted - 08/20/2013 :  20:05:32  Show Profile  Visit robvolk's Homepage  Reply with Quote
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?
Go to Top of Page

andrzej.simin
Starting Member

6 Posts

Posted - 08/21/2013 :  14:24:31  Show Profile  Reply with Quote
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...
Go to Top of Page

lazerath
Constraint Violating Yak Guru

USA
328 Posts

Posted - 08/21/2013 :  14:51:34  Show Profile  Reply with Quote
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?
Go to Top of Page

andrzej.simin
Starting Member

6 Posts

Posted - 08/21/2013 :  15:06:42  Show Profile  Reply with Quote
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.

Edited by - andrzej.simin on 08/21/2013 15:12:31
Go to Top of Page

andrzej.simin
Starting Member

6 Posts

Posted - 08/21/2013 :  15:26:30  Show Profile  Reply with Quote
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!!

Edited by - andrzej.simin on 08/21/2013 15:33:18
Go to Top of Page

lazerath
Constraint Violating Yak Guru

USA
328 Posts

Posted - 08/22/2013 :  10:10:27  Show Profile  Reply with Quote
Great! Now you can look into the execution plan and see whats up or find & change the setting that is giving you problems.
Go to Top of Page

andrzej.simin
Starting Member

6 Posts

Posted - 08/22/2013 :  10:57:47  Show Profile  Reply with Quote
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!
Go to Top of Page
  Previous Topic Topic Next Topic  
 New Topic  Reply to Topic
 Printer Friendly
Jump To:
SQL Server Forums © 2000-2009 SQLTeam Publishing, LLC Go To Top Of Page
This page was generated in 0.09 seconds. Powered By: Snitz Forums 2000