May 14, 2014 at 10:15 am
I have the following:
(a) One Dynamic SQL Query that takes 37 ms when run as a single query or in an SP.
(b) Three SQL Indexed View queries that take 0 ms when run together.
When i add (a) + (b) in the same SP, i should get 37 ms + 0 ms = 37ms, but NO it takes 400 ms.
I have no idea what is causing the extra 363 ms of latency.
I have looked at the execution plan, and don't see what could be causing this, but to be honest i don't have much experience with execution plans.
Any ideas?
Thanks
May 14, 2014 at 10:35 am
isuckatsql (5/14/2014)
I have the following:(a) One Dynamic SQL Query that takes 37 ms when run as a single query or in an SP.
(b) Three SQL Indexed View queries that take 0 ms when run together.
When i add (a) + (b) in the same SP, i should get 37 ms + 0 ms = 37ms, but NO it takes 400 ms.
I have no idea what is causing the extra 363 ms of latency.
I have looked at the execution plan, and don't see what could be causing this, but to be honest i don't have much experience with execution plans.
Any ideas?
Thanks
How about posting the execution plan? Without that the best we can do is guess.
_______________________________________________________________
Need help? Help us help you.
Read the article at http://www.sqlservercentral.com/articles/Best+Practices/61537/ for best practices on asking questions.
Need to split a string? Try Jeff Modens splitter http://www.sqlservercentral.com/articles/Tally+Table/72993/.
Cross Tabs and Pivots, Part 1 – Converting Rows to Columns - http://www.sqlservercentral.com/articles/T-SQL/63681/
Cross Tabs and Pivots, Part 2 - Dynamic Cross Tabs - http://www.sqlservercentral.com/articles/Crosstab/65048/
Understanding and Using APPLY (Part 1) - http://www.sqlservercentral.com/articles/APPLY/69953/
Understanding and Using APPLY (Part 2) - http://www.sqlservercentral.com/articles/APPLY/69954/
May 14, 2014 at 11:14 am
Maybe you're experiencing some kind of waits or blocking.
May 14, 2014 at 11:30 am
I am using SQL Indexed Views in this example.
I also know the dynamic sql has not been 'fixed' to protect from sql injection. Its on the todo list.
Thanks
May 14, 2014 at 12:27 pm
How are you measuring the time? From the SSMS client? That includes the time to transmit across the wires and isn't a good measure of server performance. If you really want to know exactly how much time a query takes, you should measure it using extended events.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
May 14, 2014 at 12:41 pm
Grant Fritchey (5/14/2014)
How are you measuring the time? From the SSMS client? That includes the time to transmit across the wires and isn't a good measure of server performance. If you really want to know exactly how much time a query takes, you should measure it using extended events.
'set statistics time on' at the head of the query.
Thanks
May 14, 2014 at 12:47 pm
Why are you using common table expressions here? You define this:
WITH results
AS (SELECT id,
industry1,
industry2,
industry3,
jobtitle AS title,
company AS companyname,
did,
JobDescription AS description,
begindate,
locationcity AS city,
locationstate,
employmenttype,
degreerequired,
PAYLOW,
PAYHIGH,
payper,
RowNum = ROW_NUMBER() OVER (ORDER BY (SELECT
1
))
FROM dbo.cb
WHERE 1 = 1 AND
employmenttype = 'Full-Time'
)
But then you only query this:
SELECT degreerequired,
COUNT(*) cnt
FROM results
GROUP BY degreerequired
OPTION (MAXDOP 8)
If you look at the execution plan, based on estimated cost (which may not always be accurate), this is the most expensive part of the query. The optimizer is figuring out that you're only referencing two columns in the query, but why not just reference the columns you need? Don't make the optimizer go through the simplification process. You're only working off employmenttype and degreerequired here. I'd just simplify the query.
But, anyway, you're getting a scan on this. What is the data distribution for employmenttype? It doesn't look like it's providing enough filtering. Maybe a combined index of degreerequired and employment type might work better. Just a guess not knowing the data.
But based on the plans, the last two queries are the majority of your load. But that's not necessarily the truth. I'm back to capturing the behavior using extended events in order to be sure.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
May 14, 2014 at 1:33 pm
Grant,
The Dynamic SQL CTE gets the main page data based on various selected / passed filters.
The Indexed SQL Views queries, the last three, just provide a count, so the user knows how many results are in each item.
Running just the dynamic query for Full-Time jobs.
(9 row(s) affected)
Table 'CB'. Scan count 1, logical reads 138, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'emptype'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 41 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 41 ms.
SQL Server Execution Times:
CPU time = 16 ms, elapsed time = 41 ms.
(1 row(s) affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
Running the dynamic query and employment type view
(9 row(s) affected)
Table 'CB'. Scan count 1, logical reads 138, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'emptype'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 37 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 37 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(1 row(s) affected)
Table 'emptype'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 37 ms.
(1 row(s) affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
Running the dynamic query, employment type view and state view
(9 row(s) affected)
Table 'CB'. Scan count 1, logical reads 138, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'emptype'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 34 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 34 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(1 row(s) affected)
Table 'emptype'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(53 row(s) affected)
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'CB'. Scan count 9, logical reads 2485, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 281 ms, elapsed time = 69 ms.
SQL Server Execution Times:
CPU time = 281 ms, elapsed time = 69 ms.
SQL Server Execution Times:
CPU time = 281 ms, elapsed time = 104 ms.
(1 row(s) affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
Running the dynamic query, employment type view, state view and degree view
(9 row(s) affected)
Table 'CB'. Scan count 1, logical reads 138, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'emptype'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 37 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 37 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(1 row(s) affected)
Table 'emptype'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(53 row(s) affected)
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'CB'. Scan count 9, logical reads 2485, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 296 ms, elapsed time = 65 ms.
SQL Server Execution Times:
CPU time = 296 ms, elapsed time = 65 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(8 row(s) affected)
Table 'CB'. Scan count 1, logical reads 3951, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 297 ms, elapsed time = 300 ms.
SQL Server Execution Times:
CPU time = 297 ms, elapsed time = 300 ms.
SQL Server Execution Times:
CPU time = 593 ms, elapsed time = 404 ms.
(1 row(s) affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
If i run a query on the views:
set statistics time on
set statistics io on
SELECT employmenttype, COUNT(*) cnt FROM cb
GROUP BY employmenttype
go
SELECT locationstate, COUNT(*) cnt FROM cb
GROUP BY LocationState
go
SELECT degreerequired, COUNT(*) cnt FROM cb
GROUP BY DegreeRequired
go
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
(9 row(s) affected)
Table 'emptype'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(53 row(s) affected)
Table 'statetype'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(8 row(s) affected)
Table 'degreetype'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
If i add a Where condition to the employmenttype
set statistics time on
set statistics io on
SELECT employmenttype, COUNT(*) cnt FROM cb
where employmenttype = 'Full-Time'
GROUP BY employmenttype
go
SELECT locationstate, COUNT(*) cnt FROM cb
GROUP BY LocationState
go
SELECT degreerequired, COUNT(*) cnt FROM cb
GROUP BY DegreeRequired
go
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
(1 row(s) affected)
Table 'emptype'. Scan count 0, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(53 row(s) affected)
Table 'statetype'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(8 row(s) affected)
Table 'degreetype'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
I agree that each extra View Query adds time, but it seems to be much more than necessary!
I am researching the other performance data options, but it is new to me so i'm not sure what you specifically need?
Thanks
Ian
May 14, 2014 at 3:20 pm
First thing I'd suggest is not trying to do this with stats. It's fine when collecting information for one query. As soon as you start collecting two, three, etc., it gets to be a pain to read. Instead capture the stats with extended events (I'm assuming we're on 2014 since we're in that forum). You can filter down to just the views or just the database, or whatever you need, and it'll be easy to see which run did which execution time. You can even save the runs to file for later comparison.
And my other suggestions were just based on a look through the execution plan you provided. Your query is doing a lot of work that the optimizer is just throwing out (hopefully). If you really want to tune the queries, one of the things you'll need to do is focus them. While a generic query seems like a great idea, when it comes to tuning, it just isn't. If you're going for something specific in your data, go for that specific thing. That CTE just isn't in use, so it doesn't make any sense to have it there.
By the way, just we're clear, dbo.cb is an indexed view? What's the key value on?
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
May 14, 2014 at 4:54 pm
http://www.statisticsparser.com/
Is this good enough?
May 14, 2014 at 5:08 pm
isuckatsql (5/14/2014)
http://www.statisticsparser.com/Is this good enough?
Ha! Well that is one way to do it I suppose.
You're still dealing with the fact that some of the time you're seeing is just because of moving stuff across the network and even a little observation bias (although, in most cases, especially when you're not capturing execution plans, that's pretty trivial stuff).
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
May 14, 2014 at 5:27 pm
isuckatsql (5/14/2014)
http://www.statisticsparser.com/Is this good enough?
Be careful with that. In the stats time output, some times are reported twice. The site adds them all up without deduping.
I know, because I used that site for prettifying the time stats for a 3 1/2 day long query (well, two queries). I knew for absolute fact that the query had run around 3 1/2 days, because I'd started it on the friday evening, it was still running monday evening but finished by tuesday midday. The stats parser site outputted a total execution time of 7 days (not CPU time, elapsed time)
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
May 14, 2014 at 5:29 pm
Thanks for the warning!
May 14, 2014 at 6:12 pm
http://johnsterrett.com/2013/08/07/workload-tuning-finding-top-offenders-in-sql-server-2012/
Is this a good resource for Extended Events?
I followed the video and produced the following results.
Any advice is appreciated!
"A file you attempted to upload is not a permitted type."
I guess the Extended Event file format is not allowed. May i ask why?
May 15, 2014 at 5:38 am
"By the way, just we're clear, dbo.cb is an indexed view? What's the key value on?"
dbo.cb is a Table not am Indexed View.
The primary key is ID.
Thanks
Viewing 15 posts - 1 through 15 (of 16 total)
You must be logged in to reply to this topic. Login to reply