MSSQLTREK

SQL Server CheckPoints – Trace Flag 3502

Checkpoint – One of the wonderful mechanisms baked within SQL Server to Flush Dirty Pages to Disk and to clear Transaction log(When a Database is Set to SIMPLE Recovery Model) automatically.

Few scenarios where CHECKPOINTS are triggered automatically:

When SQL Instance has been Shutdown, a checkpoint on all the databases.

A Checkpoint on Model Database each time a new database has been created.

T-Log 70% full and Database is in Simple Recovery Model.

A Manual CHECKPOINT by a Sysadmin or Database Owner/Backup Operator.

So…Is there any easy way to monitor the occurrences of Checkpoint??

Yes…We’ve a Documented Trace Flag 3502 which can be enabled Globally.

Demo: Scenario 1 – Shutting Down SQL Instance

I’ve enabled 3502 Traceflag and shut down my SQL Instance. See the Error Log contents below.

2011-09-19 22:12:08.200 spid52 Microsoft SQL Server 2008 R2 (SP1) – 10.50.2425.0 (X64)
Apr 6 2011 21:03:25
Copyright (c) Microsoft Corporation
Developer Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)
2011-09-19 22:12:08.210 spid52 (c) Microsoft Corporation.
2011-09-19 22:12:08.210 spid52 All rights reserved.
2011-09-19 22:12:08.210 spid52 Server process ID is 1968.
2011-09-19 22:12:08.210 spid52 System Manufacturer: ‘Dell Inc.’, System Model: ‘Studio 1555’.
2011-09-19 22:12:08.210 spid52 Authentication mode is MIXED.
2011-09-19 22:12:08.220 spid52 Logging SQL Server messages in file ‘C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\Log\ERRORLOG’.
2011-09-19 22:12:08.220 spid52 The error log has been reinitialized. See the previous log for older entries.
2011-09-19 22:12:29.830 spid52 DBCC TRACEON 3502, server process ID (SPID) 52. This is an informational message only; no user action is required.
2011-09-19 22:13:09.050 spid7s Checkpointing and truncating dbid 1 (master).
2011-09-19 22:13:09.060 spid7s Ckpt dbid 1 started (8)
2011-09-19 22:13:09.060 spid7s About to log Checkpoint begin.
2011-09-19 22:13:09.100 spid7s Ckpt dbid 1 phase 1 ended (8)
2011-09-19 22:13:09.130 spid7s About to log Checkpoint end.
2011-09-19 22:13:09.140 spid7s Ckpt dbid 1 complete
2011-09-19 22:13:09.140 spid7s Checkpointing and truncating dbid 2 (tempdb).
2011-09-19 22:13:09.140 spid7s About to log Checkpoint begin.
2011-09-19 22:13:09.160 spid7s About to log Checkpoint end.
2011-09-19 22:13:09.200 spid7s No checkpoint needed on dbid 3 (model).
2011-09-19 22:13:09.200 spid7s Checkpointing and truncating dbid 4 (msdb).
2011-09-19 22:13:09.220 spid7s Ckpt dbid 4 started (8)
2011-09-19 22:13:09.220 spid7s About to log Checkpoint begin.
2011-09-19 22:13:09.220 spid7s Ckpt dbid 4 phase 1 ended (8)
2011-09-19 22:13:09.260 spid7s About to log Checkpoint end.
2011-09-19 22:13:09.310 spid7s Ckpt dbid 4 complete
2011-09-19 22:13:09.350 spid7s No checkpoint needed on dbid 5 (LiteSpeedLocal).
2011-09-19 22:13:09.360 spid7s No checkpoint needed on dbid 6 (LiteSpeedCentral).
2011-09-19 22:13:09.730 spid7s No checkpoint needed on dbid 8 (AdventureWorksDW2008R2).
2011-09-19 22:13:09.780 spid7s No checkpoint needed on dbid 9 (AdventureWorksLT2008R2).
2011-09-19 22:13:09.910 spid7s Checkpointing and truncating dbid 10 (AdventureWorks).
2011-09-19 22:13:09.910 spid7s Ckpt dbid 10 started (8)
2011-09-19 22:13:09.930 spid7s About to log Checkpoint begin.
2011-09-19 22:13:09.930 spid7s Ckpt dbid 10 phase 1 ended (8)
2011-09-19 22:13:09.930 spid7s About to log Checkpoint end.
2011-09-19 22:13:09.980 spid7s Ckpt dbid 10 complete
2011-09-19 22:13:10.000 spid7s No checkpoint needed on dbid 11 (AdventureWorksDW).
2011-09-19 22:13:10.030 spid7s Checkpointing and truncating dbid 12 (AdventureWorksLT).
2011-09-19 22:13:10.030 spid7s Ckpt dbid 12 started (8)
2011-09-19 22:13:10.060 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.070 spid7s Ckpt dbid 12 phase 1 ended (8)
2011-09-19 22:13:10.070 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.120 spid7s Ckpt dbid 12 complete
2011-09-19 22:13:10.150 spid7s Checkpointing and truncating dbid 13 (AdventureWorks_11).
2011-09-19 22:13:10.150 spid7s Ckpt dbid 13 started (8)
2011-09-19 22:13:10.150 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.170 spid7s Ckpt dbid 13 phase 1 ended (8)
2011-09-19 22:13:10.170 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.210 spid7s Ckpt dbid 13 complete
2011-09-19 22:13:10.220 spid7s Checkpointing and truncating dbid 14 (AdventureWorks_tstst).
2011-09-19 22:13:10.220 spid7s Ckpt dbid 14 started (8)
2011-09-19 22:13:10.230 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.230 spid7s Ckpt dbid 14 phase 1 ended (8)
2011-09-19 22:13:10.240 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.280 spid7s Ckpt dbid 14 complete
2011-09-19 22:13:10.300 spid7s No checkpoint needed on dbid 15 (AdventureWorks_testst).
2011-09-19 22:13:10.320 spid7s No checkpoint needed on dbid 16 (tstrestore).
2011-09-19 22:13:10.350 spid7s Checkpointing and truncating dbid 17 (ReportServer).
2011-09-19 22:13:10.350 spid7s Ckpt dbid 17 started (8)
2011-09-19 22:13:10.350 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.370 spid7s Ckpt dbid 17 phase 1 ended (8)
2011-09-19 22:13:10.370 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.420 spid7s Ckpt dbid 17 complete
2011-09-19 22:13:10.450 spid7s Checkpointing and truncating dbid 18 (ReportServerTempDB).
2011-09-19 22:13:10.450 spid7s Ckpt dbid 18 started (8)
2011-09-19 22:13:10.480 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.500 spid7s Ckpt dbid 18 phase 1 ended (8)
2011-09-19 22:13:10.500 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.550 spid7s Ckpt dbid 18 complete
2011-09-19 22:13:10.570 spid7s Checkpointing and truncating dbid 19 (3014_demo).
2011-09-19 22:13:10.570 spid7s Ckpt dbid 19 started (8)
2011-09-19 22:13:10.580 spid7s About to log Checkpoint begin.
2011-09-19 22:13:10.590 spid7s Ckpt dbid 19 phase 1 ended (8)
2011-09-19 22:13:10.600 spid7s About to log Checkpoint end.
2011-09-19 22:13:10.630 spid7s Ckpt dbid 19 complete
2011-09-19 22:13:10.630 spid7s Checkpointing and truncating dbid 32767 (mssqlsystemresource).
2011-09-19 22:13:11.160 spid14s Service Broker manager has shut down.
2011-09-19 22:13:11.250 spid7s Skipping CleanShutdownDB() checkpoint on dbid 19 (3014_demo) with 0 freedOutcomes.
2011-09-19 22:13:11.640 spid7s Skipping CleanShutdownDB() checkpoint on dbid 18 (ReportServerTempDB) with 0 freedOutcomes.
2011-09-19 22:13:11.740 spid7s Skipping CleanShutdownDB() checkpoint on dbid 17 (ReportServer) with 0 freedOutcomes.
2011-09-19 22:13:11.850 spid7s Ckpt dbid 16 started (8)
2011-09-19 22:13:11.850 spid7s About to log Checkpoint begin.
2011-09-19 22:13:11.870 spid7s Ckpt dbid 16 phase 1 ended (8)
2011-09-19 22:13:11.890 spid7s About to log Checkpoint end.
2011-09-19 22:13:11.920 spid7s Ckpt dbid 16 complete
2011-09-19 22:13:12.050 spid7s Skipping CleanShutdownDB() checkpoint on dbid 15 (AdventureWorks_testst) with 0 freedOutcomes.
2011-09-19 22:13:12.180 spid7s Skipping CleanShutdownDB() checkpoint on dbid 14 (AdventureWorks_tstst) with 0 freedOutcomes.
2011-09-19 22:13:12.280 spid7s Skipping CleanShutdownDB() checkpoint on dbid 13 (AdventureWorks_11) with 0 freedOutcomes.
2011-09-19 22:13:12.390 spid7s Skipping CleanShutdownDB() checkpoint on dbid 12 (AdventureWorksLT) with 0 freedOutcomes.
2011-09-19 22:13:12.480 spid7s Ckpt dbid 11 started (8)
2011-09-19 22:13:12.480 spid7s About to log Checkpoint begin.
2011-09-19 22:13:12.510 spid7s Ckpt dbid 11 phase 1 ended (8)
2011-09-19 22:13:12.530 spid7s About to log Checkpoint end.
2011-09-19 22:13:12.560 spid7s Ckpt dbid 11 complete
2011-09-19 22:13:12.690 spid7s Skipping CleanShutdownDB() checkpoint on dbid 10 (AdventureWorks) with 0 freedOutcomes.
2011-09-19 22:13:12.860 spid7s Ckpt dbid 9 started (8)
2011-09-19 22:13:12.860 spid7s About to log Checkpoint begin.
2011-09-19 22:13:12.900 spid7s Ckpt dbid 9 phase 1 ended (8)
2011-09-19 22:13:12.920 spid7s About to log Checkpoint end.
2011-09-19 22:13:12.950 spid7s Ckpt dbid 9 complete
2011-09-19 22:13:13.180 spid7s Ckpt dbid 8 started (8)
2011-09-19 22:13:13.180 spid7s About to log Checkpoint begin.
2011-09-19 22:13:13.200 spid7s Ckpt dbid 8 phase 1 ended (8)
2011-09-19 22:13:13.220 spid7s About to log Checkpoint end.
2011-09-19 22:13:13.270 spid7s Ckpt dbid 8 complete
2011-09-19 22:13:13.410 spid7s Ckpt dbid 6 started (8)
2011-09-19 22:13:13.410 spid7s About to log Checkpoint begin.
2011-09-19 22:13:13.460 spid7s Ckpt dbid 6 phase 1 ended (8)
2011-09-19 22:13:13.480 spid7s About to log Checkpoint end.
2011-09-19 22:13:13.510 spid7s Ckpt dbid 6 complete
2011-09-19 22:13:13.640 spid7s Ckpt dbid 5 started (8)
2011-09-19 22:13:13.640 spid7s About to log Checkpoint begin.
2011-09-19 22:13:13.660 spid7s Ckpt dbid 5 phase 1 ended (8)
2011-09-19 22:13:13.670 spid7s About to log Checkpoint end.
2011-09-19 22:13:13.710 spid7s Ckpt dbid 5 complete
2011-09-19 22:13:13.880 spid7s Ckpt dbid 4 started (8)
2011-09-19 22:13:13.880 spid7s About to log Checkpoint begin.
2011-09-19 22:13:13.880 spid7s Ckpt dbid 4 phase 1 ended (8)
2011-09-19 22:13:13.890 spid7s About to log Checkpoint end.
2011-09-19 22:13:13.890 spid7s Ckpt dbid 4 complete
2011-09-19 22:13:14.000 spid7s Skipping CleanShutdownDB() checkpoint on dbid 3 (model) with 0 freedOutcomes.
2011-09-19 22:13:14.140 spid7s Ckpt dbid 1 started (8)
2011-09-19 22:13:14.140 spid7s About to log Checkpoint begin.
2011-09-19 22:13:14.140 spid7s Ckpt dbid 1 phase 1 ended (8)
2011-09-19 22:13:14.140 spid7s About to log Checkpoint end.
2011-09-19 22:13:14.140 spid7s Ckpt dbid 1 complete
2011-09-19 22:13:14.140 spid7s SQL Server is terminating in response to a ‘stop’ request from Service Control Manager. This is an informational message only. No user action is required.
2011-09-19 22:13:14.180 spid7s SQL Trace was stopped due to server shutdown. Trace ID = ‘1’. This is an informational message only; no user action is required.
Sooo….SQL Server is making sure that a CHECKPOINT is issued on all the Databases as mentioned above before Shutting down the SQL Instance.( Which plays a huge and a very critical role in crash recovery when SQL Instance has been started)

Scenario 2- Creating a new User Database:

I’ve created a Database called “Checkpoint_tst”. See the Error Log contents below.

2011-09-19 22:18:58.020 spid53 Microsoft SQL Server 2008 R2 (SP1) – 10.50.2425.0 (X64)
Apr 6 2011 21:03:25
Copyright (c) Microsoft Corporation
Developer Edition (64-bit) on Windows NT 6.1 <X64> (Build 7601: Service Pack 1)
2011-09-19 22:18:58.020 spid53 (c) Microsoft Corporation.
2011-09-19 22:18:58.020 spid53 All rights reserved.
2011-09-19 22:18:58.020 spid53 Server process ID is 9120.
2011-09-19 22:18:58.020 spid53 System Manufacturer: ‘Dell Inc.’, System Model: ‘Studio 1555’.
2011-09-19 22:18:58.020 spid53 Authentication mode is MIXED.
2011-09-19 22:18:58.020 spid53 Logging SQL Server messages in file ‘C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\Log\ERRORLOG’.
2011-09-19 22:18:58.020 spid53 The error log has been reinitialized. See the previous log for older entries.
2011-09-19 22:18:58.020 spid53 DBCC TRACEON 3502, server process ID (SPID) 53. This is an informational message only; no user action is required.
2011-09-19 22:20:11.500 spid53 Ckpt dbid 3 started (8)
2011-09-19 22:20:11.500 spid53 About to log Checkpoint begin.
2011-09-19 22:20:11.510 spid53 Ckpt dbid 3 phase 1 ended (8)
2011-09-19 22:20:11.510 spid53 About to log Checkpoint end.
2011-09-19 22:20:11.520 spid53 Ckpt dbid 3 complete
2011-09-19 22:20:11.790 spid53 Starting up database ‘checkpoint_tst’.
2011-09-19 22:20:11.840 spid53 Ckpt dbid 20 started (0)
2011-09-19 22:20:11.840 spid53 About to log Checkpoint begin.
2011-09-19 22:20:11.840 spid53 Ckpt dbid 20 phase 1 ended (0)
2011-09-19 22:20:11.840 spid53 About to log Checkpoint end.
2011-09-19 22:20:11.840 spid53 Ckpt dbid 20 complete
2011-09-19 22:20:55.860 spid11s About to log Checkpoint begin.
2011-09-19 22:20:55.870 spid11s About to log Checkpoint end.

(22 row(s) affected)

dbid= 3 is MODEL Database. You can pull that info by

select name,database_id from sys.databases
where database_id = 3

Hope this is informative!

Backup Internals – Trace Flag 3014

Trace Flag 3014– This is one of the undocumented Trace flags in SQL Server, which basically gives a detailed information(Well, This might not be useful in most of the cases) regarding File Creation, Padding and much more related Info while you are taking a Backup of your Database.

Do you really need this Info? IMHO, 95% of the cases, i would say NO. I consider this as Just an FYI kind of Information. When i try to troubleshoot Backup/Restore Issues, I rather enable Trace Flags 3004 and 3014 along with 3605(to enable logging of all the entries in our Error Log) instead of Just enabling Single Flag(Make sure you disable these Flags once you are done with diagnostics).

Let’s See what exactly get’s logged when i Enable these Trace Flags and Take a Full Database Backup.

Tadaaaaaaaaaa!
2011-09-15 22:00:40.470 spid54 BackupStream(0): Starting MSDA of size 384 extents
2011-09-15 22:00:40.470 spid54 Started file C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\DATA\3014_demo.mdf
2011-09-15 22:00:40.780 spid54 Completed file C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\DATA\3014_demo.mdf
2011-09-15 22:00:40.790 spid54 Padding MSDA with 327680 bytes
2011-09-15 22:00:40.790 spid54 BackupStream(0): Total MSDA: 384 extents
2011-09-15 22:00:40.860 Backup Database backed up. Database: 3014_demo, creation date(time): 2011/09/15(21:46:19), pages dumped: 3100, first LSN: 163:1808:37, last LSN: 163:1824:1, number of dump devices: 1, device information: (FILE=2, TYPE=DISK: {‘D:\Backs\3014_full.bak’}).

So..Basically you can see exact times while starting backup stream , how many Extents being affected, what file(s) etc…Again This is Just an FYI information in most of the cases while you are dealing with Backups, where as the Trace Flag 3004(see here) is Extremely Useful while investigating DB Restore Issues. YMMV!

Diagnosing Database Restores – Trace Flag 3004

Recently one of my fellow DBA had an issue with a Database Restore, where he was restoring a database using a full backup(from GUI) and the wizard was progressed upto 100% and it stayed there for more than 30 Minutes and he pinged me to see what’s going on!! Well, The actual issue was the database which he took the backup had 16000+ VLF’s!!(Very Very Bad sign of Log file sizing) and the log file size was close to 78 GB and there was a hugeeee open transaction(which SQL will Undo while restoring the Backup). Note he was creating a brand new database, So SQL will be creating brand new files and remember transaction log file will be Zero Initialized always as apposed to Data files(If Instant File Initialization is enabled on your Instance).

Our focus in this post is not regarding VLF’s and how Log file should be managed, but to identify what’s happening behind the scenes with your Database Restore and kind of identifying current Phase of restore process. For this you can make use of Undocumented trace flag 3004 along with 3605 to get the events logged in our Error Log. You can enable this trace flag either globally or at session level. (No need of touching your start up parameters for these trace flags) Please see the below Screenshot.

For demo purpose, Let’s restore a Full Backup of a database(it has an Open Transaction) and let’s see how our Error Log looks like with this trace flag being enabled.

I’ve restored the DB, see the Error Log in the below Screenshot.

Focus on these steps where you can note the actual time SQL Server took for Zeroing your Log File, Redo,Undo and all other required Information.

1.Zeroing C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\DATA\3005_Demo_1.ldf
from page 1 to 20584 (0x2000 to 0xa0d0000)
2.Restore: Waiting for log zero on 3005_Demo
3.Zeroing completed on
C:\Program Files\Microsoft SQL Server\MSSQL10_50.PROD\MSSQL\DATA\3005_Demo_1.ldf
4.Restore: LogZero complete
5.Starting up database ‘3005_Demo’.
6.The database ‘3005_Demo’ is marked RESTORING and is in a state that does not allow recovery to be run.
7.Starting up database ‘3005_Demo’.
8.Recovery is writing a checkpoint in database ‘3005_Demo’ (19).
9.Recovery completed for database 3005_Demo (database ID 19) in 9 second(s)
(analysis 20 ms, redo 1801 ms, undo 7690 ms.)
10.Restore is complete on database ‘3005_Demo’. The database is now available.
Database was restored: Database: 3005_Demo, creation date(time): 2011/08/23(23:16:47), first LSN: 38:19:1 blabla

Hope this is informative!

When was SQL Server Restarted??

As a DBA seldom we see cases where a User reports “Hey Mr DBA, my application went down for a minute or even few minutes, Now everything appears to be Okay. Can you pls take a look what happened?” Well, our very First place should be SQL Server Error Logs( My Personal favorite to start troubleshooting any issue) and let’s assume in this case that our Instance has been restarted and we see it in our Error Logs. So this is the traditional way to find out regarding SQL Server restarts – The SQL Server Error Logs.

Let’s jump into another scenario where you want to know when was the SQL Server restarted. It would be little annoying to cycle through all the error logs in SSMS if you are recycling your Logs on a daily basis and maintaining multiple Error Logs(PS we can have upto 99 Archives of Error Logs listed in our SSMS). So what would be our easiest bet to figure out when was the Instance restarted??

Method 1:

TempDB Creation date:

Since we all know Tempdb will be created each time you restart SQL Server, Tempdb creation date will give us the answer.

Alternate Methods:

1st Session(Session_id = 1) creation time and by starting SQL Server 2008, we can query DMV sys.dm_os_sys_info.

FYI Please see the below Screenshot

Note: Notice a slight difference in Milli seconds( could be seconds) in tempdb creation time and the time when SQL created it’s first session. But that’s Okay! Choose your Best method. I use tempdb creation date(since I’m used to it since SQL 2005). May be I’ve to start using DMV on new boxes!!

Hope this helps!

SQL Server Encryption – Part5 Encrypting Data(TDE) vs Encrypting Connections

This is the final part of Encryption series where i’m going to show how to encrypt connections in SQL Server. In the previous 4 parts of this series we’ve seen how to enable TDE for your Database, what EFS is and what Bitlocker is. If you recall correctly, all we discussed was how to encrypt our Database(Physical Files on the Disk), not securing Connections. In other words the data will be encrypted as long as it stays on the disk but not encrypted while SQL is sending data over to clients as you can see below!!

Note: TDE encrypts Data on Disk, Connections are not Encrypted using TDE.

So…..how to encrypt data across Wires(in other words how to Encrypt Connections)?

We have to use 128 Bit SSL(Secure Socket Layer) within SQL Server to encrypt Connections btw SQL Server and Client(s), which leads to slower performance but your SQL Server is Very Very Secured! Basically we’ve to Install a trusted certificate in our windows Certificate Store on our Physical Server where our SQL Server Instance is living on and we’ve to let SQL know that “Hey Mr.SQL Server! we’ve a certificate for you..make use of it for every connection”.

Step 1: Install Certificate(We can work with our Server/Network Team on this)

Step2: Go to your SQL Server Config Manager and enable Encryption as shown below.(I’ve 3 Instances on this Server, I’ll show you on PROD Instance)

Navigate to network Configuration, Right click on Network Protocols and select Properties as shown below.

Now, all your Certificates will be shown in the drop down menu under “Certificates” tab as shown below(I don’t have any on my Server)

Now, on Flags tab you can choose either Force Encryption to Yes or leave to default No as shown below.

If you Choose YES – Clients who are not encrypted are not allowed to connect.( In other words, any client which doesn’t allow encryption is declined to connect)

If you choose NO – Clients will be seeing encryption as optional.

Note: SSMS(Let’s assume it as a client application now for time being) knows how to encrypt connections. We can choose an Option to Encrypt my connection while connecting to the Database Engine as shown below.