It is finally time to revisit a blog posting I started on Dec 21st, 2016.
That post is titled “SQL Server – Error – Cannot shrink log file because the logical file located at the end of the file is in use“.
And, it is here.
Received an alarm that our database files are growing and so sought to find out why.
Transaction Log – Utilization Metrics from Performance Counter
use master go if schema_id('transactionLog') is null begin exec('create schema [transactionLog] authorization [dbo]') end go if object_id('[transactionLog].[IUDF_UtilizationMetricsFromPerformanceCounters]') is null begin exec( 'create function [transactionLog].[IUDF_UtilizationMetricsFromPerformanceCounters] () RETURNS table AS RETURN ( SELECT [shell] = 1/0 ); ' ) end go alter function [transactionLog].[IUDF_UtilizationMetricsFromPerformanceCounters] () returns TABLE as return ( with cte ( [dbid] , [database] , [counter] , [size] ) as ( SELECT [dbid] = db_id(RTRIM(instance_name)) , [database] = RTRIM(instance_name) , tblDMOPC.counter_name , cntr_value log_size_kb FROM sys.dm_os_performance_counters tblDMOPC WHERE tblDMOPC.object_name = 'SQLServer:Databases' AND tblDMOPC.counter_name like 'Log File' + '%' AND tblDMOPC.instance_name <> '_Total' ) , ctePivot as ( select * from cte pivot ( avg ([size]) for [counter] in ( [Log File(s) Used Size (KB)] , [Log File(s) Size (KB)] ) ) as avgSize ) select [cteP].[dbid] , [cteP].[database] , [usedMB] = [Log File(s) Used Size (KB)] / 1000 , [totalMB] = [Log File(s) Size (KB)] / 1000 , [%] = cast ( ( [Log File(s) Used Size (KB)] * 100.00) / ( [Log File(s) Size (KB)]) as decimal(10,2 ) ) , [recoveryModel] = tblSD.recovery_model_desc , [log reuse wait] = tblSD.log_reuse_wait_desc from ctePivot cteP inner join sys.databases tblSD on cteP.[dbid] = tblSD.database_id ) go
- Before capturing the screenshot above, our target database, QA_rbpivr1, was in FULL RECOVERY
- It’s transaction log size was 8 GB
- And, 3.2 GB of the 8GB is in use
Why so much Transaction Log is being held up?
Again for QA_rbpiv1 3.2 GB is being used.
Let us review how database is configured
We see that the Recovery Mode for our database is Full.
- The last full backup was taken last night Feb 2nd, 2017 and it completed at 8:35 PM
- And, the last Transaction backup was taken on Sunday Feb 5th, 2017 at 6 PM
Transaction Backup History
Let us review our Transaction Backup History
- Before today, transaction backups were occurred on 2/5/2017, 1/29/2017, 1/22/2017
- And, they were occurring each hour
- Looked back at the Calendar and those days fell on Sundays
Review Scheduled Transaction Backup
- Schedule is Weekly on Sundays
- And, the frequency is each hour
- Changed Schedule’s frequency from Weekly to Daily
Review Checkpoints in Error Log File
Enable Logging of Checkpoints in ErrorLog file
Enable Trace Flags
dbcc traceon (3502, 3504, 3605, -1 )
Review ErrorLog file
Let us review our error logs and make sure that Checkpoints are indeed been logged.
use [master] go if object_id('transactionLog.sp_checkPointsInErrorLogFileAggregate') is null begin exec('create procedure [transactionLog].[sp_checkPointsInErrorLogFileAggregate] as ') end go alter procedure [transactionLog].[sp_checkPointsInErrorLogFileAggregate] as begin set nocount on; declare @p1 INT declare @p2 INT declare @p3 VARCHAR(255) declare @p4 VARCHAR(255) declare @tblErrorLog TABLE ( [id] int not null identity(1,1) , [LogDate] datetime , [ProcessInfo] sysname , [Text] varchar(600) null , primary key ( [LogDate] , [id] ) , INDEX INDX_ID ( [id] ) ) set @p1 = 0 -- current set @p2 = 1 -- error log set @p3 = 'Ckpt' set @p3 = 'Ckpt dbid' set @p4 = '' insert into @tblErrorLog ( [LogDate] , [ProcessInfo] , [Text] ) exec [sys].[sp_readerrorlog] @p1 = @p1 , @p2 = @p2 , @p3 = @p3 , @p4 = @p4 select tblSD.[name] , tblSD.log_reuse_wait_desc , [count] = count(tblEL.LogDate) , [LogDateMin] = min(tblEL.LogDate) , [LogDateMax] = max(tblEL.LogDate) from sys.databases tblSD left outer join @tblErrorLog tblEL on tblEL.[Text] like '%' + cast(tblSD.database_id as varchar(10)) + '%' and tblEL.[Text] like 'Ckpt dbid ' + '%' + 'started' group by tblSD.[name] , tblSD.log_reuse_wait_desc order by tblSD.log_reuse_wait_desc asc , count(tblEL.LogDate) desc , tblSD.[name] end go
- From digging in the Transaction Log File, we can see that the last Transaction Log on 2017-02-06 20:34
- The timeline is Yesterday, Monday Feb 6th, 2017 8:34 PM
- LogDateMin is 2017-01-15 04:00
- In readable term Jan 15th, 2017 @ 4 AM
In summary, our transaction size is growing and not being pruned because unfortunately our scheduled Transaction backup job was incorrectly set to only occur on Sundays.
Please keep in mind this only affects databases set for FULL RECOVERY.
From the metrics above, we can see that our identified database Transaction Log Checkpoints are only occurring at the tail end of Full Backups.
And, as aforementioned on Sundays.