The September edition of TechNet Magazine is available on the web now and has the latest installment of my regular SQL Q&A column.

This month's topics are:

• Online index operations logging changes in SQL Server 2008
• Is that transaction contained in my full backup?
• ALTER INDEX ... REBUILD vs. ALTER INDEX ... REGORGANIZE
• Avoiding regular log file shrinking

Check it out at http://technet.microsoft.com/en-us/magazine/hh395481.aspx.

We're teaching on-site with a financial client in New York for two weeks and in a session this morning on log file architecture I was asked why the VLF (virtual log file) sequence numbers in a new database don't start at one.

Here's an example:

CREATE DATABASE foo;
GO
DBCC LOGINFO ('foo');
GO

FileId  FileSize  StartOffset FSeqNo Status  Parity  CreateLSN
------- --------- ----------- ------ ------- ------- ------------------
2       253952    8192        137    2       64      0
2       253952    262144      0      0       0       0

Why is the first sequence number (FSeqNo) 137 and not 1? (For an explanation of the various fields in the output of the undocumented DBCC LOGINFO, see the post Inside the Storage Engine: More on the circular nature of the log.)

The answer is that it's one more than the highest VLF sequence number currently in the model database. Let's see:

DBCC LOGINFO ('model');
GO

FileId  FileSize  StartOffset FSeqNo Status  Parity  CreateLSN
------- --------- ----------- ------ ------- ------- ------------------
2       253952    8192        136    2       128     0
2       262144    262144      135    0       128     0

The highest FSeqNo in the output above is 136, which accounts for the 137 in the new user database.

Now I'll prove it by increasing the sequence number in the model database:

USE model;
GO
CREATE TABLE BigRows (c1 INT IDENTITY, c2 CHAR (8000) DEFAULT 'a');
GO
INSERT INTO BigRows DEFAULT VALUES;
GO 50
DBCC LOGINFO;
GO

FileId  FileSize  StartOffset FSeqNo Status  Parity  CreateLSN
------- --------- ----------- ------ ------- ------- ------------------
2       253952    8192        136    0       128     0
2       262144    262144      137    2       128     0

And now I'll create another user database and the first VLF sequence number should be 138:

CREATE DATABASE foo2;
GO
DBCC LOGINFO ('foo2');
GO

FileId  FileSize  StartOffset FSeqNo Status  Parity  CreateLSN
------- --------- ----------- ------ ------- ------- ------------------
2       253952    8192        138    2       64      0
2       360448    262144      0      0       0       0

And it is - proven!

The eagle-eyed among you may notice that the log file size of the database foo2 I just created is larger than the size of the foo database I initially created. This is because the default log file size is the higher of 0.5MB or 25% of the sum of the data files created. In this case, the data file is copied from the model database, and I made it larger when I created the BigRows table, so the log file of the new database has to be slightly larger.

One question that came up in the post comments - why is the highest VLF sequence number in my model database 136? No particular reason except I've done a bunch of things in model which generated transaction log and so the VLF sequence numbers have increased. It's almost certain to be different in your SQL Server instances for that reason.

Next up tomorrow - results from the index count survey from last month.

The July edition of TechNet Magazine is available on the web now and has the latest installment of my regular SQL Q&A column.

This month's topics are:

• Deferred log truncation from concurrent data and log backups
• Database mirroring monitoring
• Multiple transaction log files
• Best use of SSDs in a SQL environment (high-level)

Check it out at http://technet.microsoft.com/en-us/magazine/hh334997.aspx.

The January edition of TechNet Magazine is available on the web now and has the latest installment of my regular SQL Q&A column.

This month's topics are:

• Diagnosing I/O subsystem bottlenecks
• Capacity planning for transaction logs
• Why there are no non-logged operations in user databases

Check it out at http://technet.microsoft.com/en-us/magazine/gg552991.aspx.

(Happy Independence Day to everyone back home in the USA! We're in Dublin for another week...) 

Back at the end of April I conducted a survey of transaction log characteristics (see here) and now I present the results to you.

I had a great response to the survey from almost 100 people, and the total data set for these observations is 16841 databases on 847 SQL Server instances (SQL Server Edition is irrelevant).

This isn't the most exciting blog post, but I at least found the numbers interesting - hope you do too! I've got some pointers in the summary to log management blog posts.

Number of Databases Per Instance 

Each plot on the graph below is a count of the number of instances having that many databases, including the four system databases.

Just under 75% of instances have 20 or fewer databases (including system databases). The highest number per instance is 571.

Number of Log Files Per Database

This wasn't worth plotting. The results are:

Log Files   Number of Databases
1           16657
2           158
3           9
4           8
5           1
6           4
7           1
24          1

I'm impressed by this - I expected to see more databases with multiple log files. The one with 24 is tempdb - someone setting the number of log files to equal the number of processor cores I'd guess.

System Databases: Log File Size

Each plot on the graph below shows the number of log files of that size across all the instances, color-coded for master, msdb and tempdb.

89% of master database log files are less than 10MB (a number I arbitrarily chose as a comparison point).

Only 40% of msdb log files are less than 10MB. This would suggest that there are a high proportion of msdb databases not using the SIMPLE recovery model. However, only 5% of them aren't using SIMPLE.

Only 33% of tempdb log files are less than 10MB. I would expect this number to be low.

Looking at the distribution on the graph, master log files (blue) are generally smaller, tempdb log files (green) are generally larger, with msdb (red) in the middle. Again, this is what I'd expect to see.

System Databases: Number of VLFs

Each plot on the graph below shows the number of log files with that many VLFs across all the instances, color-coded for master, msdb and tempdb. (If you're unfamiliar with the term 'VLFs', see the TechNet Magazine article I link to at the bottom).

98.6% of all master log files have less than 100 VLFs (our arbitrary 'you may have too many VLFs' tipping point), with the maximum being 331.

Only 65% of all msdb log files have less than 100 VLFs. From the other 35%, only 5% of them aren't using the SIMPLE recovery model. The maximum number of VLFs is 7646.

Surprisingly, 75% of tempdb log files have less than 100 VLFs. I expected this number to be higher in general, because of tempdb autogrowth. The maximum number of VLFs is 59708.

Looking at the graph, master (blue) is as I expected, but msdb (red) and tempdb (green) are the opposite of what I expected - with more msdb log files having more VLFs.

User Databases: Log File Size

Out of all 13451 user databases in the sample:

• 6797 use the SIMPLE recovery model (50.5%)
• 177 use the BULK_LOGGED recovery model (1.3%)
• 6477 use the FULL recovery model (48.2%)

This in itself is surprising - I expected to see a higher proportion of FULL recovery model databases. 

Given that the log file behavior is the same for FULL and BULK_LOGGED recovery models, and as so few databases use the BULK_LOGGED recovery model, I lumped the FULL and BULK_LOGGED databases together for analysis.

Each plot on the graphs below shows the number of log files of a certain size across all the instances.

The graphs above have different sizes because more databases in the SIMPLE recovery model are larger sized. The overall distribution looks very similar though.

90.7% of user databases using the SIMPLE recovery model have a log file size less than 1GB, compared with 83.0% for non-SIMPLE user databases.

98.2% of SIMPLE user databases have a log file size less than 10GB, compared with 96.8% for non-SIMPLE user databases.

The maximum size of a log file for a SIMPLE user database is 1020GB, dropping to 326GB for a non-SIMPLE user database.

The non-SIMPLE user databases seem to be slightly better managed. My guess would be this represents databases that have been in the FULL or BULK_LOGGED recovery models, have grown out of control and been switched to SIMPLE, but not cleaned up.

User Databases: Number of VLFs

Each plot on the graphs below shows the number of log files with a certain number of VLFs across all the instances.

As with the log file sizes, the distributions of these two graphs look very similar. 

76.9% of user databases using the SIMPLE recovery model have less than 100 VLFs, dropping to 67.8% for those not using SIMPLE.

98.4% of user databases using the SIMPLE recovery model have less than 500 VLFs (definitely a point at which maintenance is required), dropping to 97.0% for those not using SIMPLE.

The maximum number of VLFs for the SIMPLE user databases is 34057, and 27093 for those not using SIMPLE.

Given that more user databases using SIMPLE are larger, but have slightly fewer VLFs, I'd guess this indicates that autogrowth of thse databases was slightly higher.

User Databases: Log File Size vs. Number of VLFs

At first glance, the graph below looks confusing. It shows the number of VLFs each log file has compared to its size in MB. If you look at the first few log file sizes, you'll see that there are multiple points plotted on the Y-axis. This is because there are databases that have the same size log files, but the log files have different numbers of VLFs.

There's definitely a loose trend-line in the graph, with a knee at around 50MB log file size.

Summary

I'm impressed. 75% of all databases in the sample have less than 100 VLFs, and 97.4% have less than 500 VLFs. I expected the results to be worse, but they seem show that the majority of you are managing your logs well. Now, these results are a bit skewed though because they're coming from people who read my blog, where I bang on and on about good maintenance and management.

I was very surprised by the 50/50 split of SIMPLE/non-SIMPLE recovery model for user databases. My guess is that more of these *should* be in FULL to comply with business SLAs around RPO/data-loss, but for some reason aren't, or aren't any longer because of out-of-control growth issues.

Thanks to everyone who sent me results!

Here are some links for further reading:

• Importance of proper transaction log size management
• TechNet Magazine: Understanding Logging and Recovery in SQL Server
• Transaction Log VLFs - too many or too few?
• 8 Steps to better Transaction Log throughput
• New script: is that database REALLY in the FULL recovery mode?

Enjoy!

One of the first things you should always check when a database has been damaged and you're going to perform a restore operation is whether you need to back up the tail of the log.

The tail of the log contains the transaction log that's been generated since the most recent log backup was taken. If you want to be able to recover right up to the point of the disaster, you need to be able to get those log records so they can be part of the restore sequence.

There are two cases to consider here 1) the server is still available 2) the server is not available. For case 1, you can just perform a regular tail-of-the-log backup. For case 2, you'll need to hack-attach the log into another server to be able to back it up.

Case 1: tail-of-the-log backup when server is available

If the database is damaged but the server is still available, taking a tail-of-the-log backup is simple. The only exception is when there has been a minimally-logged operation performed in the BULK_LOGGED recovery model since the previous log backup - in that case a tail-of-the-log backup is not possible at all, and you'll have lost all transaction log generated since the last log backup. See A SQL Server DBA myth a day: (28/30) BULK_LOGGED recovery model for more details.

When the data files are damaged and you want to take a log backup, you'll get an error if you try to back up the log normally.

As an example, I'll create a database and put some transactions in it:

CREATE DATABASE DBMaint2008;
GO
USE DBMaint2008;
GO

CREATE TABLE TestTable (C1 INT IDENTITY, C2 CHAR (100));
GO

-- Take a full backup
BACKUP DATABASE DBMaint2008 TO DISK = 'D:\SQLskills\DemoBackups\DBMaint_Full.bck' WITH INIT;
GO

-- Insert some rows
INSERT INTO TestTable VALUES ('Transaction 1');
INSERT INTO TestTable VALUES ('Transaction 2');
GO

-- Take a log backup
BACKUP LOG DBMaint2008 TO DISK = 'D:\SQLskills\DemoBackups\DBMaint_Log1.bck' WITH INIT;
GO

-- Insert some more rows
INSERT INTO TestTable VALUES ('Transaction 3');
INSERT INTO TestTable VALUES ('Transaction 4');
GO

Now disaster will strike - I'll do the following to simulate a disaster:

1. ALTER DATABASE DBMaint2008 SET OFFLINE
2. Delete the data file

If I try to then access the database, I'll get:

ALTER DATABASE DBMaint2008 SET ONLINE;
GO

Msg 5120, Level 16, State 101, Line 1
Unable to open the physical file "C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\DBMaint2008.mdf". Operating system error 2: "2(The system cannot find the file specified.)".
Msg 945, Level 14, State 2, Line 1
Database 'DBMaint2008' cannot be opened due to inaccessible files or insufficient memory or disk space.  See the SQL Server errorlog for details.
Msg 5069, Level 16, State 1, Line 1
ALTER DATABASE statement failed.

So I'll try a normal log backup:

BACKUP LOG DBMaint2008 TO DISK = 'D:\SQLskills\DemoBackups\DBMaint_Log_Tail.bck' WITH INIT;
GO

Msg 945, Level 14, State 2, Line 1
Database 'DBMaint2008' cannot be opened due to inaccessible files or insufficient memory or disk space.  See the SQL Server errorlog for details.
Msg 3013, Level 16, State 1, Line 1
BACKUP LOG is terminating abnormally.

It doesn't work - as the data files aren't all accessible.

The trick is to use the NO_TRUNCATE option, which allows the log backup even if the database files aren't there:

BACKUP LOG DBMaint2008 TO DISK = 'D:\SQLskills\DemoBackups\DBMaint_Log_Tail.bck' WITH INIT, NO_TRUNCATE;
GO

Processed 2 pages for database 'DBMaint2008', file 'DBMaint2008_log' on file 1.
BACKUP LOG successfully processed 2 pages in 0.010 seconds (0.972 MB/sec).

I can then use the tail-of-the-log backup as the final backup in the restore sequence, saving transactions 3 and 4 from above. Try it for yourself.

Case 2: tail-of-the-log backup when server is no longer available

This is the case where the server crashed and cannot be brought online. If you have access to all the data and log files for the database, you can attach it to another server and crash recovery will run automatically. If you only have access to the log file, you'll need to perform some extra steps to allow a tail-of-the-log backup to be performed - basically performing what I call a hack-attach.

Assuming I've run the script above to setup the database, this time I'll do the following to simulate a server-crash disaster:

1. ALTER DATABASE DBMaint2008 SET OFFLINE
2. Delete the data file
3. Copy the log file somewhere else
4. DROP DATABASE DBMaint2008

Now all I have is some backups and a log file. I'll need to attach the log file to SQL Server somehow so that I can perform the vital tail-of-the-log backup. The way to do it is:

1. Create a dummy database with the same name as the one that we're interested in (make sure you have instant file initialization enabled so the file creations don't take ages - see this blog post)
2. Set the database offline (or shutdown the server)
3. Delete all the files from the dummy database
4. Drop in the log file from our real database

Like so for steps 1 and 2:

CREATE DATABASE DBMaint2008;
GO
ALTER DATABASE DBMaint2008 SET OFFLINE;
GO

Now I'll perform steps 3 and 4.

I need to attempt to bring the database online again:

ALTER DATABASE DBMaint2008 SET ONLINE;
GO

Msg 5120, Level 16, State 101, Line 1
Unable to open the physical file "C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\DBMaint2008.mdf". Operating system error 2: "2(The system cannot find the file specified.)".
Msg 945, Level 14, State 2, Line 1
Database 'DBMaint2008' cannot be opened due to inaccessible files or insufficient memory or disk space.  See the SQL Server errorlog for details.
Msg 5069, Level 16, State 1, Line 1
ALTER DATABASE statement failed.

And then I can perform the tail-of-the-log backup as before, and use it to recover everything up to the point of the disaster.

Note: This procedure does not work if I try to perform the hack-attach to a more recent version of SQL Server. I tried hacking a 2005 log into a 2008 server and taking the tail-of-the-log backup - which worked fine, but the tail-of-the-log backup could not be used in conjunction with the first set of backups from the 2005 server. The reason for this is that the database version number in the tail-of-the-log backup is 655 (SQL Server 2008) and those for the 2005 backups are 611 (SQL Server 2005). The database doesn't get upgraded when restoring on the 2008 server until the end of the restore sequence - so as far as the 2008 server is concerned, my 2008 tail-of-the-log backup can't be used in the restore seqeunce of a still-2005-really database. Hope that makes sense!

Summary

Checking whether a tail-of-the-log backup is required is essential during a disaster recovery, and it's not hard to do. As with any disaster recovery procedures, make sure you've practiced doing it in advance!

I was teaching an internals/maintenance/performance class for Microsoft DBAs this week on the Redmond campus and one of the students (thanks Crystal!) showed me a really strange bug that I'd never seen before.

One of the things that Kimberly and I both recommend is not having transaction log VLFs be too large, with 500MB being our recommended maximum so as not to interrupt the clearing/truncating of the log. See Kimberly's blog post Transaction Log VLFs - too many or too few? for more details.

If you try to grow a log file by a multiple of 4GB, it will fail on the first attempt and only grow by about 31KB, with no error message. The second attempt will succeed!

We've examined the SQL code and it's a bug that the code miscalculates the growth size when the specified size is an exact multiple of 4GB. Simple type conversion error. It's fixed in the SQL11 code already.

This could cause you problems if you follow our advice and try to grow a log file in increments of 8GB to keep the VLF size at 500MB (a growth of 1GB or more create 16VLFs, with each VLF being 1/16th the size of the growth).

I tested this on 2005 SP3 and 2008 SP1.

Here's an example script to show what I mean. First off I'll create a database and grow the log file to 1GB.

CREATE DATABASE TestLogFileGrowth;
GO

ALTER DATABASE TestLogFileGrowth MODIFY FILE
(
    NAME = TestLogFileGrowth_Log, SIZE = 1GB
);
GO

That took 30 seconds to run, performing the zero initialization of the log file (which must *always* occur - see Search Engine Q&A #24: Why can't the transaction log use instant initialization?).

Checking the log size:

DBCC SQLPERF (LOGSPACE);
GO

Database Name       Log Size (MB) Log Space Used (%) Status
------------------- ------------- ------------------ -------
<snip>
TestLogFileGrowth   1023.992      0.0733858          0

Now I'll try to grow the log file by 4GB:

ALTER DATABASE TestLogFileGrowth MODIFY FILE
(
    NAME = TestLogFileGrowth_Log, SIZE = 5GB
);
GO

This took zero seconds. Impossible if it actually grew the log by 4GB and zero initialized it!!

Let's check the log size:

DBCC SQLPERF (LOGSPACE);
GO

Database Name      Log Size (MB) Log Space Used (%) Status
------------------ ------------- ------------------ -----------
<snip>
TestLogFileGrowth  1024.234      0.07994729         0

Weird! It only grew by 1MB! If I try the grow again (and as long as I don't specify a size that's an exact multiple of 4GB from the current size), it takes a couple of minutes and grows correctly.

Don't be surprised if you see this.

Cheers

(Look in the Misconceptions blog category for the rest of the month's posts and check out the 60-page PDF with all the myths and misconceptions blog posts collected together: CommonSQLServerMyths.pdf (732.96 kb))

The month is finally over so time for the grand finale!

Although it's been fun debunking all these myths, it's been a tad stressful making sure I come up with an interesting and useful myth to debunk every day. I'd like to give kudos to fellow-MVP Glenn Berry (blog|twitter) who's been running an excellent DMV-a-Day series through April too!

To round out the month, I present to you 30 myths around backups - one for each day of the month of April. Last night I sat down to write this post and was a few myths short so reached out to the fabulous SQL community on Twitter (follow me!) for help - too many people to list (you know who you are) - I thank you!

A few folks have asked if I'll pull the month's posts into a PDF e-book - let me know if you'd like that.

I *really* hope you've enjoyed the series over the last month and have had a bunch of myths and misconceptions debunked once and for all - I know quite a few of you are going to use these explanations as ammunition against 3rd-party vendors, developers, and other DBAs who insist on incorrect practices.

Ok - here we go with the last one...

Myth #30: various myths around backups...

All are FALSE!!

For a good primer on understanding backups and how they work see my TechNet Magazine article Understanding SQL Server Backups. 

30-01) backup operations cause blocking

No. Backup operations do not take locks on user objects. Backups do cause a really heavy read load on the I/O subsystem so it might *look* like the workload is being blocked, but it isn't really. It's just being slowed down. There's a special case where a backup that has to pick up bulk-logged extents will take a file lock which could block a checkpoint operation - but DML is never blocked.

30-02) switching from the FULL recovery model to the BULK_LOGGED recovery model and back again breaks the log backup chain

No. It just doesn't. Switching from either FULL or BULK_LOGGED to SIMPLE *does* break the log backup chain however.

30-03) breaking the log backup chain requires a full backup to restart it

No. You can restart the log backup chain with either a full or differential backup - anything that bridges the LSN gap from the point at which the log backup chain was broken. See my blog post A SQL Server DBA myth a day: (20/30) restarting a log backup chain requires a full database backup for more details.

30-04) concurrent log backups are not possible while a full or differential backup is in progress 

No, this changed in SQL Server 2005. See my blog post Search Engine Q&A #16: Concurrent log and full backups.

30-05) a full or differential backup clears the log

No. A log backup includes all the log since the last log backup - nothing can change that - no matter whether that log was also backed up by a full or differential backup. I had a famous argument on Twitter last year and wrote this blog post as proof: Misconceptions around the log and log backups: how to convince yourself. In the FULL or BULK_LOGGED recovery models, the *only* thing that clears the log is a log backup.

30-06) using the BULK_LOGGED recovery model for minimally-logged operations reduces the size of the next transaction log backup

No. A minimally-logged operation is so-named because only the page allocations are logged. A log backup needs all the information necessary to resconstitute the transaction, so a log backup following a minimally-logged operation must backup the log plus all extents changed by the minimally-logged operation. This will result in the log backup being roughly the same size as if the operation was fully logged.

30-07) full and differential backups only contain the log generated while the backup was running

No. A full or differential backup contains enough log to be able to recover the database to a transactionally-consistent view of the database at the time the data-reading portion of the backup finished (or as far back as the oldest log record that transactional replication has not yet processed - to ensure that replication works properly after a restore). Check out these two blog posts for details:

• Debunking a couple of myths around full database backups
• More on how much transaction log a full backup includes

30-08) backups always test existing page checksums

No. It only does it when you use the WITH CHECKSUM option - which you should.

No. Nothing else to say.

30-11) if the backup works, the restore will too

No. Please don't fall into this trap. You must regularly validate your backups to give yourself a high level of confidence that they will work if a disaster occurs. See Importance of validating backups for more details.

30-12) a mirrored backup will succeed if the mirror location becomes unavailable

No. If any one of the paths to a mirrored backup fails, the entire mirrored backup operation fails. I'd really like it to work the other way around - where the local backup succeeds and the remote backups fail, but it doesn't unfortunately.

30-13) a tail-of-the-log backup is always possible

No. A tail-of-the-log backup is one that backs up all the log generated since the last log backup, in an exceptional situation. If the data files are damaged, you can still do a tail-of-the-log backup EXCEPT if the un-backed-up log contains a minimally-logged operation. That would require reading data extents - which cannot be done if the data files are damaged. For this reason, the BULK_LOGGED recovery model should not be used on databases that have 24x7 user transactions.

30-14) you can use backups instead of DBCC CHECKDB

No. See A SQL Server DBA myth a day: (27/30) use BACKUP WITH CHECKSUM to replace DBCC CHECKDB.

30-15) you can backup a database snapshot

No. It's not implemented, but would be great if you could.

30-16) you can use database snapshots instead of log backups

No. A database snapshot is only usable while the database on which it is based is usable and online. If the source database is corrupted, the database snapshot most likely is too. If the source database goes suspect, so does the database snapshot.

Also, having multiple database snapshots (equating to multiple log backups) incurs an increasing performance drain - as every page that changes in the source database may need to be synchronously written to all existing snapshots before it can be written to the source database data files, and all existing database snapshots will grow as more pages are pushed into them.

30-17) log backups will be the size of the log

No. The log has to accomodate the space necessary to roll back active transactions, the amount of space returned by DBCC SQLPERF (LOGSPACE) on a busy system doesn't accurately refect the amount of log records in the log. This blog spot explains: Search Engine Q&A #25: Why isn't my log backup the same size as my log? And apart from that, a log backup is just all the log generated since the last log backup - not the whole log file usually - and if it happens to be, the first part of the explanation comes into play.

30-18) you cannot backup a corrupt database

No. In most cases you can use the WITH CONTINUE_AFTER_ERROR option to back up the corrupt database.  If that fails (maybe because of a damaged boot page or file-header page), there are no other options apart from OS-level file backups.

30-19) you cannot stop someone doing a BACKUP LOG .. WITH NO_LOG or TRUNCATE_ONLY operation

No. In SQL Server 2008 it's not possible any more (yay!) and in 2005 and before, use trace flag 3231 which turns the operation into a no-op.

30-20) log backups always clear the log

No.

If there's no concurrent data backup running, a log backup will always *try* to clear the log, and only succeed in clearing the inactive portion of the log - the log that's only considered 'required' by SQL Server because it hasn't yet been backed up. If anything else is holding the log 'required', it cannot be cleared, even though it has been backed up. Subsequent log backups will check again and again until the time comes when that portion of the log can be cleared. The TechNet Magazine article Understanding Logging and Recovery in SQL Server I wrote last year explains a lot more about how the log works.

Also, if there is a concurrent data backup running, the log clearing will be delayed until the data backup finishes. See the blog post in myth 30-04 for more details.

30-21) differential backups are incremental

No. Differential backups are all the data extents that have changed since the last full backup - so they are cumulative. Log backups are incremental - all log generated since the last log backup. Many people call differential backups 'incrementals', when they're not really.

30-22) once a backup completes, you can safely delete the previous one

No. No. No.

If you go to restore, and you find your full backup is corrupt, what do you do? Well, if you don't have an older full backup, you most likely start updating your resume. You need to keep a rolling-window of backups around in case a disaster occurs and you need to restore from an older set of backups.

30-23) you can back up a mirror database

No. A mirror database is not accessible except through a database snapshot. And you can't back up that either.

30-24) you can back up a single table

No. You can effectively back up single table if it happens to be wholely contained on a single filegroup, but there's no way to say BACKUP TABLE.

30-25) SQL Server has to be shut down to take a backup

No. No idea how this myth started... [Edit: apparently this myth started with Oracle - and we all know how good Oracle is compared to SQL Server... :-)]

30-26) my transaction is guaranteed to be contained in the backup if it committed before the backup operation completed

No. The commit log record for the transaction has to have been written out before the data-reading portion of the backup finished. See my blog post Search Engine Q&A #6: Using fn_dblog to tell if a transaction is contained in a backup for more details.

30-27) you should shrink the database before a backup to reduce the backup size

No. Shrink just moves pages around so won't make any difference. See my old blog post Conference Questions Pot-Pourri #10: Shrinking the database before taking a backup. And of course, shrink is evil. See A SQL Server DBA myth a day: (9/30) data file shrink does not affect performance. And what's even worse as someone reminded me, is if you do the shrink *after* the full backup, the next differential backup may be huge, for no actual data changes!

30-28) backups are always the best way to recover from a disaster

No. Backups are usually the best way to recover with zero data-loss (as long as you have log backups up to the point of the disaster), but not necessarily the best way to recover with minimal downtime. It may be way faster to fail over, or to run repair and accept some data loss if the business requirements allow it.

30-29) you don't need to back up master, msdb, model...

No. You should always back up the system databases. Master contains all the security info, what databases exist - msdb contains all the SSIS packages, Agent jobs, backup history - model contains the configuration for new databases. Don't fall into the trap of only backing up user databases otherwise you'll be in a world of hurt if you have to do a bare-metal install.

30-30) you should always plan a good backup strategy

No. Now you're thinking 'Huh?'...

You should plan a restore strategy. Use the business requirements and technical limitations to figure out what you need to be able to restore in what time, and then use that to figure out what backups you need to take to allow those restores to happen. See the blog posts:

• Importance of having the right backups
• Planning a backup strategy - where to start?

The vast majority of the time people plan a backup strategy without testing or thinking about restores - and come a disaster, they can't restore within their SLAs. Don't let that be you.

(Look in the Misconceptions blog category for the rest of the month's posts and check out the 60-page PDF with all the myths and misconceptions blog posts collected together: CommonSQLServerMyths.pdf (732.96 kb))

The BULK_LOGGED recovery model continues to confuse people...

Myth #28: various myths around the BULK_LOGGED recovery model.

28a) regular DML operations can be minimally-logged

No.

Only a small set of bulk operations can be minimally-logged when in the BULK_LOGGED (or SIMPLE) recovery model. The list is in the Books Online topic Operations That Can Be Minimally Logged has the list. This is the 2008 link - make sure to check the link for the version you're running on.

28b) using the BULK_LOGGED recovery model does not affect disaster recovery

No.

Firstly, if a minimally-logged operation has been performed since the last log backup, and one or more data files were damaged and offline because of the disaster, a tail-of-the-log backup cannot be performed and so all user transactions performed since the last log backup will be lost.

Secondly, if a log backup contains a minimally-logged operation, a point-in-time restore cannot be performed to any time covered by the log backup. The log backup can either not be restored, or be restored in its entirety (plus additional log backups if required) - i.e. you can restore to a point:

• Before the beginning of that log backup
• At the end of that log backup
• After the end of that log backup

But you can't restore to a point during that log backup.

28c) using the BULK_LOGGED recovery model also reduces the size of log backups

No.

A log backup that includes a minimally-logged operation must backup the minimal amount of transaction log *and* all the data file extents changed by that operattion - otherwise the restore of the log backup would not fully reconstitute the minimally-logged operation. This means that log backups are roughly the same size whether in the FULL or BULK_LOGGED recovery model.

(Look in the Misconceptions blog category for the rest of the month's posts and check out the 60-page PDF with all the myths and misconceptions blog posts collected together: CommonSQLServerMyths.pdf (732.96 kb))

Nested transactions are an evil invention designed to allow developers to make DBAs' lives miserable. In SQL Server, they are even more evil...

Myth #26: nested transactions are real in SQL Server.

FALSE!!!

Nested transactions do not actually behave the way the syntax would have you believe. I have no idea why they were coded this way in SQL Server - all I can think of is someone from the dim and distant past is continually thumbing their nose at the SQL Server community and going "ha - fooled you!!".

Let me explain. SQL Server allows you to start transactions inside other transactions - called nested transactions. It allows you to commit them and to roll them back.

The commit of a nested transaction has absolutely no effect - as the only transaction that really exists as far as SQL Server is concerned is the outer one. Can you say 'uncontrolled transaction log growth'? Nested transactions are a common cause of transaction log growth problems because the developer thinks that all the work is being done in the inner transactions so there's no problem.

The rollback of a nested transaction rolls back the entire set of transactions - as there is no such thing as a nested transaction.

Your developers should not use nested transactions. They are evil.

If you don't believe me, here's some code to show you what I mean. First off - create a database with a table that each insert will cause 8k in the log.

CREATE DATABASE NestedXactsAreNotReal;
GO
USE NestedXactsAreNotReal;
GO
ALTER DATABASE NestedXactsAreNotReal SET RECOVERY SIMPLE;
GO
CREATE TABLE t1 (c1 INT IDENTITY, c2 CHAR (8000) DEFAULT 'a');
CREATE CLUSTERED INDEX t1c1 ON t1 (c1);
GO
SET NOCOUNT ON;
GO

Test #1: Does rolling back a nested transaction only roll back that nested transaction?

BEGIN TRAN OuterTran;
GO

INSERT INTO t1 DEFAULT Values;
GO 1000

BEGIN TRAN InnerTran;
GO

INSERT INTO t1 DEFAULT Values;
GO 1000

SELECT @@TRANCOUNT, COUNT (*) FROM t1;
GO

I get back the results 2 and 2000. Now I'll roll back the nested transaction and it should only roll back the 1000 rows inserted by the inner transaction...

ROLLBACK TRAN InnerTran;
GO

Msg 6401, Level 16, State 1, Line 1
Cannot roll back InnerTran. No transaction or savepoint of that name was found.

Hmm... from Books Online, I can only use the name of the outer transaction or no name. I'll try no name:

ROLLBACK TRAN;
GO

SELECT @@TRANCOUNT, COUNT (*) FROM t1;
GO

And I get the results 0 and 0. As Books Online explains, ROLLBACK TRAN rolls back to the start of the outer transaction and sets @@TRANCOUNT to 0. All changes are rolled back. The only way to do what I want is to use SAVE TRAN and ROLLBACK TRAN to the savepoint name.

Test #2: Does committing a nested transaction really commit the changes made?

BEGIN TRAN OuterTran;
GO

BEGIN TRAN InnerTran;
GO

INSERT INTO t1 DEFAULT Values;
GO 1000

COMMIT TRAN InnerTran;
GO

SELECT COUNT (*) FROM t1;
GO

I get the result 1000, as expected. Now I'll roll back the outer transaction and all the work done by the inner transaction should be preserved...

ROLLBACK TRAN OuterTran;
GO

SELECT COUNT (*) FROM t1;
GO

And I get back the result 0. Oops - committing the nested transaction did not make its changes durable.

Test #3: Does committing a nested transaction at least let me clear the log?

I recreated the database again before running this so the log was minimally sized to begin with, and the output from DBCC SQLPERF below has been edited to only include the NestedXactsAreNotReal database.

BEGIN TRAN OuterTran;
GO

BEGIN TRAN InnerTran;
GO

INSERT INTO t1 DEFAULT Values;
GO 1000

DBCC SQLPERF ('LOGSPACE');
GO

Database Name         Log Size (MB) Log Space Used (%) Status
--------------------- ------------- ------------------ -----------
NestedXactsAreNotReal 12.05469      95.81983           0

Now I'll commit the nested transaction, run a checkpoint (which will clear all possible transaction log in the SIMPLE recovery model), and check the log space again:

COMMIT TRAN InnerTran;
GO

CHECKPOINT;
GO

DBCC SQLPERF ('LOGSPACE');
GO

Database Name         Log Size (MB) Log Space Used (%) Status
--------------------- ------------- ------------------ -----------
NestedXactsAreNotReal 12.05469      96.25324           0

Hmm - no change - in fact the Log Space Used (%) has increased slightly from writing out the checkpoint log records (see How do checkpoints work and what gets logged). Committing the nested transaction did not allow the log to clear. And of course not, because a rollback can be issued at any time which will roll back all the way to the start of the outer transaction - so all log records are required until the outer transaction commits or rolls back.

And to prove it, I'll commit the outer transaction and run a checkpoint:

COMMIT TRAN OuterTran;
GO

CHECKPOINT;
GO

DBCC SQLPERF ('LOGSPACE');
GO

Database Name         Log Size (MB) Log Space Used (%) Status
--------------------- ------------- ------------------ -----------
NestedXactsAreNotReal 12.05469      26.4339            0

And it drops right down.

Nested transactions - just say no! (a public service announcement from the nice folks at SQLskills.com :-)

Over the last few months there's been some noise (mostly of my making) on Twitter about the number of VLFs in transsction logs. Given the large numbers of people who read the blog and follow me on Twitter, I thought it would be very interesting to collect some statistics from a few hundred of you about how your transction logs are configured - in terms of the size, number of log files, and number of VLFs.

To that end, I've created a little script that you can download and run which will generate output of the form:

DB ID  Recovery Model  Log Size (MB)  Log Used (%)   Log File Count  VLF Count 
------ --------------- -------------- -------------- --------------- ----------
1      SIMPLE          6.12           34.42          1               22
2      SIMPLE          0.49           75.60          1               2 
3      FULL            14.68          97.90          1               51
4      SIMPLE          2.49           45.92          1               10
11     SIMPLE          1.99           33.55          1               4
12     FULL            359.99         77.84          1               96
13     FULL            0.48           45.67          1               2

I'd like as many of you as possible to send me the results for some of your systems - there are no database names in the output and the results will be completely anonymous. I'll collect all the results together and blog some scatter graphs showing how people have things set up.

You can get the code from SQLSkillsLogInfo.zip (2.05 kb) (it works on 2000, 2005, 2008) and send me as many results as you like (paul@sqlskills.com) either in plain text or spreadsheet format - or paste them totally anonymously in a comment. The script only takes a few seconds to run, won't affect performance in any way, and won't affect your transaction logs. Now - if your transaction log has many thousands of VLFs, it might take a few minutes to run...

You might think your system is boring - but as far as this is concerned, all results are useful results.

I'll publish the results in a couple of weeks.

Thanks!

(Look in the Misconceptions blog category for the rest of the month's posts and check out the 60-page PDF with all the myths and misconceptions blog posts collected together: CommonSQLServerMyths.pdf (732.96 kb))

Today's myth is very persistent, so it's high time it was debunked with a nice script to prove it too!

Myth #19: a TRUNCATE TABLE operation is non-logged.

FALSE

There is no such thing as a non-logged operation in a user database. The only non-logged operations that SQL Server performs are those on the version store in tempdb.

A TRUNCATE TABLE operation does a wholesale delete of all data in the table. The individual records are not deleted one-by-one, instead the data pages comprising the table are simply deallocated. The allocations are unhooked from the table and put onto a queue to be deallocated by a background task called the deferred-drop task. The deferred-drop task does the deallocations instead of them being done as part of the regular transaction so that no locks need to be acquired while deallocating entire extents. Before SQL Server 2000 SP3 (when this process was put into SQL Server), it was possible to run out of memory while acquiring locks during a TRUNCATE TABLE operation.

Here's an example script:

CREATE DATABASE TruncateTest;
GO
USE TruncateTest;
GO
ALTER DATABASE TruncateTest SET RECOVERY SIMPLE;
GO
CREATE TABLE t1 (c1 INT IDENTITY, c2 CHAR (8000) DEFAULT 'a');
CREATE CLUSTERED INDEX t1c1 on t1 (c1);
GO

SET NOCOUNT ON;
GO

INSERT INTO t1 DEFAULT VALUES;
GO 1280

CHECKPOINT;
GO

The database is in the SIMPLE recovery mode so the log clears out on each checkpoint (for simplicity - ha ha :-)

Wait for a minute or so (there may be some ghost record cleanup that occurs) and check how many rows are in the log:

SELECT COUNT (*) FROM fn_dblog (NULL, NULL);
GO

If you don't get a result of 2, do another checkpoint and check the log record count again until it comes back at 2. Now the database is completely quiescent and any new log records are from stuff we're doing. Now we'll do the truncate:

TRUNCATE TABLE t1;
GO

SELECT COUNT (*) FROM fn_dblog (NULL, NULL);
GO

I get back a result of 541 log records - clearly the operation is not non-logged, but it's clearly also not deleting each record - as I inserted 1280 records. If we look in the log we'll see:

SELECT
 [Current LSN], [Operation], [Context],
 [Transaction ID], [AllocUnitName], [Transaction Name]
FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation           Context             Transaction ID  AllocUnitName               Transaction Name
----------------------  ------------------  ------------------  --------------  --------------------------  ----------------
00000081:000001a6:0016  LOP_BEGIN_CKPT      LCX_NULL            0000:00000000   NULL                        NULL
00000081:000001a9:0001  LOP_END_CKPT        LCX_NULL            0000:00000000   NULL                        NULL
00000081:000001aa:0001  LOP_BEGIN_XACT      LCX_NULL            0000:00001072   NULL                        TRUNCATE TABLE
00000081:000001aa:0002  LOP_LOCK_XACT       LCX_NULL            0000:00001072   NULL                        NULL
00000081:000001aa:0003  LOP_LOCK_XACT       LCX_NULL            0000:00001072   NULL                        NULL
00000081:000001aa:0004  LOP_LOCK_XACT       LCX_NULL            0000:00001072   NULL                        NULL
00000081:000001aa:0005  LOP_COUNT_DELTA     LCX_CLUSTERED       0000:00000000   sys.sysallocunits.clust     NULL
00000081:000001aa:0006  LOP_COUNT_DELTA     LCX_CLUSTERED       0000:00000000   sys.sysrowsets.clust        NULL
00000081:000001aa:0007  LOP_COUNT_DELTA     LCX_CLUSTERED       0000:00000000   sys.sysrowsetcolumns.clust  NULL
00000081:000001aa:0008  LOP_COUNT_DELTA     LCX_CLUSTERED       0000:00000000   sys.sysrowsetcolumns.clust  NULL
00000081:000001aa:0009  LOP_COUNT_DELTA     LCX_CLUSTERED       0000:00000000   sys.sysrowsetcolumns.clust  NULL
00000081:000001aa:000a  LOP_HOBT_DDL        LCX_NULL            0000:00001072   NULL                        NULL
00000081:000001aa:000b  LOP_MODIFY_ROW      LCX_CLUSTERED       0000:00001072   sys.sysallocunits.clust     NULL
00000081:000001aa:000c  LOP_MODIFY_COLUMNS  LCX_CLUSTERED       0000:00001072   sys.sysallocunits.clust     NULL
00000081:000001aa:000d  LOP_DELETE_ROWS     LCX_MARK_AS_GHOST   0000:00001072   sys.sysserefs.clust         NULL
00000081:000001aa:000e  LOP_MODIFY_HEADER   LCX_PFS             0000:00000000   Unknown Alloc Unit          NULL
00000081:000001aa:000f  LOP_SET_BITS        LCX_PFS             0000:00000000   sys.sysserefs.clust         NULL
00000081:000001aa:0010  LOP_INSERT_ROWS     LCX_CLUSTERED       0000:00001072   sys.sysserefs.clust         NULL
00000081:000001aa:0011  LOP_MODIFY_ROW      LCX_SCHEMA_VERSION  0000:00000000   sys.sysobjvalues.clst       NULL
00000081:000001aa:0012  LOP_INSERT_ROWS     LCX_CLUSTERED       0000:00001072   sys.sysallocunits.clust     NULL
00000081:000001aa:0013  LOP_INSERT_ROWS     LCX_CLUSTERED       0000:00001072   sys.sysserefs.clust         NULL
00000081:000001aa:0014  LOP_HOBT_DDL        LCX_NULL            0000:00001072   NULL                        NULL
00000081:000001aa:0015  LOP_MODIFY_ROW      LCX_CLUSTERED       0000:00001072   sys.sysrowsets.clust        NULL
00000081:000001aa:0016  LOP_IDENT_SENTVAL   LCX_NULL            0000:00001072   NULL                        NULL
00000081:000001aa:0017  LOP_MODIFY_ROW      LCX_CLUSTERED       0000:00001072   sys.syscolpars.clst         NULL
00000081:000001aa:0018  LOP_COMMIT_XACT     LCX_NULL            0000:00001072   NULL                        NULL
00000081:000001b0:0001  LOP_BEGIN_XACT      LCX_NULL            0000:00001073   NULL                        DeferredAllocUnitDrop::Process
00000081:000001b0:0002  LOP_LOCK_XACT       LCX_NULL            0000:00001073   NULL                        NULL
00000081:000001b0:0003  LOP_MODIFY_ROW      LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0004  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0005  LOP_SET_BITS        LCX_SGAM            0000:00000000   Unknown Alloc Unit          NULL
00000081:000001b0:0006  LOP_MODIFY_ROW      LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0007  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0008  LOP_MODIFY_ROW      LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0009  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:000a  LOP_MODIFY_ROW      LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:000b  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:000c  LOP_MODIFY_ROW      LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:000d  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:000e  LOP_MODIFY_ROW      LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:000f  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0010  LOP_MODIFY_ROW      LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0011  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0012  LOP_MODIFY_ROW      LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0013  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0014  LOP_SET_BITS        LCX_SGAM            0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0015  LOP_SET_BITS        LCX_GAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0016  LOP_SET_BITS        LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0017  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0018  LOP_SET_BITS        LCX_GAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:0019  LOP_SET_BITS        LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:001a  LOP_MODIFY_ROW      LCX_PFS             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:001b  LOP_SET_BITS        LCX_GAM             0000:00001073   Unknown Alloc Unit          NULL
00000081:000001b0:001c  LOP_SET_BITS        LCX_IAM             0000:00001073   Unknown Alloc Unit          NULL
etc

The transaction with ID 0000:00001072 is the implicit transaction of my TRUNCATE TABLE statement (as you can see from the transaction name). It commits at LSN 00000081:000001aa:0018 and then straight afterwards is the start of the deferred-drop transaction. As you can see from the log records, it's just deallocating the pages and extents.

Well, you can't really see that unless you know what all the log records are doing, so let's have a quick look at the descriptions:

SELECT
 [Current LSN], [Operation], [Lock Information], [Description]
FROM fn_dblog (NULL, NULL);
GO

and you'll be able to see the locks that are logged to allow fast recovery to work (see my blog post Lock logging and fast recovery for an in-depth explanation) and also the description of the operations being performed. Here's a small selection from the start of the deferred-drop transaction:

Operation       Lock Information                                             Description
--------------  -----------------------------------------------------------  --------------------------------------------------------
LOP_BEGIN_XACT  NULL                                                         DeferredAllocUnitDrop::Process
LOP_LOCK_XACT   HoBt 0:ACQUIRE_LOCK_IX ALLOCATION_UNIT: 8:72057594042384384
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X RID: 8:1:153:0
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X PAGE: 8:1:152          Deallocated 0001:00000098
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X RID: 8:1:153:1
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X PAGE: 8:1:156          Deallocated 0001:0000009c
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X RID: 8:1:153:2
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X PAGE: 8:1:157          Deallocated 0001:0000009d
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X RID: 8:1:153:3
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X PAGE: 8:1:158          Deallocated 0001:0000009e
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X RID: 8:1:153:4
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X PAGE: 8:1:159          Deallocated 0001:0000009f
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X RID: 8:1:153:5
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X PAGE: 8:1:160          Deallocated 0001:000000a0
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X RID: 8:1:153:6
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X PAGE: 8:1:161          Deallocated 0001:000000a1
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X RID: 8:1:153:7
LOP_MODIFY_ROW  HoBt 72057594042384384:ACQUIRE_LOCK_X PAGE: 8:1:162          Deallocated 0001:000000a2
LOP_SET_BITS    NULL                                                         ClearBit 0001:000000a0
LOP_SET_BITS    NULL                                                         Deallocated 1 extent(s) starting at page 0001:000000a0
LOP_SET_BITS    NULL
LOP_MODIFY_ROW                                                               Deallocated 0001:000000a8;Deallocated 0001:000000a9;Deallocated 0001:000000aa;Deallocated 0001:000000ab;Deallocated 0001:000000ac;Deallocated 0001:000000ad;Deallocated 0001:000000ae;Deallocated 0001:000000af
LOP_SET_BITS    NULL                                                         Deallocated 1 extent(s) starting at page 0001:000000a8
LOP_SET_BITS    NULL
LOP_MODIFY_ROW                                                               Deallocated 0001:000000b0;Deallocated 0001:000000b1;Deallocated 0001:000000b2;Deallocated 0001:000000b3;Deallocated 0001:000000b4;Deallocated 0001:000000b5;Deallocated 0001:000000b6;Deallocated 0001:000000b7

The first 8 operations are deallocating the 8 pages that are allocated from mixed extents when the table was first populated and after that it switches to deallocating an entire extent at a time. Have a poke around - this stuff's really fascinating. Note also the LOP_LOCK_XACT log record, which just describes the acquisition of a lock - not a change to the database. You'll notice that the extent deallocations don't have any locks protecting them - that's what the allocation unit IX lock is doing.

By the way, if you have nonclustered indexes on the table too, they are also dealt with the same way and there will be a single deferred-drop transaction which deallocates all the pages from both the table and all nonclustered indexes, one allocation unit at a time. Try it and you'll see what I mean.

Myth debunked!

PS There's another myth that a TRUNCATE TABLE can't be rolled back - I debunk that in this old blog post: Search Engine Q&A #10: When are pages from a truncated table reused?

(Look in the Misconceptions blog category for the rest of the month's posts and check out the 60-page PDF with all the myths and misconceptions blog posts collected together: CommonSQLServerMyths.pdf (732.96 kb))

Today is the big day - 8am PST I'm presenting my DBA Mythbusters session at SQL Connections for the first time. I'll hopefully do it as a longer Spotlight Session at PASS this Fall too.

So a little quicky today as I'm doing 4 sessions in a row.

Myth #14: clearing the log zeroes out log records.

FALSE

The transaction log is *always* zero initialized when first created, manually grown, or auto-grown. Do not confuse this with the process of clearing the log during regular operations. That simply means that one or more VLFs (Virtual Log Files) are marked as inactive and able to be overwritten. When log clearing occurs, nothing is cleared or overwritten. 'Clearing the log' is a very confusing misnomer. It means the exact same as 'truncating the log', which is another unfortunate misnomer, because the size of the log doesn't change at all.

You can read more about zero initialization of the log in my blog post Search Engine Q&A #24: Why can't the transaction log use instant initialization? and about how log clearing works in my TechNet Magazine article from February 2009 Understanding Logging and Recovery in SQL Server.

You can prove this to yourself using trace flag 3004. Turning it on will let you see when SQL Server is doing file zeroing operations (as I described in A SQL Server DBA myth a day: (3/30) instant file initialization can be controlled from within SQL Server). Turn it on and watch for messages coming during the day - you shouldn't see anything unless the log grows.

Here's a script to show you what I mean:

DBCC TRACEON (3004, 3605);
GO

-- Create database and put in SIMPLE recovery model so the log will clear on checkpoint
CREATE DATABASE LogClearTest ON PRIMARY (
    NAME = 'LogClearTest_data',
    FILENAME = N'D:\SQLskills\LogClearTest_data.mdf')
LOG ON (
    NAME = 'LogClearTest_log',
    FILENAME = N'D:\SQLskills\LogClearTest_log.ldf',
    SIZE = 20MB);
GO

-- Error log mark 1
ALTER DATABASE LogClearTest SET RECOVERY SIMPLE;
GO

USE LogClearTest;
GO

-- Create table and fill with 10MB - so 10MB in the log
CREATE TABLE t1 (c1 INT IDENTITY, c2 CHAR (8000) DEFAULT 'a');
GO
INSERT INTO t1 DEFAULT VALUES;
GO 1280

-- Clear the log
CHECKPOINT;
GO

-- Error log mark 2
ALTER DATABASE LogClearTest SET RECOVERY SIMPLE;
GO

And in the error log we see:

2010-04-13 13:20:27.55 spid53      DBCC TRACEON 3004, server process ID (SPID) 53. This is an informational message only; no user action is required.
2010-04-13 13:20:27.55 spid53      DBCC TRACEON 3605, server process ID (SPID) 53. This is an informational message only; no user action is required.
2010-04-13 13:20:27.63 spid53      Zeroing D:\SQLskills\LogClearTest_log.ldf from page 0 to 2560 (0x0 to 0x1400000)
2010-04-13 13:20:28.01 spid53      Zeroing completed on D:\SQLskills\LogClearTest_log.ldf
2010-04-13 13:20:28.11 spid53      Starting up database 'LogClearTest'.
2010-04-13 13:20:28.12 spid53      FixupLogTail() zeroing D:\SQLskills\LogClearTest_log.ldf from 0x5000 to 0x6000.
2010-04-13 13:20:28.12 spid53      Zeroing D:\SQLskills\LogClearTest_log.ldf from page 3 to 63 (0x6000 to 0x7e000)
2010-04-13 13:20:28.14 spid53      Zeroing completed on D:\SQLskills\LogClearTest_log.ldf
2010-04-13 13:20:28.16 spid53      Setting database option RECOVERY to SIMPLE for database LogClearTest.
2010-04-13 13:20:29.49 spid53      Setting database option RECOVERY to SIMPLE for database LogClearTest.

The two ALTER DATABASE commands serve as markers in the error log. There's clearly no zeroing occuring from the CHECKPOINT between the two ALTER DATABASE commands. To further prove to yourself, you can add in calls to DBCC SQLPERF (LOGSPACE) before and after the CHECKPOINT, to show that the log is clearing when the CHECKPOINT occurs (watch the value in the Log Space Used (%) column decrease).

Now it's session time here in Vegas! (And there's no-one to blame but yourself if you're the Conference Chair and you've got an 8am session! :-)

(Edited 2/27/10 to add database name to the output) 

Here's a little script I knocked up this afternoon to tell me who has open transactions on the server - not just the single oldest active transaction that DBCC OPENTRAN returns.

It gives back:

• session ID
• login name
• database context
• transaction begin time
• how many log records have been generated by the transaction
• how much log space has been taken up by those log records
• how much log space has been reserved in case the transaction rolls back
• the last T-SQL that was executed in the context of the transaction
• the last query plan that was executed (only for currently executing plans)

It's ordered by the transaction begin time. I had some trouble using CROSS APPLY with the sys.dm_exec_query_plan DMV - if the plan isn't available, it blows out the entire result-set for that transaction. After messing around for ten minutes I discovered the joys of the OUTER APPLY operator - which is the same as CROSS APPLY but allows NULL values from the function being cross-applied.

Also thanks to fellow MVP Aaron Bertrand (twitter|blog) for pointing out a mistake in the way I was calling sys.dm_exec_query_plan.

Here's the script with some example output:

SELECT s_tst.[session_id],
   s_es.[login_name] AS [Login Name],
   DB_NAME (s_tdt.database_id) AS [Database],
   s_tdt.[database_transaction_begin_time] AS [Begin Time],
   s_tdt.[database_transaction_log_record_count] AS [Log Records],
   s_tdt.[database_transaction_log_bytes_used] AS [Log Bytes],
   s_tdt.[database_transaction_log_bytes_reserved] AS [Log Rsvd],
   s_est.[text] AS [Last T-SQL Text],
   s_eqp.[query_plan] AS [Last Plan]
FROM sys.dm_tran_database_transactions s_tdt
   JOIN sys.dm_tran_session_transactions s_tst
      ON s_tst.[transaction_id] = s_tdt.[transaction_id]
   JOIN sys.[dm_exec_sessions] s_es
      ON s_es.[session_id] = s_tst.[session_id]
   JOIN sys.dm_exec_connections s_ec
      ON s_ec.[session_id] = s_tst.[session_id]
   LEFT OUTER JOIN sys.dm_exec_requests s_er
      ON s_er.[session_id] = s_tst.[session_id]
   CROSS APPLY sys.dm_exec_sql_text (s_ec.[most_recent_sql_handle]) AS s_est
   OUTER APPLY sys.dm_exec_query_plan (s_er.[plan_handle]) AS s_eqp
ORDER BY [Begin Time] ASC;
GO

session_id Login Name        Database Begin Time              Log Records Log Bytes Log Rsvd Last T-SQL Text                      Last Plan
---------- ----------------- -------- ----------------------- ----------- --------- -------- ------------------------------------ ---------
54         ROADRUNNERPR\paul foo      2010-02-01 15:28:48.560 2           236       8550     begin tran insert into t1 values (1) NULL
55         ROADRUNNERPR\paul foo      2010-02-01 16:38:18.373 3           356       8852     insert into t1 values (3)            NULL

(For the hardware setup I'm using, see this post. For the baseline performance measurements for this benchmark, see this post.)

In my previous post in the series, I described the benchmark I'm optimizing - populating a 1-TB clustered index as fast as possible using default values. I proved to you that I had an IO bottleneck because the IOs to the data file (from checkpoints) and the transaction log file (from transactions committing) were causing contention.

Several people commented that I might have mis-configured the iSCSI IO subsystem - so first off I want to look at that. Fellow MVP Denny Cherry (twitter|blog), who knows a lot more than me about IO subsystems, volunteered to discuss my iSCSI setup with me to make sure I hadn't goofed anywhere (many thanks Denny!). It seems like I haven't. I'm using a single iSCSI array right now, with a single NIC on the server dedicated to the iSCSI traffic - once I move to multiple volumes, I'll add in more NICs.

Looking at Task Manager in the middle of a 6-hour test run to see the network utilization through the NIC shows that it's not saturated, as shown below.

I ran the DELL smcli utility for two hours during the most recent test to see what peak throughput I'm getting, using the following command:

smcli -n Middle_MD3000 -c "set session performanceMonitorInterval=5 performanceMonitorIterations=1440;save storageArray performanceStats file=\"c:\\MiddlePerfStats.csv\";"

I saw around 101MBytes/sec. and earlier when testing the smcli settings I'd seen 106MBytes/sec. I'm sure once I remove some of the contention that this will get better.

On to the test!

The first thing I wanted to try was optimizing my use of the transaction log - i.e. doing as few and as large IOs as possible to the log. My hypothesis is that by changing the batch size from one to, say, 10 or 100 SQL Server can make more efficient use of the log.

I changed my T-SQL script to take a batch size parameter and use explicit transactions inserting <batch-size> records. Everything else remained the same as the baseline. I picked 128 concurrent threads as my test point. In the baseline, the 128-thread insert test took 8 hours 8 minutes 27 seconds to complete (29307 seconds). My simple T-SQL code changed to (with $(rows) and $(batch) being SQLCMD parameters to the script):

DECLARE @counter BIGINT;
DECLARE @inner   SMALLINT;
DECLARE @start   DATETIME;
DECLARE @end     DATETIME;

SELECT @counter = 0;
SELECT @start = GETDATE ();

WHILE (@counter < $(rows))
BEGIN
   SELECT @inner = 0;
   BEGIN TRAN;
   WHILE (@inner < $(batch))
   BEGIN
      INSERT INTO MyBigTable DEFAULT VALUES;
      SELECT @inner = @inner + 1;
   END
   COMMIT TRAN;
   SELECT @counter = @counter + $(batch);
END;

SELECT @end = GETDATE ();

INSERT INTO msdb.dbo.Results VALUES (CONVERT (INTEGER, DATEDIFF (second, @start, @end)));
GO

Below are the results for 128 threads with batch sizes varying from 10 to 10000:

Increasing the batch size from 1 record to 10 records caused the elapsed time to drop from 29307 seconds to 21167 seconds - a 28% improvement! However, increasing the batch size further didn't improve things any more. Hmmm.

Next I tried different numbers of concurrent connections with a batch size of ten to see if the improvement was universal:

So moving from a single-record batch to a ten record batch has the same dramatic effect on performance for varying numbers of connections.

What's going on?

The answer involves some deep internals of the transaction log structure and IO behavior. The transaction log is split up internally into sections called virtual log files (VLFs for short). These VLFs are used to manage which parts of the log can be overwritten with new log records. If this is all unfamiliar, go read my TechNet Magazine article on Understanding Logging and Recovery in SQL Server which explains about the log in more detail and about transactions, otherwise what's coming next may not make much sense.

Whenever a transaction commits, all the transaction log records up to and including the LOP_COMMIT_XACT log record for that transaction (including log records from other transactions that are inter-mingled with those from the one that just committed) must be written out to disk, so the transaction is durable (called write-ahead logging). But it's not individual log records that are written to disk, the unit of IO for the transaction log is a log block. VLFs are split internally into dynamically sized log blocks, ranging from 512-bytes to 60KB in 512-byte increments, as needed. There are algorithms to figure out how big log blocks should be based on what log records are being flushed out.

With the single record batch, the amount of log generated in the transaction totals 4952 bytes. You can find this by doing something like:

CHECKPOINT;  -- to force the log in the SIMPLE recovery model to clear
GO

INSERT INTO MyBigTable DEFAULT VALUES;
GO

SELECT * FROM fn_dblog (NULL, NULL); -- show me all active log
GO

Then add up the values in the Log Record Length column for all records from the first LOP_BEGIN_XACT log record to the LOP_COMMIT_XACT with the matching Transaction ID.

Anyway, a single-record transaction generates 4952 bytes of transaction log, which will be flushed out in our case in a log block that's 5120 bytes (the nearest multiple of 512 above 4952), with a bunch of zero-padding at the end. For ten single-record transactions, that's 10 small IOs.

The ten-record transaction generates 48688 bytes of transaction log and will be flushed out in a log block that's 49152 bytes (the nearest multiple of 512 above 48688). This is clearly more efficient than 10 smaller IOs and is why changing to batches makes things go faster.

A 100-record transaction generates 489628 bytes of transaction log, which is clearly more than the 60KB log-block maximum, so it actually covers multiple log blocks (varying from 14-16 in my tests - I don't remember the exact algorithms). You can see the log block changing when the middle number in the Current LSN column of the fn_dblog output increases. It looks like it's jumping up, and it is - this is the offset of the log block within the current VLF divided by 512.

Because the 100-record transaction is split into multiple log blocks, there's no real IO gain during log flushes over the 10-record transaction - which is illustrated by the results I saw.

Now, even with this speed increase from the increased batch size, the average-disk-write-queue-length is still anywhere from 20-40 when running the 128-connection test, so there's still a significant bottleneck there. In fact, the transaction log grew significantly still during these tests (up to 23GB in one case) - for an explanation of this phenomenon, see Interesting case of watching log file growth during a perf test. I picked up some wait stats queries from fellow-MVP Glenn Berry (twitter|blog) to run while the tests were running. I'm using his as they're published and anyone can download and use them (see his blog post for the queries, and Bob Ward's CSS blog post that's starting to document the wait types).

His queries tell me that with the 10-record per batch and 128-connections:

• Average write-stall to the data file is 37ms
• Average write-stall to the log file is 18ms
• Top wait types are PAGELATCH_EX (55% of all waits), PAGELATCH_SH (28% of all waits), and WRITELOG (14% of all waits)

The first two waits are the Storage Engine waiting for the buffer pool to kick out dirty pages so that buffers can be used to hold newly created pages, and the third is the log manager waiting for log block flushes to disk to complete.

Clearly IO IO IO.  Let's look at a a perfmon capture during the 10-records per batch test with 128 connections:

Let's go through each counter (top to bottom in the list in the image) and explain what's going on. I deliberately picked this time-slice, as it really simply shows the effect of contention:

• Pages Allocated/sec: this is the light blue line and is the Access Methods part of the Storage Engine (the dev team I used to run) creating new data and index pages for the clustered index we're populating.
• Checkpoint pages/sec: this is the pink line at the bottom left and bottom right of the capture. This is the buffer pool writing out dirty pages during a periodic checkpoint.
• Avg. Disk sec/Write: this is the dark blue line that's tracking just above the thick black line. It's the amount of time in ms for a write to complete. You can see that it has a minimum around 12:51:00 and then varies wildly, hitting as high as 50+ms for a single write.
• Avg. Disk Write Queue Length: this is the highlighted line in thick black. It also has a minimum around 12:51:00 and varies wildly the rest of the time.
• Disk Write Bytes/sec: this is the dark green line at the top that shows the number of bytes being written to disk from all IO sources. Same story around 12:51:00.
• Log Growths: A simple counter since the database was created/server started. It's over 100 and off the chart.
• Log Bytes Flushed/sec: this is the red, fairly constant line around 1/3 the way up and is log blocks being flushed to disk because of transaction commits or checkpoints.
• Lazy writes/sec: this is the light green line at the bottom and is the buffer pool having to force data pages to be written to disk (along with all transaction log flushed up to the point of the last log record to change the page being written) to make space for images of newly created pages.

This time-slice is really cool in that it shows what happens when contention goes away. Just before 12:51:00, a checkpoint ends and the lazywriter has nothing to do - so the only IOs hitting the disks are those coming from the transaction log flushing out log blocks as transactions commit. You can see the Avg. Disk Write Queue Length drop down to 2-3, the Avg. Disk sec/Write drop to about 5ms, and most beautiful of all (look, I'm a big geek ok? :-), the Disk Write Bytes/sec (the green line) drops down to be exactly equal to the Log Bytes Flushed/sec - proving that it's just log flushes hitting the disk. This is the no-contention case. It happens again for brief spell about 10 seconds later - the lazywriter most likely created a temporary surfeit of empty buffers. All the rest of the time, the lazywriter and checkpoints play havoc with the write throughput on the drives by causing contention.

It's clearly time to try some separation of files to relieve the contention - and that's what I'll cover in the next post in the series.

Hope you're enjoying the series - these take a long time to write up!

I'm running some performance tests on the hardware we have (more details on the first of these tomorrow) and I was surprised to see some explosive transaction log growth while running in the SIMPLE recovery model with single row insert transactions!

Without spoiling tomorrow's thunder too much, I've got a setup with varying numbers of connections populating a 1TB table with default values, with the single data and log files on the same 8-drive RAID-10 array (again more details on why tomorrow). I was looking at perfmon while the test was running with 128 concurrent connections, and noticed some weird-looking behavior - basically what looked like a never-ending checkpoint occuring. So I dug in deeper and discovered the transaction log had grown over 7GB since the start of the test. Huh?

I restarted the test from scratch, with a 1TB data file and a 256MB log and watched what happened in perfmon; here's the screenshot of the first 90 seconds:

This is *so* interesting. The black line is the number of log growths, so you can see the log grows every time the line level goes up. The bright blue line is the number of pages being allocated per second to hold all the table rows my 128 connections are inserting. You can clearly see that every time there's a log growth, the allocations take a nose-dive - because no transactions can commit while the new portion of the log is being zeroed (remember that instant file initialization does not apply to the log - see this blog post). The green line (disk write bytes per second) spikes when the log grows because of the zeroes being written out to the log file by SQL Server (remember that SQL Server does the zeroing).

But why is the log growing in the first place? I'm in the SIMPLE recovery model and doing single-row implicit transactions (yes, I'm deliberately doing this) so there shouldn't be anything stopping the log from clearing during a checkpoint, right?

Wrong. The log starts out small (256MB) so one of the thresholds for triggering a checkpoint gets hit pretty fast (70% of the log file is used). So a checkpoint occurs (you can see the checkpoints occuring when the pink line at the bottom of the perfmon screen is above zero), and starts writing out to the data file, which is on the same disk as the log (see How do checkpoints work and what gets logged for an explanation of checkpoint mechanics), but it can't write fast enough (because of disk contention) to get to the log-clearing part before the log fills up completely and has to grow (because transactions are continuing at break-neck speed). So the log grows, and the insert transactions stop while the log is zeroed. And then the log starts to fill up again very quickly and another checkpoint is triggered, and so on and so on.

Eventually a steady state is reached where there's enough free log space during a checkpoint that no new log is required for the concurrent transactions to commit. You might ask why the checkpoint is so slow in the first place? Because I deliberately put the data file on the same RAID array as the log file, and both are being steadily hammered with writes - classic disk contention. Even though the RAID array is RAID-10 with 8x300GB 15k SCSI drives, the average disk queue write length is over 20 most of the time during the 128-way test because I'm simply trying to do too much.

The point of my blog post? Just because you don't have any of the classic causes of transaction log growth going on, doesn't mean you're going to be immune. In this case my (deliberate) poor physical layout of the database files and workload growth up to 128 concurrent connections caused the log to grow. What started out working when I was running 16 connections didn't work any more at 128 (actually I went back and re-ran some of the earlier tests and even with only 64 connections, the log grew to over 1GB before reaching steady-state).

Interesting eh?

Tomorrow I'll be continuing the perf/benchmarking series by creating my first benchmark and then tweaking the setup to see how I can improve performance (for instance with multiple data files, separation of log and data files - all the things I preach but have never *demonstrated*), but this behavior merited a post all on its own.

Earlier today there was a question on SQL Server Central where someone wanted to know what could be causing so many reads on their transaction log. I was asked to chime in by fellow MVP Jonathan Kehayias (who also sent me some questions that I've answered in this post - thanks Jon!), so I did, with a list of everything I could think of. I thought it would make for a good post, so here it is, with a few more things I remembered while writing the post.

Before I start, if you're not comfortable talking log records and transaction log architecture, see my TechNet Magazine article on Understanding Logging and Recovery, which explains everything clearly, including how having too many VLFs can affect operations on the log that have to scan VLFs.

Each of these things can cause reads of the log:

• Transaction rollback: when a transaction has to roll back (either because you say ROLLBACK TRAN or something goes wrong and SQL Server aborts the transaction), the log records describing what happened in the transaction have to be read so that their effects can be removed from the database. This is explained in the TechNet Magazine article. Note that it doesn't matter if you're using explicit transactions or not (i.e. BEGIN TRAN), SQL Server always starts a transaction for you (called an implicit transaction) so that it can put a boundary on what needs to be rolled back in case of a failure.
• Crash recovery: crash recovery must read the transaction log to figure out what to do with all the log records in the active portion of the log (all the way back to the earlier of the most recent checkpoint or the start of the oldest active transaction). The log is read twice - once going forward from that oldest point (called the REDO phase) and then going backwards (called the UNDO phase). Again, this is explained in great depth in the article.
• Creating a database snapshot: a database snapshot is a point-in-time view of a database. What's more, it's a transactionally consistent point-in-time view of a database - which means that, essentially, crash recovery must be run on the real database to create the transactionally consistent view. The crash recovery is run into the database snapshot, the real database isn't affected - apart from having all the active transaction log read so that crash recovery can run.
• Running DBCC CHECKDB: creates a database snapshot by default on 2005 onwards, and runs the consistency checks on the snapshot. See above. There's a much more detailed description, including how this worked in 2000, in the first part of the 10-page blog post CHECKDB From Every Angle: Complete description of all CHECKDB stages.
• Transaction log backups: this one's kind of obvious. A transaction log backup contains all the transaction log records generated since the last log backup finished (or since the log backup chain was established). To back up the log it has to read it. What's not so obvious is that a log backup will also scan through all the VLFs in the log to see if any active ones can be made inactive (called clearing or truncating the log - both misnomers as nothing is cleared and nothing is truncated). See my TechNet Magazine article on Understanding SQL Server Backups and in the blog post Importance of proper transaction log size management.
• Any kind of data backup: (full/differential backup of a file/filegroup/database). Yup - data backups always include transaction log - so the backup can be restored and give you a transactionally consistent view of the database. See Debunking a couple of myths around full database backups and More on how much transaction log a full backup includes for details if you don't believe me.
• Transactional replication: transactional replication works by harvesting committed transactions from the transaction log of the publication database (and then sending them to the subscriber(s) via the distribution database - beyond the scope of this post). This is done by the Log Reader Agent job, running from the Distributor. It needs to read all the log records generated in the publication database, even if they're nothing to do with the publications. More log equals more reads. My whitepaper on combining database mirroring and transactional replication in 2008 has more details on this stuff, as does Books Online.
• Change data capture (in 2008): CDC uses the transactional replication log reader agent to harvest changes from the transaction log. See above. This means the CDC can cause the log to not be able to clear properly, just like transactional replication or database mirroring - see my blog post Search Engine Q&A #1: Running out of transaction log space for more details. Note the I didn't say Change Tracking - it uses a totally different mechanism - see my TechNet Magazine article on Tracking Changes in Your Enterprise Database for more details.
• Database mirroring: DBM works by sending physical log records from the principal to the mirror database. If the mirroring sessions drops out of the SYNCHRONIZED state, then the log records won't be able to be read from memory and the mirroring subsystem will have to get them from disk - causing log reads. This can happen if you're running asynchronous mirroring (where you're specifically allowing for this), or if something went wrong while running synchronous mirroring (e.g. the network link between the principal and mirror dropped out, and a witness wasn't configured or the principal could still see the witness - again, beyond the scope of this post). Regardless, this is called having a SEND queue on the principal.
• Restoring a backup: whenever backups are restored, even is you've said WITH NORECOVERY, the REDO portion of recovery is run for each restore, which reads the log.
• Restoring a log backup using WITH STANDBY: in this case, you've essentially said you'd like recovery to run, but not to affect the transaction log itself. Running recovery has to read the log. For more info on using WITH RECOVERY, NORECOVERY, or STANDBY, see my latest TechNet Magazine article on Recovering from Disasters Using Backups, which explains how restores work.
• A checkpoint, in the SIMPLE recovery mode only: see my blog post How do checkpoints work and what gets logged for a description of what checkpoints are and what they do. In the SIMPLE recovery mode, checkpoints are responsible for clearing the log (described with links above) so must read through all the VLFs to see which can be marked inactive.
• When processing a DML trigger (on 2000): (thanks to Clay Lenhart for the comment that reminded me of this). In SQL Server 2000, the before and after tables that you can process in a DML trigger body are actually found from looking at the log records generated by the operation that caused the trigger to fire. My dev team changed this in 2005 to store the before and after tables using the version store, giving a big perf boost to DML trigger processing. 
• Manually looking in the log (with DBCC LOG or the table-valued function fn_dblog): this one's pretty obvious.

Phew - a lot of things can cause log reads, the trick is knowing which one it is!

As you can see, there could be a lot of activity reading from your log as well as writing to it, which could cause an IO bottleneck. Make sure that the IO subsystem on which you place the log file (note: you don't get ANY performance benefit from having multiple log files) can handle the read and write workload the log demands. RAID 1 or RAID 10 with a bunch of spindles to spread the IOs out (note/warning/achtung: that's a big generalization - don't reply with a comment saying it's wrong because you've seen something different - different scenarios have different demands), and a proper RAID configuration (64k multiple for a stripe size, NTFS allocation unit size, volume partition alignment).

One of the things I love teaching is how the transaction log and logging/recovery work. I presented a session on this at both PASS and SQL Connections in the last two weeks, and in both sessions I promised to write some blog posts about the deep internals of logging operations. This is the first one in the series. Previous blog posts that dive into logging operations are:

• How do checkpoints work and what gets logged (this also explains how crash recovery starts, using the boot page and the most recent checkpoint log record)
• Finding out who dropped a table using the transaction log
• How expensive are page splits in terms of transaction log?
• Inside the Storage Engine: More on the circular nature of the log
• Ghost cleanup redux
• Inside the Storage Engine: Ghost cleanup in depth

Ok, on with the show. 

SQL Server 2005 introduced a feature called 'fast recovery' in Enterprise Edition. This allows a database to become available for use after the first part of recovery (REDO) completes and before the (usually longer running) second part of recovery (UNDO) completes. See my TechNet Magazine article Understanding Logging and Recovery in SQL Server if you don't know what I'm talking about. But how does SQL Server do this?

The answer is lock logging. A log record describes a single change made to a database. For log records describing changes that can be used as part of UNDO (yes, some changes to the database are one-way only - for instance PFS page changes), from 2005 onwards the log record also includes a description of which locks were being held at the time the change was made. These locks were necessary to protect the change being made when the original transaction was running (before the crash) and so the same locks will be necessary to protect the anti-operation which reverses the change. I'll explain more about these anti-operations in one of the next in-depth logging blog posts.

The Storage Engine does two passes through the log as part of crash recovery. The first pass does REDO and also reads the log records that will be processed as part of the second pass (UNDO), looking at the lock description and actually acquiring those locks. For fast recovery, at that point the database is brought online. This is possible because the recovery system knows that it already has the correct locks to guarantee that it can safely generate and perform the anti-operations necessary to perfom UNDO. One side-effect of this is that although the database is available for use, a query may bump into one of the locks being held to allow fast recovery - in which case it will have to wait for that lock to be dropped as UNDO progresses.

Cool eh?

That was the introduction to allow me to do some gratuitous spelunking around the internals :-) I'm going to create a few simple examples to show you lock logging in the log. Now, don't get confused - it's not logging actual locks (the memory used to hold the lock itself), it's just logging a description of which locks were held and in which modes.

Here's the script to create a database with a simple table. I'm using a LOB column and specifically setting it to be stored off row (see Importance of choosing the right LOB storage technique) so we can see some text page locks too. I'm using the SIMPLE recovery model for simplicity (ha ha) - so I can clear the log when a checkpoint occurs rather than having to muck around with log backups. I'll insert the first row and then clear the log.

CREATE DATABASE LockLogging;
GO
USE LockLogging;
GO

CREATE TABLE LockLogTest (c1 INT, c2 INT, c3 VARCHAR (MAX));
GO
EXEC sp_tableoption 'LockLogtest', 'large value types out of row', 'on';
GO

INSERT INTO LockLogTest VALUES (1, 1, 'a');
GO

ALTER DATABASE LockLogging SET RECOVERY SIMPLE;
GO
CHECKPOINT;
GO

Now let's try the first operation - a simple insert - and look at the log records using fn_dblog (and I'm skipping the checkpoint log records):

INSERT INTO LockLogTest VALUES (2, 2, 'b');
GO
SELECT [Operation], [Context], [Page ID], [Slot ID], [Number of Locks] AS Locks, [Lock Information]
FROM fn_dblog (NULL, NULL);
GO

Operation        Context       Page ID        Slot ID  Locks Lock Information
---------------- ------------- -------------- -------- ----- -------------------------------------------------------------------
LOP_BEGIN_XACT   LCX_NULL      NULL           NULL     NULL  NULL
LOP_INSERT_ROWS  LCX_TEXT_MIX  0001:00000098  1        2     ACQUIRE_LOCK_IX PAGE: 18:1:152; ACQUIRE_LOCK_X RID: 18:1:152:1
LOP_INSERT_ROWS  LCX_HEAP      0001:0000009a  1        3     ACQUIRE_LOCK_IX OBJECT: 18:2073058421:0;
                                                                 ACQUIRE_LOCK_IX PAGE: 18:1:154; ACQUIRE_LOCK_X RID: 18:1:154:1
LOP_COMMIT_XACT  LCX_NULL      NULL           NULL     NULL  NULL

We can see page IX and row X locks for the LOB value being inserted into the text page, plus table IX, page IX, and row X locks for the data record being inserted into the heap. The lock resources break out as follows:

• 18:1:152 is page 152 in file 1 of database ID 18
• 18:1:152:1 is slot 1 on page 152 in file 1 of database ID 18
• 18:2073058421:0 is object ID 2073058421 (the object ID of the table LockLogTest) in database ID 18

Notice also the LOP_BEGIN_XACT and LOP_COMMIT_XACT log records - even though I didn't do an explicit transaction, SQL Server has to start one internally for me (called an implicit transaction) so that there's a boundary for where to rollback if something goes wrong during the operation. 

And now an update operation (with a checkpoint first to clear out the log):

CHECKPOINT;
GO
UPDATE LockLogTest SET c1 = 3;
GO
SELECT [Operation], [Context], [Page ID], [Slot ID], [Number of Locks] AS Locks, [Lock Information]
FROM fn_dblog (NULL, NULL);
GO

Operation        Context       Page ID        Slot ID  Locks Lock Information
---------------- ------------- -------------- -------- ----- -------------------------------------------------------------------
LOP_BEGIN_XACT   LCX_NULL      NULL           NULL     NULL  NULL
LOP_MODIFY_ROW   LCX_HEAP      0001:0000009a  0        3     ACQUIRE_LOCK_IX OBJECT: 18:2073058421:0;
                                                                 ACQUIRE_LOCK_IX PAGE: 18:1:154; ACQUIRE_LOCK_X RID: 18:1:154:0
LOP_MODIFY_ROW   LCX_HEAP      0001:0000009a  1        3     ACQUIRE_LOCK_IX OBJECT: 18:2073058421:0;
                                                                 ACQUIRE_LOCK_IX PAGE: 18:1:154; ACQUIRE_LOCK_X RID: 18:1:154:1
LOP_COMMIT_XACT  LCX_NULL      NULL           NULL     NULL  NULL

Just as we expected - a table IX lock, a page IX lock, and two row X locks on that page.

Now, what about something more complicated like a TRUNCATE TABLE? Have you heard the myth about it not being logged? Right - it's a myth:

CHECKPOINT;
GO
TRUNCATE TABLE LockLogTest;
GO
SELECT [Operation], [Context], [Page ID], [Slot ID], [Number of Locks] AS Locks, [Lock Information]
FROM fn_dblog (NULL, NULL);
GO

Operation        Context       Page ID        Slot ID  Locks Lock Information
---------------- ------------- -------------- -------- ----- -------------------------------------------------------------------
LOP_BEGIN_XACT   LCX_NULL      NULL           NULL     NULL  NULL
LOP_LOCK_XACT    LCX_NULL      NULL           NULL     1     ACQUIRE_LOCK_SCH_M OBJECT: 18:2073058421:0
LOP_MODIFY_ROW   LCX_IAM       0001:0000009b  0        1     ACQUIRE_LOCK_X RID: 18:1:155:0
LOP_MODIFY_ROW   LCX_PFS       0001:00000001  0        1     ACQUIRE_LOCK_X PAGE: 18:1:154
LOP_MODIFY_ROW   LCX_PFS       0001:00000001  0        1     ACQUIRE_LOCK_X PAGE: 18:1:155
LOP_MODIFY_ROW   LCX_IAM       0001:00000099  0        1     ACQUIRE_LOCK_X RID: 18:1:153:0
LOP_MODIFY_ROW   LCX_PFS       0001:00000001  0        1     ACQUIRE_LOCK_X PAGE: 18:1:152
LOP_MODIFY_ROW   LCX_PFS       0001:00000001  0        1     ACQUIRE_LOCK_X PAGE: 18:1:153
LOP_SET_BITS     LCX_SGAM      0001:00000003  1        NULL  NULL
LOP_SET_BITS     LCX_GAM       0001:00000002  1        NULL  NULL
LOP_COUNT_DELTA  LCX_CLUSTERED 0001:00000014  89       NULL  NULL
LOP_COUNT_DELTA  LCX_CLUSTERED 0001:00000011  78       NULL  NULL
LOP_COUNT_DELTA  LCX_CLUSTERED 0001:00000014  90       NULL  NULL
LOP_COUNT_DELTA  LCX_CLUSTERED 0001:00000041  164      NULL  NULL
LOP_COUNT_DELTA  LCX_CLUSTERED 0001:00000041  165      NULL  NULL
LOP_COUNT_DELTA  LCX_CLUSTERED 0001:00000041  166      NULL  NULL
LOP_HOBT_DDL     LCX_NULL      NULL           NULL     NULL  NULL
LOP_MODIFY_ROW   LCX_CLUSTERED 0001:00000014  89       2     ACQUIRE_LOCK_IX OBJECT: 18:7:0;
                                                                 ACQUIRE_LOCK_X KEY: 18:458752 (0000c2681664)
LOP_HOBT_DDL     LCX_NULL      NULL           NULL     NULL  NULL
LOP_MODIFY_ROW   LCX_CLUSTERED 0001:00000014  90       2     ACQUIRE_LOCK_IX OBJECT: 18:7:0;
                                                                 ACQUIRE_LOCK_X KEY: 18:458752 (00007a581379)
LOP_MODIFY_ROW   LCX_CLUSTERED 0001:00000011  78       2     ACQUIRE_LOCK_IX OBJECT: 18:5:0;
                                                                 ACQUIRE_LOCK_X KEY: 18:327680 (00001df3833b)
LOP_COMMIT_XACT  LCX_NULL      NULL           NULL     NULL  NULL

Lots of logging and lots of locks. If you look at the Context column, you'll see that the operation is modifying allocation bitmaps (LCX_IAM, LCX_PFS, LCX_SGAM, LCX_GAM) but taking locks on the table pages, not on the allocation bitmaps themselves - they're only ever latched (an internal, much lighter-weight, synchronization mechanism). This is done as the pages comprising the table are deallocated - this is all done because the table's small enough that the Storage Engine chooses to deallocate all the storage immediately, instead of pushing it all onto the task queue for the deferred drop background task. See my previous post Search Engine Q&A #10: When are pages from a truncated table reused? which discusses this too.

There are no actual row operations performed on the table itself. The only table row operations are down at the bottom on table with object IDs 7 and 5 (sysallocunits and sysrowsets, respectively) to update the page counts, first IAM, and first page entries for the table.

So - hopefully this has been useful to you. In the next post in the series, I'll discuss compensation log records and how rollback operations work.

PS Send me an email or put in a comment if there's something in particular about the log (or log records) you'd like to see explained.

Last week I posted in-depth about how checkpoints work and what exactly goes on (see How do checkpoints work and what gets logged). About a year ago I posted about why the buffer pool on a busy system may seem to have an inordinate amount of dirty tempdb pages in it, and now I want to clarify a bit more why this is the case and how checkpoints work for tempdb. To see the buffer pool contents, see my post Inside the Storage Engine: What's in the buffer pool?.

A checkpoint is only done for tempdb when the tempdb log file reaches 70% full - this is to prevent the tempdb log from growing if at all possible (note that a long-running transaction can still essentially hold the log hostage and prevent it from clearing, just like in a user database).

If you read the first post I reference above, you'll see that when a checkpoint occurs for a user database, all dirty pages for that database are flushed to disk (as well as other operations). This does not happen for tempdb. Tempdb is not recovered in the event of a crash, and so there is no need to force dirty tempdb pages to disk, except in the case where the lazywriter process (part of the buffer pool) has to make space for pages from other databases.

The other operation that occurs during a checkpoint of databases in the SIMPLE recovery model is that the VLFs in the log are examined to see if they can be made inactive (see TechNet Magazine: feature article on understanding logging and recovery and Inside the Storage Engine: More on the circular nature of the log). This process allows the log to wrap-around and overwrite itself without having to grow - and this process *IS* required by tempdb, for proper management of it's log size.

This is all that happens for a checkpoint of tempdb - no data pages are flushed to disk.

This is a blog post I've been meaning to do for a while, and I've recently noticed some info on the web about checkpoints which is a little misleading, so I want to do a quick post to explain how checkpoints work as far as log records are concerned.

When a checkpoint operation occurs, no matter how it's triggered (for instance through a manual CHECKPOINT, from a database or differential backup, or automatically) the same set of operations occurs:

• All dirty data file pages for the database are written to disk (all pages that have changed in memory since they were read from disk or since the last checkpoint), regardless of the state of the transaction that made the change.
• Before a page is written to disk, all log records up to and including the most recent log record describing a change to that page are written to disk (yes, log records can be cached in memory too). This guarantees recovery can work and is called write-ahead logging. Log records are written to the log sequentially, and log records from multiple transactions will be interspersed in the log. The log cannot be selectively written to disk, so writing a dirty page to disk that only has a single log record affecting it may mean writing many more previous log records to disk as well.
• Log records describing the checkpoint are generated.
• The LSN of the checkpoint is recorded in the database boot page in the dbi_checkptLSN field (see Search Engine Q&A #20: Boot pages, and boot page corruption).
• If in the SIMPLE recovery model, the VLFs in the log are checked to see whether they can be marked inactive (called clearing or truncating the log - both of which are terrible misnomers, as nothing is either physically cleared or truncated).

I'm using some terms you may not have come across - for a background primer on logging, recovery, and transaction log architecture see my article in the February 2009 TechNet Magazine - Understanding Logging and Recovery in SQL Server (or come to my Wednesday November 4th PASS Spotlight session with the same title).

Checkpoints are not really tracked in the transaction log - it just serves as a useful repository for information about which transactions are active at the time of the checkpoint. The LSN of the last checkpoint is recorded in the database boot page. This is where recovery starts, and if this page is inaccessible, the database cannot be attached, opened, or processed in any way - partly because it's the boot page that knows whether the database was cleanly shut down or not, and partly because it's the only place that records the LSN of the last checkpoint record. You may say, well it's recorded in the transaction log too, but what if the log is corrupt in some way?

One area of confusion I've seen is that the checkpoint log records are overwritten by subsequent checkpoints. Absolutely not - once written, a log record is NEVER updated or overwritten - it will only be overwritten when the log wraps and the VLFs are re-used (see Inside the Storage Engine: More on the circular nature of the log). This has led to further confusion about when checkpoint information is retrievable from the log, using commands such as fn_dblog.

For the rest of this post, I want to show you what's going on in the transaction log when checkpoints occur under different circumstances.

Consider the following example:

CREATE DATABASE CheckpointTest;
GO
USE CheckpointTest;
GO
CREATE TABLE t1 (c1 INT);
GO
INSERT INTO t1 VALUES (1);
GO
CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- -------------------------------
00000047:00000051:009b  LOP_BEGIN_CKPT
00000047:00000091:0001  LOP_END_CKPT

We see the log records for the checkpoint. In this case the checkpoint is very simple and so there are only two records - beginning and ending the checkpoint.

If we run another checkpoint, what do we see?

CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- -------------------------------
00000047:00000092:0001  LOP_BEGIN_CKPT
00000047:00000093:0001  LOP_END_CKPT

Only information about one checkpoint, but with different LSNs for the log records. It's not that the previous checkpoint was overwritten, it's that we did a checkpoint - so the active portion of the log has moved forward and the log records for the previous checkpoint aren't considered active any more as they're not required (for instance, for database mirroring, an active transaction, a log backup, transactional replication). They're still there in the log though, but just aren't part of the required portion of the log and so aren't dumped by fn_dblog.

Now, what if I create an active transaction? In another connection, I'll do:

USE CheckpointTest;
GO
BEGIN TRAN;
GO
INSERT INTO t1 VALUES (1);
GO

And what if we do a checkpoint and look at the log now?

CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- -------------------------------
00000047:00000094:0001  LOP_BEGIN_XACT
00000047:00000094:0002  LOP_INSERT_ROWS
00000047:00000094:0003  LOP_COUNT_DELTA
00000047:00000094:0004  LOP_COUNT_DELTA
00000047:00000094:0005  LOP_COUNT_DELTA
00000047:00000094:0006  LOP_BEGIN_CKPT
00000047:00000096:0001  LOP_XACT_CKPT
00000047:00000096:0002  LOP_END_CKPT

We see the start of the open transaction, the insert of the record, the update of row counts in metadata, and the checkpoint.

You may notice that there's another log record being generated for the checkpoint - LOP_XACT_CKPT. This is only generated when there are active (uncommitted) transactions and it lists information about all actvie transactions at the time the checkpoint begins. This is used during crash recovery to work out how far back in the transaction log to go to start REDO and UNDO operations (well, technically only UNDO will need to go this far back). Focusing in on this log record, we can see:

SELECT [Current LSN], [Operation], [Num Transactions], [Log Record]
FROM fn_dblog (NULL, NULL) WHERE [Operation] = 'LOP_XACT_CKPT';
GO

Current LSN             Operation                       Num Transactions
----------------------- ------------------------------- ----------------
00000047:00000096:0001  LOP_XACT_CKPT                   1

Log Record
-----------------------------------------------------------------------------------------------------------
0x000018 <snip> 780500000000000047000000940000000100040147000000940000000200000001 <snip> 6621000000000000

This log record contains information about each active (uncommitted) transaction at the time of the checkpoint. Without going into all the details about what's in the payload for this log record, you can see two things in there:

• The LSN of the LOP_BEGIN_XACT log record for the oldest active transaction (the first bold number above - match it against the LOP_BEGIN_XACT in the log dump a little higher up)
• The LSN of the first log record making a database change for that transaction (the second bold number above - match it against the LOP_INSERT_ROWS in the log dump a little higher up)

You'll notice that these LSNs are stored byte-reversed. 

How about if we do another checkpoint?

CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- -------------------------------
00000047:00000094:0001  LOP_BEGIN_XACT
00000047:00000094:0002  LOP_INSERT_ROWS
00000047:00000094:0003  LOP_COUNT_DELTA
00000047:00000094:0004  LOP_COUNT_DELTA
00000047:00000094:0005  LOP_COUNT_DELTA
00000047:00000094:0006  LOP_BEGIN_CKPT
00000047:00000096:0001  LOP_XACT_CKPT
00000047:00000096:0002  LOP_END_CKPT
00000047:00000097:0001  LOP_BEGIN_CKPT
00000047:00000098:0001  LOP_XACT_CKPT
00000047:00000098:0002  LOP_END_CKPT

This time we see the log records for the current checkpoint and the previous one - as the active log stretches all the way back to the start of the oldest active transaction - no matter how many checkpoints we do while there's an active transaction.

Now what if we start another active transaction in a third connection?

USE CheckpointTest;
GO
BEGIN TRAN;
GO
INSERT INTO t1 VALUES (2);
GO

And then go back to the original connection and do another checkpoint and dump the log again:

CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- -------------------------------
00000047:00000094:0001  LOP_BEGIN_XACT
00000047:00000094:0002  LOP_INSERT_ROWS
00000047:00000094:0003  LOP_COUNT_DELTA
00000047:00000094:0004  LOP_COUNT_DELTA
00000047:00000094:0005  LOP_COUNT_DELTA
00000047:00000094:0006  LOP_BEGIN_CKPT
00000047:00000096:0001  LOP_XACT_CKPT
00000047:00000096:0002  LOP_END_CKPT
00000047:00000097:0001  LOP_BEGIN_CKPT
00000047:00000098:0001  LOP_XACT_CKPT
00000047:00000098:0002  LOP_END_CKPT
00000047:00000099:0001  LOP_BEGIN_XACT
00000047:00000099:0002  LOP_INSERT_ROWS
00000047:00000099:0003  LOP_COUNT_DELTA
00000047:00000099:0004  LOP_COUNT_DELTA
00000047:00000099:0005  LOP_COUNT_DELTA
00000047:00000099:0006  LOP_BEGIN_CKPT
00000047:0000009b:0001  LOP_XACT_CKPT
00000047:0000009b:0002  LOP_END_CKPT

You can see that we now have three sets of checkpoint log records, and two active transactions. Only one of these sets of checkpoint log records is the pertinent one - the previous two have been superceded, but the log records haven't been overwritten or removed, as you can clearly see.

Looking inside all the LOP_XACT_CKPT records, we can see (with a bit of creative formatting of the output):

SELECT [Current LSN], [Operation], [Num Transactions], [Log Record]
FROM fn_dblog (NULL, NULL) WHERE [Operation] = 'LOP_XACT_CKPT';
GO

Current LSN             Operation                       Num Transactions
----------------------- ------------------------------- ----------------
00000047:00000096:0001  LOP_XACT_CKPT                   1
00000047:00000098:0001  LOP_XACT_CKPT                   1
00000047:0000009b:0001  LOP_XACT_CKPT                   2

Log Record
-------------------------------------------------------------------------------------------------------------
0x000018 <snip> 780500000000000047000000940000000100040147000000940000000200000001 <snip> 21000000000000
0x000018 <snip> 780500000000000047000000940000000100040147000000940000000200000001 <snip> 21000000000000
0x000018 <snip> 780500000000000047000000940000000100040147000000940000000200000001 <snip> 21000000000000 ...
    ... 79050000000000004700000099000000010004014700000099000000020000000100000002000000DC000000

The first two checkpoints only list one active transaction and the most recent one lists two, as we'd expect. The log record payload for the first two lists the same oldest active transaction (highlighted in bold). The payload for the last checkpoint lists the same oldset active transaction (as that hasn't changed), but now lists an additional transaction (match the 470000009900000001000 with the LSN of the second LOP_BEGIN_XACT in the log dump above), and has a transaction count of two.

Just to finish things off, let's look at the boot page of the database either using DBCC PAGE or DBCC DBINFO:

DBCC TRACEON (3604);
GO
DBCC DBINFO ('CheckpointTest');
GO

DBINFO STRUCTURE:

DBINFO @0x6711EF64

dbi_dbid = 18                        dbi_status = 65536                   dbi_nextid = 2089058478
dbi_dbname = CheckpointTest          dbi_maxDbTimestamp = 2000            dbi_version = 611
dbi_createVersion = 611              dbi_ESVersion = 0                   
dbi_nextseqnum = 1900-01-01 00:00:00.000                                  dbi_crdate = 2009-09-28 07:06:35.873
dbi_filegeneration = 0              
dbi_checkptLSN

m_fSeqNo = 71                        m_blockOffset = 153                  m_slotId = 6
dbi_RebuildLogs = 0                  dbi_dbccFlags = 2                   
dbi_dbccLastKnownGood = 1900-01-01 00:00:00.000                          
<snip>

The dbi_checkptLSN is dumped out in decimal - converting to hex gives us  (47:99:6), which exactly matches the LSN of the most recent LOP_BEGIN_CKPT record in the log dump above.

Hopefully this explains things clearly!

The August edition of TechNet Magazine is available on the web now and has the latest installment of my regular SQL Q&A column.

This month's topics are:

• Proactive page checksum failure detection
• Why GUIDs make for bad clustered index keys 
• Possible problems using a log shipping secondary for reporting 
• Recovery model choice for log size management

Check it out at http://technet.microsoft.com/en-us/magazine/dd776512.aspx.

I came across a question on ServerFault this afternoon that inflamed my desire to be ultra-geeky (it was really already inflamed after teaching backup and restore internals all afternoon). Basically the question boiled down to how to find out who dropped a table if there's no other way except the transaction log (e.g. no tracing is available, even the default trace). So I hacked around and figured out at least how to find out *when* a particular table was dropped plus the UID and SPID of who dropped it.

Everything hinges on using undocumented commands to look into the transaction log. I've played with this before on the blog: fn_dblog.

First off I created a script to create a database, populate a table and then drop it.

USE master;
GO
CREATE DATABASE FnDbLogTest;
GO
USE FnDbLogTest;
GO

CREATE TABLE TestTable (
    c1 INT IDENTITY,
    c2 CHAR (100) DEFAULT 'a');
GO
CREATE CLUSTERED INDEX TT_CL ON TestTable (c1);
GO
INSERT INTO TestTable DEFAULT VALUES;
GO

SELECT OBJECT_ID ('TestTable');
GO

DROP TABLE TestTable;
GO

First we need to find the transactions that drop tables in the log. The following code works for 2000, 2005, and 2008:

SELECT [Transaction Id], [Begin Time], [UID], [SPID]
FROM ::fn_dblog (NULL, NULL)
WHERE [Transaction Name] = 'DROPOBJ'
GO

The (NULL, NULL) is the starting LSN and ending LSN to process - NULL means process everything available. 

Results on SQL Server 2000 will look as follows for me logging in as a Windows login in the SA role:

Transaction Id Begin Time              UID         SPID       
-------------- ----------------------- ----------- -----------
0000:000000e0  2009/06/16 18:23:03:320 1           51

And for the same circumstances on 2005 and 2008, the results look like:

Transaction Id Begin Time               UID         SPID
-------------- ------------------------ ----------- -----------
0000:00000587  2009/06/16 17:49:56:927  -1          51

If the user who dropped the table logged in as a role member, and they're not connected as that SPID any more, you may not be able to tell who it was unless you're also tracking successful logins into your server - but you'll at least know what role it was.

Now, this only shows us that a table was dropped, not which table it was. There's no way to get the name of the table that was dropped, only the object ID - so you'll need to have some other way to determine what the table ID is if there are multiple table drops and only one of them is malignant.

For SQL Server 2000, the code to find which object ID we're talking about is as follows (dropping the Transacation Id into the WHERE clause):

SELECT DISTINCT [Object Name] FROM ::fn_dblog (NULL, NULL)
WHERE [Transaction Id] = '0000:000000e0'
AND [Context] = 'LCX_IAM';
GO

Object Name     
--------------------
(2009058193)

The object ID in parentheses is the ID of the table that was dropped. 

For SQL Server 2005 and 2008, the code is as follows (with the same Transaction Id substitution):

SELECT TOP (1) [Lock Information] FROM ::fn_dblog (NULL, NULL)
WHERE [Transaction Id] = '0000:00000587'
AND [Lock Information] LIKE '%SCH_M OBJECT%';
GO

Lock Information
--------------------------------------------
ACQUIRE_LOCK_SCH_M OBJECT: 8:2073058421:0

The 8:2073058421 is the database ID and object ID of the table that was dropped.

Now you can go find whoever it was and take whatever action you deem appropriate

Hope this helps!

PS If you find the you don't get enough info from ::fn_dblog, try turning on trace flag 2537. It allows the function to look at *all* possible log, not just the active log.

There's still a widely held misconception that when properly in the FULL or BULK_LOGGED recovery models that full or differential backups can truncate the log. No. It *NEVER* happens. This is one of the reasons why I'm doing a whole spotlight session on this at PASS this year - the transaction log and its behavior is IMHO one of the most misunderstood parts of SQL Server.

Notice that I said 'when properly in the FULL or BULK_LOGGED recovery models'. If you switch recovery models to FULL or BULK_LOGGED, until you take the first full backup, you are still essentially in the SIMPLE recovery model, and so the log will truncate on checkpoint. Once you take that first full backup, you are then in I-will-manage-the-size-of-the-log-through-log-backups mode. After that, the ONLY thing that will allow the log to clear/truncate is a log backup, as long as nothing else requires those transaction log records.

If you're not familiar with the term 'log clearing' or 'log truncating', they mean exactly the same thing - part of the transaction log is marked as no longer needed and can be overwritten. Nothing is zeroed out, the log file size is not altered. Some background reading on this:

• My Understanding Logging and Recovery in SQL Server article in TechNet Magazine from February 2009. This also has a screencast demo that shows the log continues to truncate-on-checkpoint after switching to FULL and before a full backup has been taken.
• An editorial I wrote in April about Importance of proper transaction log size management.
• A pretty deep blog post I wrote about analyzing VLF sequences in the log: Inside the Storage Engine: More on the circular nature of the log

Earlier this week I was involved in a discussion about log backup size management and how to prevent a log backup following a maintenance operation to not contain details of the maintenance operation.

There's a very simple answer: you can't.

If you do an operation in the FULL or BULK_LOGGED recovery models, the next log backup will contain all information required to replay that operation. In the FULL recovery model, everything is fully logged, so the log backup will contain all the log records generated by the operation. In the BULK_LOGGED recovery model, you may perform a minimally-logged operation, which generates hardly any transaction log, but the next log *backup* will be about the same size as if the operation was fully logged - because the log backup will pick up all the data extents modified by the minimally-logged operation.

One point in the discussion was that if you're running in the FULL or BULK_LOGGED recovery models, and you do a full backup after the maintenance operation, and before the log backup, the full backup will contain all the changes made by the maintenance operation, yes, and will clear the log.

No. Never.

A log backup is *ALL* the log generated since the last log backup. If this were not the case, how would log shipping work? You could take a full backup on the log shipping primary and suddenly you've broken the log backup chain and log shipping breaks. No, this is not how things work. A full backup contains only enough transaction log necessary to be able to restore that database to a transactionally consistent time - the time at which the data reading portion of the full backup completed. I blogged about this extensively previously:

• Debunking a couple of myths around full database backups (which also explains why the WITH STOPAT syntax exists for full and differential backups, but has no effect and is only there to allow you to put WITH STOPAT on all backups in a point-in-time restore sequence.
• More on how much transaction log a full backup includes

But you don't have to believe me - it's very simple to convince yourself. The following script will show you that a full backup has no effect on the transaction log. It does the following:

• Create a database and put it into the FULL recovery model, with a full backup.
• Create and populate and index.
• Take log backup 1 (just to clear things out)
• Rebuild the index.
• Take log backup 2.
• Rebuild the index.
• Take a full backup.
• Take log backup 3.

And we will see that log backup #3 is the same size as log backup #2. The full backup will make no difference whatsoever.

Here's the script:

USE master;
GO
DROP DATABASE LogBackupTest;
GO
CREATE DATABASE LogBackupTest;
GO
USE LogBackupTest;
GO

ALTER DATABASE LogBackupTest SET RECOVERY FULL;
GO
BACKUP DATABASE LogBackupTest TO
DISK = 'C:\SQLskills\LogBackupTest_Full1.bak' WITH INIT;
GO

CREATE TABLE t1 (c1 INT IDENTITY, c2 CHAR (8000) DEFAULT 'a');
GO
CREATE CLUSTERED INDEX t1c1 ON t1 (c1);
GO
SET NOCOUNT ON;
GO
INSERT INTO t1 DEFAULT VALUES;
GO 1000

BACKUP LOG LogBackupTest TO
DISK = 'C:\SQLskills\LogBackupTest_Log1.bak' WITH INIT;
GO

-- Rebuild the index to generate some log and get a baseline
ALTER INDEX t1c1 ON t1 REBUILD;
GO
BACKUP LOG LogBackupTest TO
DISK = 'C:\SQLskills\LogBackupTest_Log2.bak' WITH INIT;
GO

-- Now do it again, but take a full backup before the log backup
ALTER INDEX t1c1 ON t1 REBUILD;
GO
BACKUP DATABASE LogBackupTest TO
DISK = 'C:\SQLskills\LogBackupTest_Full2.bak' WITH INIT;
GO
BACKUP LOG LogBackupTest TO
DISK = 'C:\SQLskills\LogBackupTest_Log3.bak' WITH INIT;
GO

And here's the result:

Log backup #3 is the same size as log backup #2. It contains all the log generated since log backup #2 was taken. The full backup had no affect whatsoever, because that would break the log backup chain.

If you don't believe me, run the script yourself and you'll see. A full backup does not and cannot affect the transaction log.

About a year ago, I blogged a cool script that would work out how much of a database has changed since the last full backup - i.e. how big will the next differential backup be. You can find that script at New script: How much of the database has changed since the last full backup?. I'm in the middle of writing a script that will tell you how big your next log backup will be, and as part of it, I need a way to determine how many extents from minimally logged operations will be included in the next log backup. I thought it might be useful to someone so I tidied it up and here it is for you to play with. It's almost the same as the previous script I published.

The code below creates a function and a stored procedure. The basic idea behind the code is as follows:

For each online data file in the database
   For each GAM interval in the file
      Crack the ML map page using DBCC PAGE
      Interpret the ML bitmap to aggregate the changed extents
      Add the sum to the total changed extents for the database
   End
End
Report results

There's a function that I create in msdb call SQLskillsConvertToExtents that cracks some of the DBCC PAGE output, and the main procedure is called sp_SQLskillsMLChangedData and it created as a system object in master. I tried making it a table-valued function but you can't do things like INSERT-EXEC in a function, and that's required for processing the DBCC PAGE output. So - create your own wrapper function or whatever to use it. The interface/output is:

This is a true story, and unfolded over the last few days. It's deliberately written this way, I'm not trying to be patronizing - just illustrating the mistakes people can make if they don't know what not to do.

Once upon a time (well, a few days ago), there was a security person who had access to a 2000 SQL Server instance. He saw that the server had run out of disk space, but had no SQL server knowledge. He decided that the best thing to do was to delete the log file, instead of contact the real DBA to take corrective action. This person should not have had any access to SQL Server, or the ability to delete the log. Nevertheless, the log was deleted. And then the database became suspect. Eventually, with no other option, someone decided to create a new transaction log file using DBCC REBUILD_LOG. This was the right thing to do. The database wasn't being backed up so restore wasn't an option. Some of the details of who did what are unclear, as it so often the case. Needless to say, the real DBA was kept in the dark.

Unfortunately, whoever rebuilt the log didn't run DBCC CHECKDB afterwards to find out what corruption had been caused in the database by having the transaction log unceremoniously ripped out from under the database's feet. Rebuilding a transaction log is one of the worst things that can happen to a database, as all active transactions are thrown away, with no chance of rolling back. This leaves the database in a transactionally inconsistent, and potentially structurally inconsistent state (see Corruption: Last resorts that people try first... filed under my Bad Advice category, and Q4 from TechNet Magazine: February 2009 SQL Q&A column: Is it ever safe to rebuild a transaction log?).

Instead they carried on running. The real DBA thought everything was cool and even upgraded the instance from SQL 2000 to SQL 2005. To be honest, after seeing the 19000+ corruptions they had in the database, I'm surprised that the database upgraded successfully. But it did. Then he tried to rebuild some indexes, which failed with corruption errors. Which brought us to this morning, when DBCC CHECKDB was run. It reported a lot of corruption, but running from SSMS only showed the first 1000 errors (which was the inspiration for one of my previous posts today How to get all the corruption messages from CHECKDB. So they started to run REPAIR_ALLOW_DATA_LOSS, which will cause data loss - we chose the name of the repair option well. I got involved at this point, and saw from the list of errors that massive data loss would be the result.

Once they had re-run DBCC CHECKDB though the command line (luckily only 20 minutes) I could see all the errors. And I must say I was astounded. It was the *worst* case of multiply-allocated extents (see Inside the Storage Engine: Anatomy of an extent) that I've ever seen. Not only were the extents allocated by multiple IAM pages (see Inside the Storage Engine: IAM pages, IAM chains, and allocation units) - in other words, two objects thought they had the same pages in the database allocated, but the two objects had actually each proceeded to overwite the other's updates in the pages - getting the two clustered indexes hopelessly interlinked. Lots of errors (1000s) like:

Msg 8904, Level 16, State 1, Server NAMESCHANGEDTOPROTECTTHEINNOCENT, Line 1
Extent (1:9528) in database ID 5 is allocated by more than one
allocation object.
...
Msg 8978, Level 16, State 1, Server NAMESCHANGEDTOPROTECTTHEINNOCENT, Line 1
Table error: Object ID 1445580188, index ID 1, partition ID
376212519911424, alloc unit ID 94737543200768 (type In-row data). Page
(1:52696) is missing a reference from previous page (1:427112).
Possible chain linkage problem.
...
Msg 8977, Level 16, State 1, Server NAMESCHANGEDTOPROTECTTHEINNOCENT, Line 1
Table error: Object ID 1445580188, index ID 1, partition ID
376212519911424, alloc unit ID 94737543200768 (type In-row data).
Parent node for page (1:143210) was not encountered.
...
Msg 2533, Level 16, State 1, Server NAMESCHANGEDTOPROTECTTHEINNOCENT, Line 1
Table error: page (1:405139) allocated to object ID 1445580188, index
ID 1, partition ID 376212519911424, alloc unit ID 94737543200768 (type
In-row data) was not seen. The page may be invalid or may have an
incorrect alloc unit ID in its header.
...
CHECKDB found 1653 allocation errors and 17646 consistency errors in
database 'NAMESCHANGEDTOPROTECTTHEINNOCENT'.

The repair for all of this? Delete it all and fix up the links. MASSIVE data loss.

Lessons to learn from this:

• Don't give people with no clue about SQL Server access to SQL Server. 
• Don't delete a transaction log to reclaim space. Cardinal sin.
• Don't rebuild a transaction log UNLESS you run a full DBCC CHECKDB afterwards and satify yourself that you know the extent of the damage.
• Don't upgrade a database without running DBCC CHECKDB first. Best case - the upgrade fails. Worst case - it upgrades and then you might not be able to fix the corruptions.
• Don't just run repair without doing a little analysis on the errors reported, especially with a *huge* number of errors reported.

Finally, I'm really grateful to the DBA in question for letting me help him out with this, and to post this blog post - we all learn from our own and others' mistakes.

PS And I got involved in this from Twitter - I just *love* it. After initially being skeptical of how much time I'd spend on it, I'm finding the benefits of connecting to the SQL community in 'real-time' vastly outweigh the time I'm putting into it. Follow me on http://twitter.com/paulrandal and you'll see a bunch of other SQL MVPs on there too.

Page splits are always thought of as expensive, but just how bad are they? In this post I want to create an example to show how much more transaction log is created when a page in an index has to split. I'm going to use the sys.dm_tran_database_transactions DMV to show how much more transaction log is generated when a page has to split. You can find the list of columns and a small amount of explanation of each column in Books Online here - I was reminded of its existence by someone on Twitter (sorry, don't remember who it was and I couldn't find it in search).

In the example, I'm going to create a table with approximately 1000-byte long rows:

CREATE DATABASE PageSplitTest;
GO
USE pagesplittest;
GO

CREATE TABLE BigRows (c1 INT, c2 CHAR (1000));
CREATE CLUSTERED INDEX BigRows_CL ON BigRows (c1);
GO

INSERT INTO BigRows VALUES (1, 'a');
INSERT INTO BigRows VALUES (2, 'a');
INSERT INTO BigRows VALUES (3, 'a');
INSERT INTO BigRows VALUES (4, 'a');
INSERT INTO BigRows VALUES (6, 'a');
INSERT INTO BigRows VALUES (7, 'a');
GO

I've engineered the case where the clustered index data page has space for one more row, and I've left a 'gap' at c1=5. Let's add it as part of an explicit transaction and see how much transaction log is generated:

BEGIN TRAN
INSERT INTO BigRows VALUES (8, 'a');
GO

SELECT [database_transaction_log_bytes_used] FROM sys.dm_tran_database_transactions
WHERE [database_id] = DB_ID ('PageSplitTest');
GO

database_transaction_log_bytes_used
-----------------------------------
1228

That's about what I'd expect for that row. Now what about when I cause a page split by inserting the 'missing' c1=5 row into the full page?

-- commit previous transaction
COMMIT TRAN
GO

BEGIN TRAN
INSERT INTO BigRows VALUES (5, 'a');
GO

SELECT [database_transaction_log_bytes_used] FROM sys.dm_tran_database_transactions
WHERE [database_id] = DB_ID ('PageSplitTest');
GO

database_transaction_log_bytes_used
-----------------------------------
6724

Wow. 5.5x more bytes are written to the transaction log as part of the system transaction that does the split.

The ratio gets worse as the row size gets smaller. For a row with an approximately 100-byte long row (use the same code as above, but change to a CHAR (100), insert 67 rows with a 'gap' somewhere then insert the 68th to cause the split), the two numbers are 328 and 5924 - the split cause 18 times more log to be generated! For a row with an approximately 10-byte long row, I got numbers of 240 and 10436, because I created skewed data (about 256 rows with the key value 8) and then inserted key value 5 which forced a (rare) non-middle page split. That's a ratio of more than 43 times more log generated! You can try this yourself if you want: I changed the code to have a CHAR (10), inserted values 1, 2, 3, 4, 6, 7, then inserted 256 key values of 8 and then 2 of 5. The resulting page had only 6 rows - it split after the key value 5 - the Storage Engine doesn't always do a 50/50 page split. And that's not even causing nasty cascading page-splits, or splits that have to split a page multiple times to fit a new (variable-sized) row in.

Bottom line: page splits don't just cause extra IOs and index fragmentation, they generate a *lot* more transaction log. And all that log has to be (potentially) backed up, log shipped, mirrored....

A short post to start the day (in India) and then at lunchtime I'll do how it works: FILESTREAM garbage collection.

This is a question that came up recently on an MVP discussion list: why does a 200MB log backup take 40 minutes to restore on my log-shipping secondary?

First answer I thought of was that the I/O subsystem on the log-shipping secondary was very slow, or broken in some way, so I/Os were taking ages to complete. Nope - I/O subsystem was performing well.

Next thing I suggested was the the log-shipping secondary was restoring the log backups using WITH STANDBY and there was something like an index rebuild that was being rolled back. As an aside, when you restore log backups on the log-shipping secondary, you have a choice how they recovery: either WITH NORECOVERY or WITH STANDBY. The first option doesn't allow any access to the database, as the database is still "in recovery". The second option runs the REDO part of recovery, then runs the UNDO part of recovery, but saves the details of what it had to do for UNDO into a file (who's name and location you specify). It then allows read-only access to the database, for queries/reporting/whatever. Obviously if there's a lot of transaction log that has to be undone (i.e. rolling back transactions that weren't committed at the time the log backup completed), then this could take some time. But 40 minutes? No. That wasn't it.

I was partly right on my second guess. The *previous* log backup that was restored WITH STANDBY contained a long-running index operation, and so the undo file that the restore created was *huge*. The next log backup that's restored after a RESTORE ... WITH STANDBY, must first undo everything in the undo file (i.e. put the database back to the exact state it was in as if the WITH STANDBY part of the restore never happened) before it can restore more transaction log. In this case, no-one had noticed that the previous log restore *also* took a lot of time and created the huge undo file. It just looked like the 200MB log backup was causing the problem.

My advice: in any kind of there's-suddenly-a-corruption-or-performance-problem situation, don't just look at what's happening now. Always look at what happened leading up to the problem, as the answer is often there.

The database is in the SIMPLE recovery model. Well, to be completely honest, it's in the FULL recovery model, but there hasn't been a full database backup yet, so as far as transaction log behavior is concerned, it behaves as if it was in SIMPLE (the log can be cleared by a CHECKPOINT) - again, if this makes no sense, go read the TechNet Magazine article. 

And then see how many VLFs it has using the DBCC LOGINFO command (and this is the *only* way to see how many VLFs there are):

DBCC LOGINFO ('LogTestDB');
GO

FileId   FileSize   StartOffset   FSeqNo   Status   Parity CreateLSN
-------- ---------- ------------- -------- -------- ------ -----------
2        1245184    8192          31       2        64     0
2        1245184    1253376       0        0        0      0
2        1245184    2498560       0        0        0      0
2        1499136    3743744       0        0        0      0

We've got 4 VLFs. The Status column tells us whether the VLF is active or not. A status of 2 means the VLF is active, 0 means it's not. The sequence number (FSeqNo) is the logical order of the VLFs within the log. The FileSize is in bytes (so each VLF is about 1.25 MB). Right now there's only one active VLF.

Now I'll engineer the situation in the image above. I'm going to fill the log so that VLFs 1, 2, and 3 are active. Then I'm going to start an explicit transaction that will hold VLF 3 and onwards active. Then I'll continue filling the log so it wraps around and starts to fill up VLF 1 again.

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

SET NOCOUNT ON;
INSERT INTO BigRows DEFAULT VALUES;
GO 300

I've filled up VLFs 1 and 2, and started on 3. Let's check with DBCC LOGINFO:

DBCC LOGINFO ('LogTestDB');
GO

FileId   FileSize   StartOffset   FSeqNo   Status   Parity CreateLSN
-------- ---------- ------------- -------- -------- ------ -----------
2        1245184    8192          31       2        64     0
2        1245184    1253376       32       2        64     0
2        1245184    2498560       33       2        64     0
2        1499136    3743744       0        0        0      0

As you can see, the first 3 VLFs now have a status of 2 (active), and they're in sequence. Now I'll create an explicit transaction that will prevent VLF 3 and onwards being cleared.

BEGIN TRAN
INSERT INTO BigRows DEFAULT VALUES;
GO

If I explicitly do a CHECKPOINT now, VLFs 1 and 2 will clear:

CHECKPOINT
GO

DBCC LOGINFO ('LogTestDB');
GO

FileId   FileSize   StartOffset   FSeqNo   Status   Parity CreateLSN
-------- ---------- ------------- -------- -------- ------ ----------
2        1245184    8192          31       0        64     0
2        1245184    1253376       32       0        64     0
2        1245184    2498560       33       2        64     0
2        1499136    3743744       0        0        0      0

Now I'll carry on filling up the BigRows table so the log wraps around and starts filling up VLFs 1 and two again.

INSERT INTO BigRows DEFAULT VALUES;
GO 300

DBCC LOGINFO ('LogTestDB');
GO

FileId   FileSize   StartOffset   FSeqNo   Status   Parity CreateLSN
-------- ---------- ------------- -------- -------- ------ ----------
2        1245184    8192          35       2        128    0
2        1245184    1253376       32       0        64     0
2        1245184    2498560       33       2        64     0
2        1499136    3743744       34       2        64     0

You can see that the log has wrapped around now, but VLFs 3 and 4 are still active. Look at the sequence numbers of the active VLFs... the active log is VLF 3 then 4 then 1, with sequence numbers 33 then 34 then 35. Now if I carry on filling up the table, what's going to happen when the log bumps up against VLF 3 that is still active? Will it stop or will it grow?

INSERT INTO BigRows DEFAULT VALUES;
GO 300

DBCC LOGINFO ('LogTestDB');
GO

FileId   FileSize   StartOffset   FSeqNo   Status   Parity CreateLSN
-------- ---------- ------------- -------- -------- ------ ------------------
2        1245184    8192          35       2        128    0
2        1245184    1253376       36       2        128    0
2        1245184    2498560       33       2        64     0
2        1499136    3743744       34       2        64     0
2        253952     5242880       37       2        64     36000000049300052
2        270336     5496832       38       2        64     36000000049300052
2        253952     5767168       0        0        0      36000000107500066
2        335872     6021120       0        0        0      36000000107500066
2        253952     6356992       0        0        0      36000000190700020
2        401408     6610944       0        0        0      36000000190700020
2        253952     7012352       0        0        0      37000000037300040
2        466944     7266304       0        0        0      37000000037300040

The answer is that it grew, and kind of skipped the active VLFs! Look at the sequence numbers. The new sequence of the active log is VLF 3 then 4 then 1 then 2 then 5 then 6, as you can see from the sequence numbers. Once the active transaction I created commits or rolls back, VLFs 3, 4, 1, and 2 can clear and then the 'normal' sequencing of VLFs in the log will resume.

Every VLF has a small header which contains the sequence number of the VLF within the transaction log, so the log can kind of do contortions to work around active VLFs in the middle of the log. Very cool.

Ok - that was fun - now I feel better!

PS In the last couple of DBCC LOGINFO dumps, where the log has wrapped around, you can see that the parity bits for the log blocks in the VLFs have changed, as I explained in one of my previous posts Search Engine Q&A #24: Why can't the transaction log use instant initialization?.

In this week's survey, I'm interested in how *you* manage the size of your transaction log. I'll report on the results around 4/10/2009.

Thanks!

(No comments please... wait till the results post next week) 

Way back at the start of me blogging here I wrote a comprehensive description of ghost records and the ghost cleanup process - see Inside the Storage Engine: Ghost cleanup in depth. A question came up in the class I'm teaching this week that's worth answering in a blog post - do ghost records occur in heaps? The answer is no, not during normal processing.

When snapshot isolation is enabled, deletes from a heap are ghosted, as part of the overall versioning process, which can lead to some interesting side-effects. A versioned record has an extra 14-bytes tagged on the end, so a heap record that suddenly becomes versioned is 14-bytes longer - which may mean it doesn't fit on the page any longer. This could lead to it being moved, resulting in a forwarding/forwarded record pair - just because the record was deleted! Now, the page has to be full for this time happen, and the Storage Engine will take steps to avoid this happening for rows less than 32 bytes long - but that's getting a little too deep.

Anyway, I digress. I want to show you the difference between deleting from a clustered index and from a heap. I'm going to create two such tables, then delete row from each and roll it back.

Here's a portion of the results from looking in the transaction log. The line of code where I turn off auto-update stats is just to prevent the auto-create transactions from cluttering up my view of the transaction log.

The first (highlighted) transaction is for the delete/rollback in the clustered index. You can clearly see that the third column shows a log context of ghosting for the LOP_DELETE_ROWS log record, plus the setting of the 'this page has at least one ghost record' in the PFS byte for that page.

The second (unhighlighted) transaction is for the delete/rollback in the heap. Here you can see that it just does a straight delete.

If you look at the data page contents before the rollback in both cases, for the clustered index you'll still be able to see the deleted (ghosted) record, and for the heap you'll see the deleted record really is deleted.

Hope this helps.

This is an interesting case that cropped up yesterday - the transaction log is damaged so a log backup doesn't work (with the error below):

Backup detected log corruption in database FakeDBName. Context is FirstSector. LogFile: 2 'F:\SQLLOGS\XYZ\FakeDBName_Log.ldf' VLF SeqNo: x502e VLFBase: x2ce40000 LogBlockOffset: x2d0a9000 SectorStatus: 2 LogBlock.StartLsn.SeqNo: x4ee3 LogBlock.StartLsn.Blk: x1348 Size: x200 PrevSize: x400
2009-03-06 10:00:02.61 Backup      Error: 3041, Severity: 16, State: 1.
2009-03-06 10:00:02.61 Backup      BACKUP failed to complete the command BACKUP LOG FakeDBName Check the backup application log for detailed messages.
2009-03-06 10:00:03.61 Backup      Error: 3041, Severity: 16, State: 1.

However a full backup succeeds, as does a DBCC CHECKDB. What's going on?

The answer comes with understanding what portions of the transaction log are required for these operations. (For a good understanding of the transaction log itself, along with logging and recovery, see my article in the February TechNet Magazine.)

A transaction log backup, by its very nature, has to backup *all* transaction log generated since the last log backup - so it will try to backup the corrupt portion and fail.

A full database backup only has to backup enough transaction log to allow the database to be restored and recovered to a transactionally consistent point. In other words, it only requires the transaction log back to the beginning of the oldest active transaction at the point that the data-reading section of the full backup completes. This is a source of immense confusion - many people don't believe that a full (or differential) backup needs to also backup some transaction log. For a more in-depth study of this, see my previous blog posts Debunking a couple of myths around full database backups and More on how much transaction log a full backup includes.

A DBCC CHECKDB operation uses a database snapshot to get a transactionally consistent view of the database on which to run consistency checks. When the database snapshot is created, crash recovery is run on it to make it transactionally consistent. That requires the same amount of log as if a full backup was taken - back to the beginning of the oldest active transaction at the time the database snapshot is created. See CHECKDB From Every Angle: Complete description of all CHECKDB stages for more info.

So - it's entirely possible for the situation reported above to exist. The question then becomes, how to recover from it?

Assuming that the database files are intact, there is a simple solution. This solution will break the log backup chain, but given that the log is corrupt so a log backup cannot be taken, the log backup chain is *already* broken. Here's what to do:

1. Stop all user activity in the database
2. Switch to the SIMPLE recovery model (breaking the log backup chain and removing the requirement that the damaged portion of log must be backed up)
3. Switch to the FULL recovery model
4. Take a full database backup (thus starting a new log backup chain)
5. Start taking log backups

You might want to manually shrink and grow the log file in between steps 2 and 3 too - in case the log file is on a damaged portion of disk - or maybe even shrink it right down and add another log file on an undamaged disk. You also will need to do some root-cause analysis to determine why the corruption occured in the first place, and to take preventative measures to stop it happening again.

Hope this helps

PS In my previous post, Testing a new survey method: backup validation, the answer with the largest number of responses so far is that people never verify their backups - very disturbing!

Back in 2005 Kimberly produced two very popular webcast series - an 11-part webcast series for TechNet called SQL Server 2005 for the IT Professional and a 10-part webcast series for MSDN called A Primer for Proper SQL Server Development. The webcast links and blog posts were broken for quite a while but now they're all fixed up and working again. I've created some web pages that link to all the webcasts and blog posts, along with abstracts. I've also included some more recent ones too and will be adding to the list over the next few weeks.

There's over 30 hours of good stuff to watch - check them out at http://www.sqlskills.com/webcasts.asp

One of the things I mentioned in my recent TechNet Magazine article on Understanding Logging and Recovery was the need to manage the transaction log so the number of VLFs (virtual log files) does not get too large (with too large being more than, say, 100 VLFs). Linchi Shea (a fellow MVP) has just posted some performance numbers comparing insert/update/delete performance between a database with 16 VLFs and one with 20000 VLFs, representing a poorly managed transaction log. You can see his blog post here.

For those wishing to take charge of unruly transaction logs, checkout Kimberly's blog posts - starting with this one. And if you want to quickly know how many VLFs your transaction log has, use the undocumented DBCC LOGINFO command - the number of lines of output is the number of VLFs you have.

Next posts coming up will be photos - we're in Bangkok right now and I've got 3 Where In The World Are Paul and Kimberly posts queued up - St. Lucia, Hyderabad, and Bangkok.

OK - last content post today. I forgot that the February TechNet Magazine also has the latest edition of my regular SQL Q&A column. This month's column covers:

• Should backup compression be enabled at the instance level?
• Client redirection during database mirroring failovers
• Partition-level lock escalation in SQL Server 2008
• Is it ever safe to rebuild a transaction log?

Check out the column at http://technet.microsoft.com/en-us/magazine/2009.02.sqlqa.aspx

Wow - today is all about new content. As if I haven't already blogged about enough stuff to keep you reading through next week, the February issue of TechNet Magazine is now available and contains a feature article I wrote about understanding how logging and recovery work inside SQL Server.

The article covers:

• What is logging?
• What is recovery?
• The transaction log (include logical and physical architecture)
• Recovery models and how they affect the behavior of the transaction log

There's also a ten-minute screencast video where I demonstrate a runaway transaction log.

Check it out at http://technet.microsoft.com/en-us/magazine/2009.02.logging.aspx.

Here's a question I got from someone who attended our database maintenance workshop at PASS last week (paraphrased):

I attended your pre-conference session on database maintenance and found it to be very informative.  From what you told use though, I think I need to change my nightly backup procedure.  I like to get my databases back to as small of a size as possible before backing them up, so I run the following commands to do this before taking the full database backup.  Could you help me with a better way of doing this? We're on SQL Server 2005.

BACKUP LOG <mydbname> WITH NO_LOG

DBCC SHRINKDATABASE (<mydbname>)

And here's the answer I sent back:

How large is the database? And how long must you keep the backups around? If the cumulative size of the backups takes up a large proportion of your available storage space (and we're talking more than just a single direct-attached 100+GB drive), then it may be worth compressing the backups - otherwise you're likely causing yourself more trouble than its worth.
 
By doing BACKUP LOG WITH NO_LOG you're effectively throwing away log records and removing the possibility of doing any kind of point-in-time, or up-to-the-second recovery (see BACKUP LOG WITH NO_LOG - use, abuse, and undocumented trace flags to stop it). If you're running in the FULL recovery model, and you don't care about either of these features, then you should switch to the SIMPLE recovery model. If you really want to be in FULL, don't ever use WITH NO_LOG.

The amount of transaction log that a full backup requires cannot be changed by you truncating the log. The full backup will backup any log it requires to enable the restored database to be a transctionally consistent copy of the database. See Debunking a couple of myths around full database backups and More on how much transaction log a full backup includes.

Doing a DBCC SHRINKDATABASE (the same exact operation as a database auto-shrink) will cause massive index fragmentation, and cause file-system fragmentation of the data files, as they will likely need to grow again after you've squeezed all the space out of them. See Auto-shrink - turn it OFF! for more details on the effects.

If you're really concerned about backup sizes and space is at a premium, I recommend using a 3rd-party backup compression tool such as LiteSpeed or HyperBac so you're not affecting the actual database. Remember also that SQL Server 2008 has native backup compression too - see my blog post here for more details.

Hope this helps

Today's post is based on a bunch of questions I've had around the various compression features in SQL Server 2008.

Does turning on data compression or backup compression compress the transaction log files on disk?

No. The transaction log is not compressed in any way under any circumstances. Rows from tables and indexes that have compression enabled will be logged in their row compressed forms, even if page compression is enabled.

Does data compression compress LOB columns?

No. There is no native compression support for any LOB columns (n/text, image, n/varchar(max), varbinary(max), XML), whether stored in-row or out-of-row. There's also no native compression support for FILESTREAM data.

Does log shipping use compression to compress the logs being shipped?

Log shipping does not ship transaction logs - it ships log *backups*. If backup compression is enabled for the instance hosting the log shipping primary database, or the log shipping job is changed to enable backup compression, then the log backups will be compressed and less data will be sent over the wire to the log shipping secondary(s).

Is backup compression the same as log stream compression with database mirroring?

No. Backup compression compresses backups (see my previous blog post here). Log stream compression with database mirroring compresses transaction log records before sending them between the principal and the mirror (see my previous blog post here).

Should I just turn on backup compression at the instance level?

Not necessarily. It depends whether the majority of database on the instance will benefit from backup compression. Backup compression (and any compression algorithm) uses CPU whether a decent compression ratio is achieved or not. Check what compression ratio is achieved first and then enable backup compression if its worth it. Otherwise, just enable it for individual databases.

Does data compression use the same algorithm as backup compression?

No. Backup compression uses a proprietary block-based compression algorithm that is part of Windows. Data compression uses up to 3 algorithms, depending on the level of compression configured. Row compression just makes all non-LOB columns into variable-length columns. Page compression does row compression, then common-prefix compression for each table columns, then common-value dictionary compression for each page. Details can be found at the following BOL sections: Row Compression Implementation  and Page Compression Implementation.

Hope this helps!

During early SQL Server 2008 development, the Storage Engine team introduced additional minimally-logged functionality. And then it was removed again for RTM. Now it seems that they've bowed under customer pressure and have made the functionality available again (see Sunil's announcement here).

Using trace flag 610 in the RTM build, you enable the potential for minimal-logging when:

• Bulk loading into an empty clustered index, with no nonclustered indexes
• Bulk loading into a non-empty heap, with no nonclustered indexes

Sunil's previous blog post here gives more info on the required syntax - very useful!