September 27, 2012 at 9:12 am
Hello,
First, some background (long):
I had something interesting happen to a vendor supplied database I work with this morning. As users started to log into the system we started to get slowness complaints and the alert message went out. Since I work with this database I jumped into SSMS and checked out the server to see if I could find anything. I noticed at once that CPU usage was pegged at 100%, but there wasn't really any IO waits, but a ton of SOS_SCHEDULER_YIELDs. My first thought was that there was a runaway report query or something that went rogue, but because of the server load the SSMS monitoring screen would halt. So I started running sp_who and sp_who2 to see if I could spot any particular SPID that was the source of the trouble. The normal connections were there and none of them was standing out. Since we are in a failover cluster, we failed over the node in case perhaps we were experiencing something on the hardware side, but the problem persisted. Finally my caffeine kicked in and I thought, make sure to check the query DMVs!. So I quickly ran
SELECT execution_count, total_worker_time, total_physical_reads, total_logical_reads, qt,text
FROM sys.dm_exec_query_stats qs CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) qt
ORDER BY total_elapsed_time DESC
Aha! There was a query being executed by a stored procedure that already had a total_logical_reads that was 100 times more then anything else. The query itself seemed simple enough so I started a background trace and captured the query plan that was being generated. As this was going on we got a hold of the vendor who said we could disable this stored procedure while we work out the issue and our users were able to operate normally.
Here is a mockup of the tables that were involved, and the query that was being executed. All statistics are current within the last 8 hours and index fragmentation is under 10%.
CREATE TABLE Document (DocumentId numeric(16,0) PRIMARY KEY,
PersonId numeric(16,0) NULL,
InstanceId numeric(16,0) NOT NULL,
SpecialId numeric(16,0) NULL
TypeId numeric(8,0) NOT NULL);
GO
CREATE TABLE Instance (Id numeric(16,0) PRIMARY KEY,
InstanceDateTime DATETIME);
GO
CREATE TABLE Document_Type (Id numeric(8,0) PRIMARY KEY,
TypeCode char(10) NOT NULL);
GO
CREATE PROCEDURE dbo.GetDocumentInstanceDate (@PersonId numeric(16,0))
AS
SET NOCOUNT ON
SELECT TOP 1 CONVERT(VARCHAR(10), i.InstanceDateTime, 101) "DocumentInstanceDate",
CASE WHEN DATEDIFF(dd, i.InstanceDateTime, GetDate()) < 90 THEN 'Y' ELSE 'N' END "isCurrent"
FROM Document d INNER JOIN Instance i ON d.InstanceId = i.InstanceId
INNER JOIN Document_Type dt ON d.TypeId = dt.Id
WHERE dt.TypeCode IN ('1234567','TESTCODE') -- TEST & LIVE Codes
AND ISNULL(d.SpecialId, 0) = 0
AND d.PersonId = @PersonId
ORDER BY i.InstanceDateTime
GO
The STATISTICS IO are also telling:
Table 'Document_Type'. Scan count 60, logical reads 120, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Worktable'. Scan count 1,logical reads 10714557, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Document'. Scan count 1, logical reads 6, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Instance'. Scan count 1, logical reads 23688, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Runtime was over 6 minutes and this SP was being called 10s of times a minute. There were the normal, very low (<10ms) IO waits while this was occurring.
The Execution Plan that was generated by SQL looks very normal, except that when it does a Clustered Index Seek on the primary key index it then does a lazy spool.
When I look at the Seek Predicates it says Seek Keys[1]: Prefix: [dbo].[Document].PersonID = Scalar Operator([@PersonID]) but in the Predicate field it shows
isnull([dbo].[Document].[SpecialId] as [d].[SpecialId],(0.))=(0.). Is this telling me that because (IIRC) a function prevents a seek from occuring that there are in essence two "pipelines"? It would make sense to me that you might see a lazy spool because it ends up calculating ISNULL() "row by agonizing row" before moving on to the join.
At any rate I'm thinking of suggesting to the vendor that
a) they remove the function from the where clause
b) they get rid of the in statement as well. I'm sure they did this because things aren't consistent between our test and production, but the solution is to synchronize test and production, not create exceptions.
Thanks for reading through all this. Mostly I'm wondering if I'm on the right trail to suggest the changes to the vendor and if I'm interpreting the issue reasonably.
Jim
September 27, 2012 at 10:10 am
I think you're on the right track, yes. The function sure sounds like the primary cause.
As to the IN statement, with a really small one like this with hardcoded values, a UNION ALL with query repeated is likely to be much more efficient. But, as with every piece of advice like this, trust but verify. Test it yourself 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
September 27, 2012 at 11:56 am
Thanks for the response! I've been trading emails with the vendor and his idea is to change a column he's filtering on to a different table as his testing is indicating that it generates a different query plan. I'm planning on doing some testing myself and see how removing the IsNull() call and replacing it with IS NULL works and trying your suggestion to split it into two statements with a UNION ALL.
Thanks again!
September 27, 2012 at 3:28 pm
Excellent. Please post back with the results.
"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
September 27, 2012 at 7:25 pm
Hmm,
Interesting (if somewhat puzzling results). If you look on MSDN it says explicitly not to use the ISNULL() function to find NULLs in a query, and to use "field" IS NULL instead. There isn't any change in the plan and both seem to execute in roughly the same amount of time. Perhaps in SQL 2008 R2 the query planner optimizes the ISNULL() function? Filtering on a different table with a better index seems to have resulted in all of the performance improvement. My mock tables didn't show it, but PersonId also exists in the Instance table and by filtering on it in the where clause the query optimizer generates an entirely different plan. For instance on the Document table it started to use a covering index that had most of the other table primary keys with another in the included field list instead of the primary key (which is probably more efficient then doing bookmark lookups I think).
If I break up the query with a UNION ALL I get double the logical reads and scans and it takes twice as long. Basically it seems that it generates the same plan as with the IN clause, but just runs it twice in a serial manner.
September 28, 2012 at 4:00 am
And that's why we test.
The thing with trying to filter NULL values is that you're doing a function on it no matter what. By their nature, NULL values have no statistics, so there's no easy way to get at them through the optimization process. It sounds like you're going down a good path with filtering elsewhere.
As far as the IN statement goes... It sometimes works, it sometimes doesn't. From the sounds of things, the IN is not doing much in the way of filtering on the query. How many records are excluded by that IN statement?
"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
September 28, 2012 at 10:31 am
The vast majority if you mean excluded as (total records - selected records).
Roughly 10 million records are excluded as only about 7000 meet the criteria.
September 28, 2012 at 1:44 pm
If you typically query the Document table by PersonId, change the clustered key on the Document table to be PersonId instead and you should get great response time for individuals regardless of the rest of the query.
If you have a default PersonId of 0 that stores a lot of documents, you will still have to read thru all those rows, of course.
SQL DBA,SQL Server MVP(07, 08, 09) "It's a dog-eat-dog world, and I'm wearing Milk-Bone underwear." "Norm", on "Cheers". Also from "Cheers", from "Carla": "You need to know 3 things about Tortelli men: Tortelli men draw women like flies; Tortelli men treat women like flies; Tortelli men's brains are in their flies".
Viewing 8 posts - 1 through 7 (of 7 total)
You must be logged in to reply to this topic. Login to reply