March 28, 2009 at 8:48 pm
Hi all,
When i run specific query in Management Studio and turn on Profiler i see 51000 (this is not exact number) Reads in Profiler, but when i add
Include Actual Execution Plan in SSMS i see 510000 (this is not exact number) Reads in Profiler. Is this normal behavior?
10 times more reads? I never seen something like this before and wondering if you know why it's happening.
Thanks
March 30, 2009 at 6:49 am
When you say reads, do you mean STATISTICS IO in SSMS? Or you are referring to execution times? There is a difference there since SSMS is still showing milliseconds and profiler is showing microseconds.
Reads in STATISTICS IO are pages read, seperated into physical and logical. Reads in a trace are the number of read operations performed, inlcuding physical and logical into a single number. They won't be the same values when you look at them.
----------------------------------------------------The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood... Theodore RooseveltThe Scary DBAAuthor of: SQL Server 2017 Query Performance Tuning, 5th Edition and SQL Server Execution Plans, 3rd EditionProduct Evangelist for Red Gate Software
March 30, 2009 at 9:59 am
No, what i mean is the number of reads under Reads column in SQL Server Profiler.
When i run SP in SSMS and Include Actual Execution Plan is turn on i see different number of reads under Reads column in SQL Server Profiler than when i turn Include Actual Execution Plan off in SSMS and run exact the same SP.
I was wondering why Include Actual Execution Plan makes the number of reads in SQL Server Profiler to be 10 times more when it's on.
June 26, 2009 at 9:57 pm
Did you ever solve this one? I am having a similar experience and it is puzzling enough that I might log a case with MS Support to better understand what is happening behind the scenes.
Situation:
A slower query with scalar UDFs in the select list (inherited query, tuning without making the chop of the UDF yet but I agree with any comments that could be made about why this is bad). Anyway through tuning indexes alone I managed to get the reads (as reported through profiler) down from anywhere from 100-300GB depending on the parameters (and that is GB, the reads were like 15,000,000 --> 65,000,000 did the math to the get the size) down to a bout 1GB per execution (around 200,000 reads in profiler).
Now when I include the Actual Execution plan the reads skyrocket up to 3,000,000 on the tuned query. Turn off Actual Execution Plan (and this doesn't matter if it is on a clean/empty buffer or procedure cache). I included the sp:statement completed event to see which statements in the proc are accounting for the reads and it is the UDF calls.
With the Actual Plan off, the UDF call reports 0 per execute of the UDF (the number is probably 4 according to set statistics io on when running the actual UDF code alone). With the Actual plan included from SSMS, the udf call reports 90-->150 per UDF call.
This one is a slight puzzler to me.
__________________________________________________
Mike Walsh
SQL Server DBA
Blog - www.straightpathsql.com/blog |Twitter
June 26, 2009 at 11:11 pm
Nope, i jump to another issue and never had a chance to see where the problem is with this one. Still wondering why this is happening.
If you fon something please let me know.
June 28, 2009 at 5:24 am
mike_walsh (6/26/2009)
Did you ever solve this one? I am having a similar experience and it is puzzling enough that I might log a case with MS Support to better understand what is happening behind the scenes.Situation:
A slower query with scalar UDFs in the select list (inherited query, tuning without making the chop of the UDF yet but I agree with any comments that could be made about why this is bad). Anyway through tuning indexes alone I managed to get the reads (as reported through profiler) down from anywhere from 100-300GB depending on the parameters (and that is GB, the reads were like 15,000,000 --> 65,000,000 did the math to the get the size) down to a bout 1GB per execution (around 200,000 reads in profiler).
Now when I include the Actual Execution plan the reads skyrocket up to 3,000,000 on the tuned query. Turn off Actual Execution Plan (and this doesn't matter if it is on a clean/empty buffer or procedure cache). I included the sp:statement completed event to see which statements in the proc are accounting for the reads and it is the UDF calls.
With the Actual Plan off, the UDF call reports 0 per execute of the UDF (the number is probably 4 according to set statistics io on when running the actual UDF code alone). With the Actual plan included from SSMS, the udf call reports 90-->150 per UDF call.
This one is a slight puzzler to me.
I think I can answer that one. When you turn on the actual execution plan and run the query, the reads you're seeing in profiler include all the extra stuff to send the information back to SSMS for display. It seems really high, but the increase is understandable. How complicated are the execution plans that you're looking at? It's probably the amount of data being sent back that, operators, estimated costs, actual costs, number of rebinds... etc. You get the picture.
----------------------------------------------------The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood... Theodore RooseveltThe Scary DBAAuthor of: SQL Server 2017 Query Performance Tuning, 5th Edition and SQL Server Execution Plans, 3rd EditionProduct Evangelist for Red Gate Software
June 28, 2009 at 5:44 am
Plus it's one plan per execution of the UDF. Also, you cannot trust statistics IO when you have a udf that does any form of data access.
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
June 28, 2009 at 5:51 am
GilaMonster (6/28/2009)
Plus it's one plan per execution of the UDF. Also, you cannot trust statistics IO when you have a udf that does any form of data access.
I'm not sure I was aware of that with the execution plans. Thanks!
----------------------------------------------------The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood... Theodore RooseveltThe Scary DBAAuthor of: SQL Server 2017 Query Performance Tuning, 5th Edition and SQL Server Execution Plans, 3rd EditionProduct Evangelist for Red Gate Software
June 28, 2009 at 6:35 am
GilaMonster (6/28/2009)
Plus it's one plan per execution of the UDF. Also, you cannot trust statistics IO when you have a udf that does any form of data access.
Hey Gail -
I was aware of that. In fact when you have a UDF inside of your query you won't even see the UDF calls IO statistics it would appear.
__________________________________________________
Mike Walsh
SQL Server DBA
Blog - www.straightpathsql.com/blog |Twitter
June 28, 2009 at 6:43 am
mike_walsh (6/28/2009)
GilaMonster (6/28/2009)
Plus it's one plan per execution of the UDF. Also, you cannot trust statistics IO when you have a udf that does any form of data access.Hey Gail -
I was aware of that. In fact when you have a UDF inside of your query you won't even see the UDF calls IO statistics it would appear.
Yup.
http://sqlinthewild.co.za/index.php/2009/04/29/functions-io-statistics-and-the-execution-plan/
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
June 28, 2009 at 6:44 am
Grant Fritchey (6/28/2009)
GilaMonster (6/28/2009)
Plus it's one plan per execution of the UDF. Also, you cannot trust statistics IO when you have a udf that does any form of data access.I'm not sure I was aware of that with the execution plans. Thanks!
I think that's what happens, though since management studio doesn't display the udf's exec plan it's hard to verify. Might be worth hauling profiler out to see exactly what's happening.
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
June 28, 2009 at 6:46 am
Grant Fritchey (6/28/2009)
I think I can answer that one. When you turn on the actual execution plan and run the query, the reads you're seeing in profiler include all the extra stuff to send the information back to SSMS for display. It seems really high, but the increase is understandable. How complicated are the execution plans that you're looking at? It's probably the amount of data being sent back that, operators, estimated costs, actual costs, number of rebinds... etc. You get the picture.
Hey Grant - I understand what you are saying but I am not 100% sure if I follow with this situation. Follow along and smack me around and tell me where my brain went off the deep end here (because I am certain it has 🙂 )
The execution plans here are fairly complex (another issue we are working out.. much more work than necessary.. so this is more of an academic question.. Once the developers and I have our chat and things get rewritten things should be less complex). I agree that when the plan is displayed there are extra reads to get the information needed as part of the plan and I know in SQL 2000 the calls to do this work were definitely part of the reads in profiler. I don't know if they "fixed" that in 2005 so the reads are only buffer cache reads (whether data was there or had to be fetched from disk before getting there).
The strange thing here is that the huge increase in reads is directly attirbuted to the UDF calls. If I run a statement level profile and see the reads for each statement call the biggest increase in reads is in the code that is inside of the UDF. It goes from displaying 0 per call (without the plan included) up to 90 per call (with the plan included) and the UDF is (this is why you just don't use scalar UDFs like this) called numerous times.
While I agree with your point what confuses me is that the UDF really isn't in the execution plan each time it is called. In fact the execution plan will not even really display the UDF calls as UDF calls (part of the reason people might look at an execution plan and IO statistics with a scalar UDF in the select list and reason: "Oh the plan looks fine to me"). It just shows the compute from it and "hides" the UDF. and it does it once for each place a function is referenced in the proc, not once for each call.
That is where I get a bit confused here. Of course it doesn't really matter in this case. The problem is many fold... First they put a UDF in the code like this at all. Then they are calling it in an inner most select (with plenty of subselects) and doing it on all rows before any filtering/aggregation is occurring rather than doing it on the final 30 rows that are being returned, etc. etc.
__________________________________________________
Mike Walsh
SQL Server DBA
Blog - www.straightpathsql.com/blog |Twitter
June 28, 2009 at 7:09 am
Mike, I just did some tests myself and, while I do see a small increase in reads, it's not overwhelming.
Use Adventureworks
GO
Create function LineItemTotal(@ProductID int)
returns money
as
begin
declare @Total money
select @Total = sum(LineTotal) from sales.SalesOrderDetail where productid = @ProductID
return @Total
end
GO
-- Run this twice, once with exec plan off, once with exec plan on
SELECT productid, productnumber, dbo.LineItemTotal(productid) as SumTotal
FROM Production.Product
WHERE ProductNumber LIKE 'bk-m%'
Run one (no exec plan)
CPU: 3079
Reads: 429541
Duration: 2109
Run two (include actual exec plan on)
CPU: 4594
Reads: 429555
Duration: 3008
Can you maybe use profiler with the statement level events on and see if you can see a difference?
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
June 28, 2009 at 7:17 am
GilaMonster (6/28/2009)
Yup.http://sqlinthewild.co.za/index.php/2009/04/29/functions-io-statistics-and-the-execution-plan/
I actually remember reading that when it came out and I even used it to prove my point to a developer (people tend to believe you more when you can show you aren't the only one suggesting something)
__________________________________________________
Mike Walsh
SQL Server DBA
Blog - www.straightpathsql.com/blog |Twitter
June 28, 2009 at 7:22 am
GilaMonster (6/28/2009)
Mike, I just did some tests myself and, while I do see a small increase in reads, it's not overwhelming....
Can you maybe use profiler with the statement level events on and see if you can see a difference?
Hey Gail --> Yeah I already have done the statement level events (I said it but it was buried in my rambling post above 😀 ) And when I do the majority of the reads difference is inside of the UDF calls. Each call went from profiler reporting 0 reads without the plan up to 90-->120 with the plan included.
__________________________________________________
Mike Walsh
SQL Server DBA
Blog - www.straightpathsql.com/blog |Twitter
Viewing 15 posts - 1 through 15 (of 16 total)
You must be logged in to reply to this topic. Login to reply