Friday, April 20, 2012

Extended Event - Check for Log Shrink and Email

I saw SQL Server MVP Jason Strate give a presentation a year or two ago on Extended Events. One situation I remember him giving was that he was having problems with a log file shrinking every so often; for some reason this caused some issues (auto-grow or something). So he used Extended Events to capture the shrink and get more details on it. This problem sounded interesting to me and I wanted to see if I could generate some code to do this from scratch, this is what I came up with:

First we need to create the Extended Event (hereafter referred to as XE) to capture the log shrink:

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name = 'XE_Log_Shrink')
DROP EVENT SESSION XE_Log_Shrink ON SERVER
GO
CREATE EVENT SESSION XE_Log_Shrink ON SERVER -- Session Name
ADD EVENT sqlserver.databases_log_shrink -- Event we want to capture
(
ACTION -- What contents to capture
(
sqlserver.client_app_name
,sqlserver.client_hostname
,sqlserver.nt_username
,sqlserver.session_id
,sqlserver.sql_text
,sqlserver.username
)
)
ADD TARGET package0.ring_buffer WITH (MAX_DISPATCH_LATENCY = 1 SECONDS, STARTUP_STATE = ON) -- The target
GO

ALTER EVENT SESSION XE_Log_Shrink ON SERVER STATE = START


Next to check it, we need to shrink a log (I'll auto grow it again, so I can redo this numerous times if I need to)


USE [AdventureWorks]
GO
DBCC SHRINKFILE (N'AdventureWorks_Log' , 1)
GO

USE [master]
GO
ALTER DATABASE [AdventureWorks] MODIFY FILE ( NAME = N'AdventureWorks_Log', SIZE = 100MB )
GO


Lets check the XE to see if we captured the event:

;WITH Data
AS (
SELECT CAST(target_data AS XML) AS TargetData
FROM sys.dm_xe_session_targets dt
JOIN sys.dm_xe_sessions ds ON ds.address = dt.event_session_address
JOIN sys.server_event_sessions ss ON ds.Name = ss.Name
WHERE dt.target_name = 'ring_buffer'
AND ds.Name = 'XE_Log_Shrink'
)
SELECT DATEADD(hour,-5,XEventData.XEvent.value('(@timestamp)[1]', 'datetime')) AS event_timestamp
,XEventData.XEvent.value('@name', 'varchar(4000)') AS event_name
,DB_NAME(XEventData.XEvent.value('(data/value)[2]', 'VARCHAR(100)')) AS DatabaseName
,XEventData.XEvent.value('(action/value)[2]', 'VARCHAR(512)') AS client_hostname
,XEventData.XEvent.value('(action/value)[3]', 'VARCHAR(512)') AS nt_username
,XEventData.XEvent.value('(action/value)[6]', 'VARCHAR(512)') AS username
,XEventData.XEvent.value('(action/value)[5]', 'VARCHAR(512)') AS sql_text
,XEventData.XEvent.value('(action/value)[4]', 'VARCHAR(512)') AS session_id
,XEventData.XEvent.value('(action/value)[1]', 'VARCHAR(512)') AS client_app_name
FROM Data d
CROSS APPLY TargetData.nodes('//RingBufferTarget/event') AS XEventData ( XEvent )



So, we should see the event now. But lets take it a step further, lets say we want to get emailed when it happens. I've created this stored proc which will check once an hour (this is a variable, you can configure it as you see fit, but keep it under 2 hours or else you'll have to modify my waitfor logic...or you could remove the waitfor logic and just run it from the scheduler in the agent job you setup, just match up the @How_Often variable with how often your job fires)

USE master
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
-- ===========================================================
-- Author: Eric Zierdt
-- Create date: 4/19/2012
-- Description: Checks for Log Shrinkage and sends email
-- URL: http://ericemployed.blogspot.com
-- Usage: exec Email_On_Log_Shrinkage 60
-- ===========================================================
ALTER PROCEDURE Email_On_Log_Shrinkage
-- Add the parameters for the stored procedure here
@How_Often INT = 60
AS
BEGIN
SET NOCOUNT ON
Start_Code:
--DECLARE @How_Often INT = 60
DECLARE @RowCount INT = 0
,@SQL VARCHAR(MAX) = ''

IF EXISTS (SELECT * FROM tempdb.dbo.sysobjects WHERE ID = OBJECT_ID(N'tempdb..#TempData'))
BEGIN
DROP TABLE #TempData
END

;WITH Data
AS (
SELECT CAST(target_data AS XML) AS TargetData
FROM sys.dm_xe_session_targets dt
JOIN sys.dm_xe_sessions ds ON ds.address = dt.event_session_address
JOIN sys.server_event_sessions ss ON ds.Name = ss.Name
WHERE dt.target_name = 'ring_buffer'
AND ds.Name = 'XE_Log_Shrink'
)
SELECT DATEADD(hour,-5,XEventData.XEvent.value('(@timestamp)[1]', 'datetime')) AS event_timestamp
,XEventData.XEvent.value('@name', 'varchar(4000)') AS event_name
,DB_NAME(XEventData.XEvent.value('(data/value)[2]', 'VARCHAR(100)')) AS DatabaseName
,XEventData.XEvent.value('(action/value)[2]', 'VARCHAR(512)') AS client_hostname
,XEventData.XEvent.value('(action/value)[3]', 'VARCHAR(512)') AS nt_username
,XEventData.XEvent.value('(action/value)[6]', 'VARCHAR(512)') AS username
,XEventData.XEvent.value('(action/value)[5]', 'VARCHAR(512)') AS sql_text
,XEventData.XEvent.value('(action/value)[4]', 'VARCHAR(512)') AS session_id
,XEventData.XEvent.value('(action/value)[1]', 'VARCHAR(512)') AS client_app_name
INTO #TempData
FROM Data d
CROSS APPLY TargetData.nodes('//RingBufferTarget/event') AS XEventData ( XEvent )
WHERE DATEADD(hour,-5,XEventData.XEvent.value('(@timestamp)[1]', 'datetime')) > DATEADD(MINUTE,-1*@How_Often,GETDATE())

SELECT @RowCount = COUNT(1) FROM #TempData
IF @RowCount > 0
BEGIN
PRINT CAST(@RowCount AS VARCHAR(10)) + ' Log Shrink records were found'
SET @SQL = '






'
DECLARE @DBName VARCHAR(120)
,@HostName VARCHAR(120)
,@TimeStamp VARCHAR(120)
,@UserName VARCHAR(120)
,@SQL_Text VARCHAR(120)
DECLARE ZCursor CURSOR FOR
(
SELECT DatabaseName
,client_hostname
,CAST(event_timestamp AS VARCHAR(120)) AS TimeStamp
,username
,sql_text
FROM #TempData
)
OPEN ZCursor
FETCH NEXT FROM ZCursor INTO @DBName,@HostName,@TimeStamp,@UserName,@SQL_Text
WHILE @@FETCH_STATUS = 0
BEGIN
SET @SQL += '



'

FETCH NEXT FROM ZCursor INTO @DBName,@HostName,@TimeStamp,@UserName,@SQL_Text
END

CLOSE ZCursor
DEALLOCATE ZCursor
SET @SQL += '
ServerDatabase NameTime StampClient HostnameUsernameSQL_Text
' + @@SERVERNAME + '' + @DBName + '' + @TimeStamp + '' + @HostName + '' + @UserName + '' + @SQL_Text + '

'
END
ELSE
PRINT 'No Shrinks in the time frame requested'

--PRINT @SQL

EXEC msdb.dbo.sp_send_dbmail
@recipients = '[Your Email Here]',
@body = @SQL,
@subject = 'Log Shrink Detected',
@profile_name = '[Your Profile Name Here]',
@body_format = 'html';

DROP TABLE #TempData

DECLARE @Delay VARCHAR(10)
--,@How_Often INT = 60
IF @How_Often < 60
SET @Delay = '00:' + RIGHT('00' + CAST(@How_Often AS VARCHAR(2)),2) + ':00'
ELSE
SET @Delay = '01:' + RIGHT('00' + CAST(@How_Often-60 AS VARCHAR(2)),2) + ':00'

WAITFOR DELAY @Delay
GOTO Start_Code
END
GO


Then the last step is to call this proc from a agent job. Iif you use the WaitFor logic, I'd still set a schedule to run every hour, just in case it fails...but the more I think about this, the more I prefer not using the WaitFor logic and just running the job every hour; but if the job fails, you won't get emailed.

--Eric

No comments:

Post a Comment