info@techdevops.com
|
437-991-3573
|
Data Engineering Services
|
TechDevOps.com
|
| | | |
|
Experts in Microsoft SQL Server on Windows, Linux, Containers | Clusters, Always On, FCI | Migrations, Cloud, Performance
|
| | | |
|
Find the root cause of a TEMPDB LOG growth issue
by BF (Principal Consultant; Architecture; Engineering)
2018-06-13
Using Extended Events, DBCC OPENTRAN, INPUTBUFFER & SYSPROCESSES to help find the root cause of TEMPDB LOG growth issue
Step 1: Create New Extended Events Session to capture file growth events for database_file_size_change and database_log_file_used_size_changes
CREATE EVENT SESSION [EE_DB_File_Growth] ON SERVER
ADD EVENT [sqlserver].[database_file_size_change] (
ACTION ( [sqlserver].[session_id], [sqlserver].[database_id],
[sqlserver].[client_hostname], [sqlserver].[sql_text], [sqlserver].[tsql_stack], [sqlserver].[plan_handle], [sqlserver].[query_hash], [sqlserver].[query_plan_hash])
WHERE ( ([database_id] = ( 2 ) or [database_id] = ( 8 ))
AND [session_id] > ( 50 ) ) ),
ADD EVENT [sqlserver].[databases_log_file_used_size_changed] (
ACTION ( [sqlserver].[session_id], [sqlserver].[database_id],
[sqlserver].[client_hostname], [sqlserver].[sql_text], [sqlserver].[tsql_stack], [sqlserver].[plan_handle], [sqlserver].[query_hash], [sqlserver].[query_plan_hash] )
WHERE ( ([database_id] = ( 2 ) or [database_id] = (8))
AND [session_id] > ( 50 ) ) )
ADD TARGET [package0].[asynchronous_file_target] ( SET filename = N'c:\temp\evdbgrowth.xel' ,
metadatafile = N'c:\temp\evdbgrowth.xem' ,
max_file_size = ( 10 ) ,
max_rollover_files = 10 )
WITH ( MAX_MEMORY = 4096 KB ,
EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS ,
MAX_DISPATCH_LATENCY = 1 SECONDS ,
MAX_EVENT_SIZE = 0 KB ,
MEMORY_PARTITION_MODE = NONE ,
TRACK_CAUSALITY = ON ,
STARTUP_STATE = ON );
GO
ALTER EVENT SESSION [EE_DB_File_Growth] ON SERVER STATE = START;
Step 2: Create a Permanent Logging Table to store the extended events data
Create Table OPS.dbo.LOG_FILE_GROWTH (SessionID int, ClientHostName varchar(100), OriginatingDB varchar(50), GrowthDB varchar(50),
GrowthFile varchar(25), DBFileType varchar(25), EventName varchar(100), SizeChangeInKB int, TotalFileSizeInKB int, DurationInMS int,
GrowthTime datetime, QueryText varchar(500), TSQLStack varchar(500), PlanHandle varchar(max), QueryHash varchar(max), QueryPlanHash varchar(max), InsertedDate datetime)
Step 3: Create a Stored Procedure to capture extended events data
Create Procedure dbo.Admin_EE_DB_File_Growth
as
Insert into OPS.dbo.LOG_FILE_GROWTH
(SessionID, ClientHostName, OriginatingDB, GrowthDB, GrowthFile, DBFileType, EventName, SizeChangeInKB, TotalFileSizeInKB, DurationInMS,
GrowthTime, QueryText, TSQLStack, PlanHandle, QueryHash, QueryPlanHash, InsertedDate)
SELECT [evts].[event_data].[value]('(event/action[@name="session_id"]/value)[1]',
'INT') AS [SessionID] ,
[evts].[event_data].[value]('(event/action[@name="client_hostname"]/value)[1]',
'VARCHAR(MAX)') AS [ClientHostName] ,
COALESCE(DB_NAME([evts].[event_data].[value]('(event/action[@name="database_id"]/value)[1]',
'BIGINT')), ';(._.); I AM KING KRAB') AS [OriginatingDB] ,
DB_NAME([evts].[event_data].[value]('(event/data[@name="database_id"]/value)[1]',
'BIGINT')) AS [GrowthDB] ,
[evts].[event_data].[value]('(event/data[@name="file_name"]/value)[1]',
'VARCHAR(MAX)') AS [GrowthFile] ,
[evts].[event_data].[value]('(event/data[@name="file_type"]/text)[1]',
'VARCHAR(MAX)') AS [DBFileType] ,
[evts].[event_data].[value]('(event/@name)[1]', 'VARCHAR(MAX)') AS [EventName] ,
[evts].[event_data].[value]('(event/data[@name="size_change_kb"]/value)[1]',
'BIGINT') AS [SizeChangeInKb] ,
[evts].[event_data].[value]('(event/data[@name="total_size_kb"]/value)[1]',
'BIGINT') AS [TotalFileSizeInKb] ,
[evts].[event_data].[value]('(event/data[@name="duration"]/value)[1]',
'BIGINT') AS [DurationInMS] ,
[evts].[event_data].[value]('(event/@timestamp)[1]', 'VARCHAR(MAX)') AS [GrowthTime] ,
[evts].[event_data].[value]('(event/action[@name="sql_text"]/value)[1]',
'VARCHAR(MAX)') AS [QueryText],
[evts].[event_data].[value]('(event/action[@name="tsql_stack"]/value)[1]',
'VARCHAR(MAX)') AS [TSQLStack],
[evts].[event_data].[value]('(event/action[@name="plan_handle"]/value)[1]',
'VARCHAR(MAX)') AS [PlanHandle],
[evts].[event_data].[value]('(event/action[@name="query_hash"]/value)[1]',
'VARCHAR(MAX)') AS [QueryHash],
[evts].[event_data].[value]('(event/action[@name="query_plan_hash"]/value)[1]',
'VARCHAR(MAX)') AS [QueryPlanHash],
GetDate()
FROM
(SELECT CAST([event_data] AS XML) AS [TargetData] FROM [sys].[fn_xe_file_target_read_file]('c:\temp\evdbgrowth*.xel',NULL,NULL,NULL)) AS [evts] ([event_data])
WHERE [evts].[event_data].[value]('(event/@name)[1]', 'VARCHAR(MAX)') = 'database_file_size_change'
OR [evts].[event_data].[value]('(event/@name)[1]', 'VARCHAR(MAX)') = 'databases_log_file_used_size_changed'
ORDER BY [GrowthTime] ASC;
IF QueryText above is empty, get the QueryText through the PlanHandle field...
Step 4: Create a TMP Table to join with sys.dm_exec_query_plan to get the Execution Plan
Select * Into #TMP from OPS.dbo.LOG_FILE_GROWTH
Update #TMP set PlanHandle = '0x'+PlanHandle
Select 'Select * from sys.dm_exec_query_plan' + '(' + planhandle + ')' from #TMP
Select * from sys.dm_exec_query_plan(0x05000800ec4aaa5110b54bae0c00000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x05000800ec4aaa5110b54bae0c00000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x05000800ec4aaa5110b54bae0c00000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x05000800ec4aaa5110b54bae0c00000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)
Select * from sys.dm_exec_query_plan(0x06000800bffbef2cd0fd42ed0700000001000000000000000000000000000000000000000000000000000000)
Step 5: At this point you have the timestamp(s) of any database file growth events and possibly the root cause data. If you need further information, use the below process.
Ex:
Use TEMPDB
go
DBCC OPENTRAN
Transaction information for database 'tempdb'.
Oldest active transaction:
SPID (server process ID): 90
UID (user ID) : -1
Name : user_transaction
LSN : (3096:70456:190)
Start time : Jun 13 2018 9:00:09:587AM
SID : 0x19be18a29ccb13469e1fdc482b42e979
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
* The above shows we have active open transactions since 9:00AM !!! (7 hours and counting!)
DBCC INPUTBUFFER (90)
select spid, blocked, lastwaittype from sysprocesses where '~90~~98~' like '%~' + cast (spid as nvarchar)+ '~%' and '~90~~98~' like '%~' + cast (blocked as nvarchar)+ '~%'
Select * from sysprocesses where spid = 90
open_tran status hostname cmd programname
3 sleeping VM-PR AWAITING COMMAND Distribution Agent Name
* This information shows that SPID 90 in fact has 3 open transactions and the programname is Replication Related !!! (i.e. From the Distribution Agent on a separate server)
* We stopped that Distribution Agent and the 3 Open Transactions in TEMPDB immediately went away and the free space in TEMPDB went to 90% free.
DBCC OPEN TRAN went from 9:00AM to 4:05PM
Transaction information for database 'tempdb'.
Oldest active transaction:
SPID (server process ID): 77
UID (user ID) : -1
Name : sort_init
LSN : (3338:707992:215)
Start time : Jun 13 2018 4:05:15:453PM
SID : 0x010500000000000515000000bfab95a7da18eca6aa267657eb030000
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
Root Cause of TEMPDB LOG File huge growth = SPID with 3 open transactions from a Replication Distribution Agent.
Resolved !!!
|
|
|
|
|
|
|
|
|
|