June 15, 2011 at 7:57 am
1) have you run a profiler trace, looking for recompiles while this thing is running?
2) have you run a profiler trace with STATEMENT completion on for each run to check potential issues with the UDFs? Those things can be truly devastating, and they do NOT get reported correctly in the query plan. BEWARE doing this on production server - specify the exact spid as a filter for trace!
Best,
Kevin G. Boles
SQL Server Consultant
SQL MVP 2007-2012
TheSQLGuru on googles mail service
June 15, 2011 at 10:24 am
TheSQLGuru (6/15/2011)
1) have you run a profiler trace, looking for recompiles while this thing is running?
I have not traced the process but will give it a go. I have an INT environment where the performance disparity can be recreated and can play there. Thanks for the lead!
2) have you run a profiler trace with STATEMENT completion on for each run to check potential issues with the UDFs?
The UDFs were a mess! We're talking about scalar UDFs that make use of CURSORs to lookup values in a table and generate a comma-delimited list :angry:
I provided a couple options and the developer has rewritten the UDFs to alleviate the use of cursors...but the UDFs survived. The performance is acceptable, but not the ideal end. I would have liked to see the UDFs go away but I have to be patient. They balked at my second option, using the "FOR XML,TYPE" technique to gen a delimited list as part of the grouping that would replace the UDF in the outer query.
Those things can be truly devastating, ...
Agreed. They can easily destroy performance of an otherwise well-performing set-based query and iterative thinking developers do not make the connection. *blue in the face*
...and they do NOT get reported correctly in the query plan.
Still learning...thanks again for another lead!
BEWARE doing this on production server - specify the exact spid as a filter for trace!
Indeed. It's always good to have this point re-enforced.
There are no special teachers of virtue, because virtue is taught by the whole community.
--Plato
June 15, 2011 at 11:34 am
Another thought......
Would these functions return an ANSI warning ie "NULL value eliminated from query"
As that may be being 'consumed' somewhere and causing the slow down.
Ive mocked it up on a 2008 setting and not seeing a slow down , but dont have access to 2005 easiliy.
June 15, 2011 at 12:07 pm
Dave Ballantyne (6/15/2011)
Another thought......Would these functions return an ANSI warning ie "NULL value eliminated from query"
As that may be being 'consumed' somewhere and causing the slow down.
Ive mocked it up on a 2008 setting and not seeing a slow down , but dont have access to 2005 easiliy.
That is a possibility. Having ANSI_WARNINGS ON does allow SQL Server to send warnings through the information stream to the client which will generate additional network traffic. That said, when I run this particular proc via SSMS with ANSI_WARNINGS ON I do not receive any warning messages so it may not be relevant in this specific case.
I think the setting was turned OFF for this proc, just as it was for the other 212 procs in this database, due to the spread of incorrect knowledge about it being harmless...something along the lines of "turning off ANSI_WARNINGS just turns off WARNING messages which we don't care about, so we just turn it off at the top of all our procs".
There are no special teachers of virtue, because virtue is taught by the whole community.
--Plato
June 15, 2011 at 1:31 pm
opc.three (6/15/2011)
TheSQLGuru (6/15/2011)
1) have you run a profiler trace, looking for recompiles while this thing is running?I have not traced the process but will give it a go. I have an INT environment where the performance disparity can be recreated and can play there. Thanks for the lead!
I just got done tracing the process in both scenarios capturing the following events with a filter on a specific SPID:
ExistingConnection
RPC:Completed
SP:Completed
SP:Recompile
SQL:StmtRecompile
Per the docs we should see trigger and UDF recompiles show up as SP:Recompile events.
Every statement recompiled in both scenarios, however there are only 61 statements in the batch. Within a given statement that included a UDF I did see SP:Completed events for each call to the UDF, however I did not see a recompile for each call. Here is a mini snap from the trace showing the recurring theme:
EventClass TextData Duration SPID DatabaseName ObjectType
----------------- ----------- ---------- ----- -------------- -------------------
SP:Recompile INSERT... NULL 60 Reports 8272 - P
SQL:StmtRecompile INSERT... NULL 60 Reports 8272 - P
SP:Completed INSERT... 9 60 Reports 20038 - FN
. INSERT... ~9 60 Reports 20038 - FN
. thousands more INSERT... ~9 60 Reports 20038 - FN
. INSERT... ~9 60 Reports 20038 - FN
SP:Completed INSERT... 9 60 Reports 20038 - FN
SP:Recompile DELETE... NULL 60 Reports 8272 - P
SP:StmtRecompile DELETE... NULL 60 Reports 8272 - P
I don't like leaving items like this without finding the root cause however I have exhausted what is a reasonable amount of time I can spend on this...especially since we have the process running in the same amount of time with ANSI_WARNINGS ON and OFF following some of the code changes mentioned earlier.
The only item not really run down was the diff between the execution plans for Query 7 but my inexperience prevents me from being able to say much about that.
Thanks for all the comments and suggestions.
There are no special teachers of virtue, because virtue is taught by the whole community.
--Plato
Viewing 5 posts - 16 through 19 (of 19 total)
You must be logged in to reply to this topic. Login to reply