Getting a history of database snapshot creation

Earlier today someone asked on the #sqlhelp Twitter alias if there is a history of database snapshot creation anywhere, apart from scouring the error logs.

There isn’t, unfortunately, but you can dig around the transaction log of the master database to find some information.

When a database snapshot is created, a bunch of entries are made in the system tables in master and they are all logged, under a transaction named DBMgr::CreateSnapshotDatabase. So that’s where we can begin looking.

Here’s a simple example of a database snapshot:

USE [master];
GO

IF DATABASEPROPERTYEX (N'Company_Snapshot', N'Version') > 0
BEGIN
    DROP DATABASE [Company_Snapshot];
END
GO
IF DATABASEPROPERTYEX (N'Company', N'Version') > 0
BEGIN
    ALTER DATABASE [Company] SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
    DROP DATABASE [Company];
END
GO

-- Create a database
CREATE DATABASE [Company];
GO

-- Create the snapshot
CREATE DATABASE [Company_Snapshot]
ON (NAME = N'Company', FILENAME = N'C:\SQLskills\CompanyData.mdfss')
AS SNAPSHOT OF [Company];
GO

And I can find the transaction using the following code, plus who did it and when:

USE [master];
GO

SELECT
    [Transaction ID],
    SUSER_SNAME ([Transaction SID]) AS [User],
    [Begin Time]
FROM fn_dblog (NULL, NULL)
WHERE [Operation] = N'LOP_BEGIN_XACT'
    AND [Transaction Name] = N'DBMgr::CreateSnapshotDatabase';
GO
Transaction ID User             Begin Time
-------------- ---------------- ------------------------
0000:00099511  APPLECROSS\Paul  2016/10/20 13:07:53:143

Now to get some useful information, I can crack open one of the system table inserts, specifically the insert into one of the nonclustered indexes of the sys.sysdbreg table:

SELECT
    [RowLog Contents 0]
FROM fn_dblog (NULL, NULL)
WHERE [Transaction ID] = N'0000:00099511'
    AND [Operation] = N'LOP_INSERT_ROWS'
    AND [AllocUnitName] = N'sys.sysdbreg.nc1';
GO
RowLog Contents 0
-------------------------------------------------------------------------------------
0x26230000000100290043006F006D00700061006E0079005F0053006E0061007000730068006F007400

Bytes 2 through 5 (considering the first byte as byte 1) are the byte-reversed database ID of the snapshot database, and bytes 10 through the end of the data are the sysname name of the database. Similarly, grabbing the insert log record for the nonclustered index of the sys.syssingleobjrefs table allows us to get the source database ID.

Here’s the finished code:

SELECT * FROM
(
SELECT
    SUSER_SNAME ([Transaction SID]) AS [User],
    [Begin Time]
FROM fn_dblog (NULL, NULL)
WHERE [Transaction ID] = N'0000:00099511'
    AND [Operation] = N'LOP_BEGIN_XACT'
) AS [who],
(
SELECT
    CONVERT (INT,
        SUBSTRING ([RowLog Contents 0], 5, 1) +
        SUBSTRING ([RowLog Contents 0], 4, 1) +
        SUBSTRING ([RowLog Contents 0], 3, 1) +
        SUBSTRING ([RowLog Contents 0], 2, 1)) AS [Snapshot DB ID],
    CONVERT (SYSNAME, SUBSTRING ([RowLog Contents 0], 10, 256)) AS [Snapshot DB Name]
FROM fn_dblog (NULL, NULL)
WHERE [Transaction ID] = N'0000:00099511'
	AND [Operation] = N'LOP_INSERT_ROWS'
	AND [AllocUnitName] = N'sys.sysdbreg.nc1'
) AS [snap],
(
SELECT
    CONVERT (INT,
        SUBSTRING ([RowLog Contents 0], 5, 1) +
        SUBSTRING ([RowLog Contents 0], 4, 1) +
        SUBSTRING ([RowLog Contents 0], 3, 1) +
        SUBSTRING ([RowLog Contents 0], 2, 1)) AS [Source DB ID]
FROM fn_dblog (NULL, NULL)
WHERE [Transaction ID] = N'0000:00099511'
	AND [Operation] = N'LOP_INSERT_ROWS'
	AND [AllocUnitName] = N'sys.syssingleobjrefs.nc1'
) AS [src];
GO
User             Begin Time               Snapshot DB ID Snapshot DB Name  Source DB ID
---------------- ------------------------ -------------- ----------------- ------------
APPLECROSS\Paul  2016/10/20 13:07:53:143  35             Company_Snapshot  22

I’ll leave it as an exercise for the reader to wrap a cursor around the code to operate on all such transactions, and you can also look in the master log backups using the fn_dump_dblog function (see here for some examples).

Enjoy!

Calling all user group leaders! We want to present for you in 2017!

By the end of December, we at SQLskills will have presented remotely (and a few in-person) to 94 user groups and PASS virtual chapters around the world in 2016!

We’d love to present remotely for your user group in 2017, anywhere in the world. It’s not feasible for us to travel to user groups or SQL Saturdays unless we’re already in that particular city, but remote presentations are easy to do and are becoming more and more popular. We haven’t had any bandwidth problems doing remote presentations in 2016 to groups as far away as South Africa, Australia, and New Zealand, plus Norway, Bulgaria, UK, India, Ukraine, Poland, Ireland, and Canada. This way we can spread the community love around user groups everywhere that we wouldn’t usually get to in person.

Note: we have our own Webex accounts which we generally use, or we can use your GoToMeeting or Webex, but you must use computer audio – we won’t call in by phone as the sound quality is too poor. We also will not use Skype/Lync as we’ve had too many problems with it around user group laptops and sound.

So, calling all user group leaders! If you’d like one of us (me, Kimberly, Jon, Erin, Glenn, Tim) to present remotely for you in 2017 (or maybe even multiple times), send me an email and be sure to include:

  • Details of which user group you represent (and if sending from a shared user group account, your name)
  • The usual day of the month, meeting time, and timezone of the user group
  • Which months you have available, starting in January 2017 (a list of available dates would be ideal)

And I’ll let you know who’s available with what topics so you can pick.

What’s the catch? There is no catch. We’re just continuing our community involvement next year and we all love presenting :-)

And don’t think that because you’re only reading this now (maybe a few weeks or months after the posting date) that we can’t fit you in – send me an email and we’ll see what we can do.

We’re really looking forward to engaging with you all!

Cheers

PS By all means pass the word on to any SharePoint and .Net user group leaders you know too.

Investigating the proportional fill algorithm

This is something that came up recently on the Microsoft Certified Master DL, and is something I discuss in our IEPTO1 class because of the performance implications of it, so I thought it would make an interesting post.

Allocation Algorithms

The SQL Server Storage Engine (SE) uses two algorithms when allocating extents from files in a filegroup: round robin and proportional fill.

Round robin means that the SE will try to allocate from each file in a filegroup in succession. For instance, for a database with two files in the primary filegroup (with file IDs 1 and 3, as 2 is always the log file), the SE will try to allocate from file 1 then file 3 then file 1 then file 3, and so on.

The twist in this mechanism is that the SE also has to consider how much free space is in each of the files in the filegroup, and allocate more extents from the file(s) with more free space. In other words, the SE will allocate proportionally more frequently from files in a filegroup with more free space. This twist is called proportional fill.

Proportional fill works by assigning a number to each file in the filegroup, called a ‘skip target’. You can think of this as an inverse weighting, where the higher the value is above 1, the more times that file will be skipped when going round the round robin loop. During the round robin, the skip target for a file is examined, and if it’s equal to 1, an allocation takes place. If the skip target is higher than 1, it’s decremented by 1 (to a minimum value of 1), no allocation takes place, and consideration moves to the next file in the filegroup.

(Note that there’s a further twist to this: when the -E startup parameter is used, each file with a skip target of 1 will be used for 64 consecutive extent allocations before the round robin loop progresses. This is documented in Books Online here and is useful for increasing the contiguity of index leaf levels for very large scans – think data warehouses.)

The skip target for each file is the integer result of (number of free extents in file with most free space) / (number of free extents in this file). The files in the filegroup with the least amount of free space will therefore have the highest skip targets, and there has to be at least one file in the filegroup with a skip target of 1, guaranteeing that each time round the round robin loop, at least one extent allocation takes place.

The skip targets are recalculated whenever a file is added to or removed from a filegroup, or at least 8192 extent allocations take place in the filegroup.

Investigating the Skip Targets

There’s an undocumented trace flag, 1165, that lets us see the skip targets whenever they’re recalculated and I believe the trace flag was added in SQL Server 2008. It also requires trace flag 3605 to be enabled to allow the debugging info to be output.

Let’s try it out!

First I’ll turn on the trace flags, cycle the error log, creating a small database, and look in the error log for pertinent information:

DBCC TRACEON (1165, 3605);
GO

EXEC sp_cycle_errorlog;
GO

USE [master];
GO

IF DATABASEPROPERTYEX (N'Company', N'Version') > 0
BEGIN
	ALTER DATABASE [Company] SET SINGLE_USER
		WITH ROLLBACK IMMEDIATE;
	DROP DATABASE [Company];
END
GO

CREATE DATABASE [Company] ON PRIMARY (
    NAME = N'Company_data',
    FILENAME = N'D:\SQLskills\Company_data.mdf',
	SIZE = 5MB,
    FILEGROWTH = 1MB)
LOG ON (
    NAME = N'Company_log',
    FILENAME = N'D:\SQLskills\Company_log.ldf'
);

EXEC xp_readerrorlog;
GO
2016-10-04 11:38:33.830 spid56       Proportional Fill Recalculation Starting for DB Company with m_cAllocs -856331000.
2016-10-04 11:38:33.830 spid56       Proportional Fill Recalculation Completed for DB Company new m_cAllocs 8192, most free file is file 1.
2016-10-04 11:38:33.830 spid56       	File [Company_data] (1) has 44 free extents and skip target of 1. 

The m_cAllocs is the threshold at which the skip targets will be recalculated. In the first line of output, it has a random number as the database has just been created and the counter hasn’t been initialized yet. It’s the name of a class member of the C++ class inside the SE that implements filegroup management.

Now I’ll add another file with the same size:

ALTER DATABASE [Company] ADD FILE (
	NAME = N'SecondFile',
	FILENAME = N'D:\SQLskills\SecondFile.ndf',
	SIZE = 5MB,
    FILEGROWTH = 1MB);
GO

EXEC xp_readerrorlog;
GO
2016-10-04 11:41:27.880 spid56       Proportional Fill Recalculation Starting for DB Company with m_cAllocs 8192.
2016-10-04 11:41:27.880 spid56       Proportional Fill Recalculation Completed for DB Company new m_cAllocs 8192, most free file is file 3.
2016-10-04 11:41:27.880 spid56       	File [Company_data] (1) has 44 free extents and skip target of 1. 
2016-10-04 11:41:27.880 spid56       	File [SecondFile] (3) has 79 free extents and skip target of 1. 

Note that even though the two files have different numbers of extents, the integer result of 79 / 44 is 1, so the skip targets are both set to 1.

Now I’ll add a much larger file:

ALTER DATABASE [Company] ADD FILE (
	NAME = N'ThirdFile',
	FILENAME = N'D:\SQLskills\ThirdFile.ndf',
	SIZE = 250MB,
    FILEGROWTH = 1MB);
GO

EXEC xp_readerrorlog;
GO
2016-10-04 11:44:20.310 spid56       Proportional Fill Recalculation Starting for DB Company with m_cAllocs 8192.
2016-10-04 11:44:20.310 spid56       Proportional Fill Recalculation Completed for DB Company new m_cAllocs 8192, most free file is file 4.
2016-10-04 11:44:20.310 spid56       	File [Company_data] (1) has 44 free extents and skip target of 90. 
2016-10-04 11:44:20.310 spid56       	File [ThirdFile] (4) has 3995 free extents and skip target of 1. 
2016-10-04 11:44:20.310 spid56       	File [SecondFile] (3) has 79 free extents and skip target of 50. 

The file with the most free space is file ID 4, so the skip targets of the other files are set to (file 4’s free extents) / (free extents in the file). For example, the skip target for file 1 becomes the integer result of 3995 / 44 = 90.

Now I’ll create a table that can have only one row per page, and force more than 8192 extent allocations to take place (by inserting more than 8192 x 8 rows, forcing that many pages to be allocated). This will also mean the files will have autogrown and will have roughly equal numbers of free extents.

USE [Company];
GO

CREATE TABLE [BigRows] (
	[c1] INT IDENTITY,
	[c2] CHAR (8000) DEFAULT 'a');
GO

SET NOCOUNT ON;
GO

INSERT INTO [BigRows] DEFAULT VALUES;
GO 70000

EXEC xp_readerrorlog;
GO
2016-10-04 11:55:28.840 spid56       Proportional Fill Recalculation Starting for DB Company with m_cAllocs 8192.
2016-10-04 11:55:28.840 spid56       Proportional Fill Recalculation Completed for DB Company new m_cAllocs 8192, most free file is file 3.
2016-10-04 11:55:28.840 spid56       	File [Company_data] (1) has 0 free extents and skip target of 74. 
2016-10-04 11:55:28.840 spid56       	File [ThirdFile] (4) has 0 free extents and skip target of 74. 
2016-10-04 11:55:28.840 spid56       	File [SecondFile] (3) has 74 free extents and skip target of 1. 

We can see that all the files have filled up and auto grown, and randomly file ID 3 is now the one with the most free space.

Spinlock Contention

The skip targets for the files in a filegroup are protected by the FGCB_PRP_FILL spinlock, so this spinlock has to be acquired for each extent allocation, to determine which file to allocate from next. There’s an exception to this when all the files in a filegroup have roughly the same amount of free space (so they all have a skip target of 1). In that case, there’s no need to acquire the spinlock to check the skip targets.

This means that if you create a filegroup that has file sizes that are different, the odds are that they will auto grow at different times and the skip targets will not all be 1, meaning the spinlock has to be acquired for each extent allocation. Not a huge deal, but it’s still extra CPU cycles and the possibility of spinlock contention occurring (for a database with a lot of insert activity) that you could avoid by making all the files in the filegroup the same size initially.

If you want, you can watch the FGCB_PRP_FILL spinlock (and others) using the code from this blog post.

Performance Implications

So when do you need to care about proportional fill?

One example is when trying to alleviate tempdb allocation bitmap contention. If you have a single tempdb data file, and huge PAGELATCH_UP contention on the first PFS page in that file (from  a workload with many concurrent connections creating and dropping small temp tables), you might decide to add just one more data file to tempdb (which is not the correct solution). If that existing file is very full, and the new file isn’t, the skip target for the old file will be large and the skip target for the new file will be 1. This means that subsequent allocations in tempdb will be from the new file, moving all the PFS contention to the new file and not providing any contention relief at all! I discuss this case in my post on Correctly adding data file to tempdb.

The more common example is where a filegroup is full and someone adds another file to create space. In a similar way to the example above, subsequent allocations will come from the new file, meaning that when it’s time for a checkpoint operation, all the write activity will be on the new file (and it’s location on the I/O subsystem) rather than spread over multiple files (and multiple locations in the I/O subsystem). Depending on the characteristics of the I/O subsystem, this may or may not cause a degradation in performance.

Summary

Proportional fill is an algorithm that it’s worth knowing about, so you don’t inadvertently cause a performance issue, and so that you can recognize a performance issue caused by a misconfiguration of file sizes in a filegroup. I don’t expect you to be using trace flag 1165, but if you’re interested, it’s a way to dig into the internals of the allocation system.

Enjoy!