When you’re trying to diagnose performance problems in SQL Server, what’s the first thing you usually do? For me, it’s usually running a trace in SQL Server Profiler for a while to see what’s happening and get an idea of the most expensive operations that are happening. This time, I decided to try something different and used the Dynamic Management Views instead. These views reflect the inner workings of SQL server, and querying them is like having the ability to query a very complete trace that is continuously running. I’m only just dipping my toes in these waters, but I’ve concocted a pretty nice query that outputs expensive queries and highlights the section within the query that is taking up the most time.
First of all, you will need my print_long stored procedure if you don’t have it. This procedure overcomes the 8000 byte character limit of the print statement, enabling you to output very long procedures and queries to the message window.
create procedure dbo.print_long
@long_str nvarchar(max)
as
set nocount on
declare
@cr char(1),
@lf char(1),
@long_str_len int,
@pos int,
@len int,
@is_crlf bit,
@max_len int
set @cr = char(13)
set @lf = char(10)
set @max_len = 4000 -- 8000 if @long_str is varchar(max)
set @long_str_len = len(@long_str)
set @pos = 1
while ((@long_str_len - @pos) > @max_len)
begin
select top 1
@len = n,
@is_crlf = case substring(@long_str, @pos + n - 1, 2) when @cr + @lf then 1 else 0 end
from dbo.sequence
where n between 1 and @max_len
and substring(@long_str, @pos + n, 1) in (@cr, @lf)
and substring(@long_str, @pos + n, 2) <> @cr + @lf
order by n desc
print substring(@long_str, @pos, @len - @is_crlf)
set @pos = @pos + @len + 1
end
print substring(@long_str, @pos, @max_len)
GO
And now, here is the Dynamic Management View query. This one outputs the top 10 most expensive queries by total time since the plan was first cached, but you could just as easily sort by average time, I/O, or CPU utilization.
declare @stmt nvarchar(max) = ''
select top 10 @stmt += '
' + replicate('-', 80) + '
-- ' + cast(row_number() over (order by qs.total_elapsed_time / qs.execution_count desc) as varchar(11)) + '
total time (s): ' + cast(qs.total_elapsed_time / 1000000.0 as varchar(max)) + '
average time (s): ' + cast(qs.total_elapsed_time / qs.execution_count / 1000000.0 as varchar(max)) + '
' + replicate('-', 80) + '
' + stuff(stuff(st.text + ' ', (case qs.statement_end_offset when -1 then datalength(st.text) else qs.statement_end_offset end) / 2 + 1, 0, '
' + stuff(replicate('-', 80), 3, 13, ' END SECTION ') + '
'), qs.statement_start_offset / 2 + 1, 0, '
' + stuff(replicate('-', 80), 3, 16, ' START SECTION ') + '
')
from sys.dm_exec_query_stats qs
cross apply sys.dm_exec_sql_text(qs.sql_handle) st
order by qs.total_elapsed_time desc
exec dbo.print_long @stmt
Here is some sample output, demonstrating how the most expensive block is highlighted. Look for BEGIN SECTION and END SECTION. You can see that this procedure showed up on the list because it counts time waiting for service broker messages in the WAITFOR statement. Nothing to worry about, but it might still show up in your results if you use DB mail.
--------------------------------------------------------------------------------
-- 1
total time (s): 22030.398276000
average time (s): 244.782203000
--------------------------------------------------------------------------------
-- sp_readrequest : Reads a request from the the queue and returns its
-- contents.
CREATE PROCEDURE sp_readrequest
@receive_timeout INT -- the max time this read will wait for new message
AS
BEGIN
SET NOCOUNT ON
-- Table to store message information.
DECLARE @msgs TABLE
(
[conversation_handle] uniqueidentifier,
[service_contract_name] nvarchar(256),
[message_type_name] nvarchar(256),
[message_body] varbinary(max)
)
-- Declare variables to store row values fetched from the cursor
DECLARE
@exit INT,
@idoc INT,
@mailitem_id INT,
@profile_id INT,
@conversation_handle uniqueidentifier,
@service_contract_name NVARCHAR(256),
@message_type_name NVARCHAR(256),
@xml_message_body VARCHAR(max),
@timediff INT,
@rec_timeout INT,
@start_time DATETIME,
@localmessage NVARCHAR(256),
@rc INT
--Init variables
SELECT @start_time = GETDATE(),
@timediff = 0,
@exit = 0,
@rc = 0
WHILE (@timediff <= @receive_timeout)
BEGIN
-- Delete all messages from @msgs table
DELETE FROM @msgs
-- Pick all message from queue
SET @rec_timeout = @receive_timeout - @timediff
-- START SECTION --------------------------------------------------------------
WAITFOR(RECEIVE conversation_handle, service_contract_name, message_type_name, message_body
FROM ExternalMailQueue INTO @msgs), TIMEOUT @rec_timeout
-- Check if there was some error in reading from queue
-- END SECTION -----------------------------------------------------------------
SET @rc = @@ERROR
IF (@rc <> 0)
BEGIN
IF(@rc < 4) -- make sure return code is not in reserved range (1-3)
SET @rc = 4
--Note: we will get error no. 9617 if the service queue 'ExternalMailQueue' is currently disabled.
BREAK
END
--If there is no message in the queue return 1 to indicate a timeout
IF NOT EXISTS(SELECT * FROM @msgs)
BEGIN
SET @rc = 1
BREAK
END
-- Create a cursor to iterate through the messages.
DECLARE msgs_cursor CURSOR FOR
SELECT conversation_handle,
service_contract_name,
message_type_name,
CONVERT(VARCHAR(MAX), message_body)
FROM @msgs;
-- Open the cursor
OPEN msgs_cursor;
-- Perform the first fetch and store the values in the variables.
FETCH NEXT FROM msgs_cursor
INTO
@conversation_handle,
@service_contract_name,
@message_type_name,
@xml_message_body
-- Check @@FETCH_STATUS to see if there are any more rows to fetch.
WHILE (@@FETCH_STATUS = 0)
BEGIN
-- Check if the message is a send mail message
IF(@message_type_name = N'{//www.microsoft.com/databasemail/messages}SendMail')
BEGIN
-- Get the handle to the xml document
EXEC @rc = sp_xml_preparedocument
@idoc OUTPUT,
@xml_message_body,
N'<ns xmlns:requests="http://schemas.microsoft.com/databasemail/requests" />'
IF(@rc <> 0)
BEGIN
IF(@rc < 4) -- make sure return code is not in reserved rang (1-3)
SET @rc = 4
END
ELSE -- parse the document and process its contents
BEGIN
-- Execute a SELECT statement that uses the OPENXML rowset provider to get the MailItemId.
SELECT @mailitem_id = MailItemId
FROM OPENXML (@idoc, '/requests:SendMail', 1)
WITH (MailItemId INT './MailItemId')
--Close the handle to the xml document
EXEC sp_xml_removedocument @idoc
-- get account information
SELECT @profile_id = profile_id
FROM sysmail_mailitems
WHERE mailitem_id = @mailitem_id
IF(@profile_id IS NULL) -- mail item has been deleted from the database
BEGIN
-- log warning
SET @localmessage = FORMATMESSAGE(14667, convert(NVARCHAR(50), @mailitem_id))
exec msdb.dbo.sysmail_logmailevent_sp @event_type=2, @description=@localmessage
-- Resource clean-up
IF(@conversation_handle IS NOT NULL)
END CONVERSATION @conversation_handle;
-- return code has special meaning and will be propagated to the calling process
SET @rc = 2
END
ELSE
BEGIN
-- This returns the mail item to the client as multiple result sets
EXEC sp_MailItemResultSets
@mailitem_id = @mailitem_id,
@profile_id = @profile_id,
@conversation_handle = @conversation_handle,
@service_contract_name = @service_contract_name,
@message_type_name = @message_type_name
SET @exit = 1 -- make sure we exit outer loop
END
END
-- always break from the loop upon processing SendMail message
BREAK
END
-- Check if the message is a dialog timer. This is used for account retries
ELSE IF(@message_type_name = N'http://schemas.microsoft.com/SQL/ServiceBroker/DialogTimer')
BEGIN
-- Handle the retry case. - DialogTimer is used for send mail reties
EXEC @rc = sp_process_DialogTimer
@conversation_handle = @conversation_handle,
@service_contract_name = @service_contract_name,
@message_type_name = N'{//www.microsoft.com/databasemail/messages}SendMail'
-- Always break from the loop upon processing DialogTimer message
-- In case of failure return code from procedure call will simply be propagated to the calling process
SET @exit = 1 -- make sure we exit outer loop
BREAK
END
-- Error case
ELSE IF (@message_type_name = 'http://schemas.microsoft.com/SQL/ServiceBroker/Error')
-- Error in the conversation, hence ignore all the messages of this conversation.
BREAK
-- This is executed as long as fetch succeeds.
FETCH NEXT FROM msgs_cursor
INTO
@conversation_handle,
@service_contract_name,
@message_type_name,
@xml_message_body
END
CLOSE msgs_cursor;
DEALLOCATE msgs_cursor;
-- Check if we read any request or only SSB generated messages
-- If a valid request is read with or without an error break out of loop
IF (@exit = 1 OR @rc <> 0)
BREAK
--Keep track of how long this sp has been running
select @timediff = DATEDIFF(ms, @start_time, getdate())
END
-- propagate return code to the calling process
RETURN @rc
END
There are a lot of other Dynamic Management Views that I haven’t gotten into yet, but using this query is a great way to get started without needing to run a trace first. I hope you find it useful.