In Recovery...

Using fn_dblog, fn_dump_dblog, and restoring with STOPBEFOREMARK to an LSN

paul.nospam@nospam.sqlskills.com (paul) — Thu, 17 May 2012 03:05:00 -0700

I've blogged a bunch about using the undocumented fn_dblog function I helped write (and I've got a lot more to come :-) but here's one I haven't mentioned on my blog before: fn_dump_dblog (although I have talked about it at SQL Connections last year).

Here's a scenario: someone dropped a table and you want to find out when it happened and maybe who did it. The default trace has also wrapped so you can't get the DDL trace from there anymore.

If the transaction log for the DROP hasn't yet been cleared from the active portion of the log then you'd be able to use fn_dblog to search through the log for the information you need. You might even be able to look in the inactive portion of the log by using trace flag 2536, which instructs the log reader to ignore the log truncation point and dump all possible log records from the log.

But what do you do if the pertinent log records just don't exist in the log anymore? They're only in your log backups. You could tediously inch your way through restoring the log backups a few seconds at a time until you find the point at which the DROP took place, and then restore to just before that point so you can get the data back.

Or you could save a whole ton of time and use fn_dump_dblog which allows you to dump and search log records from a log backup file, without having to restore the database!

Finding a DROP in the log

Here's an example - I'm going to create a table, populate it, back it up, then drop it.

USE MASTER;
GO
IF DATABASEPROPERTYEX ('FNDBLogTest', 'Version') > 0 DROP DATABASE FNDBLogTest;
GO

CREATE DATABASE FNDBLogTest;
GO
USE FNDBLogTest;
GO
SET NOCOUNT ON;
GO

-- Create tables to play with
CREATE TABLE ProdTable (c1 INT IDENTITY, c2 DATETIME DEFAULT GETDATE (), c3 CHAR (25) DEFAULT 'a');
CREATE TABLE ProdTable2 (c1 INT IDENTITY, c2 DATETIME DEFAULT GETDATE (), c3 CHAR (25) DEFAULT 'a');
GO

INSERT INTO ProdTable DEFAULT VALUES;
GO 1000

-- Take initial backups
BACKUP DATABASE FNDBLogTest TO DISK = 'D:\SQLskills\FNDBLogTest_Full.bak' WITH INIT;
GO
BACKUP LOG FNDBLogTest TO DISK = 'D:\SQLskills\FNDBLogTest_Log1.bak' WITH INIT;
GO

INSERT INTO ProdTable2 DEFAULT VALUES;
GO 1000

Now I'll drop the table and add some more log records:

DROP TABLE ProdTable;
GO

INSERT INTO ProdTable2 DEFAULT VALUES;
GO 1000

Now how can we find the point at which the table was dropped?

SELECT
    [Current LSN],
    [Operation],
   [Context],
    [Transaction ID],
    [Description]
FROM fn_dblog (NULL, NULL),
    (SELECT [Transaction ID] AS tid FROM fn_dblog (NULL, NULL) WHERE [Transaction Name] LIKE '%DROPOBJ%') fd
WHERE [Transaction ID] = fd.tid;
GO

Current LSN            Operation       Context           Transaction ID Description
---------------------- --------------- ----------------- ------------- --------------------------------
0000009d:0000021e:0001 LOP_BEGIN_XACT LCX_NULL          0000:00001ff7 DROPOBJ; <snip>
0000009d:0000021e:0002 LOP_LOCK_XACT   LCX_NULL          0000:00001ff7
0000009d:0000021e:0003 LOP_LOCK_XACT   LCX_NULL          0000:00001ff7
0000009d:0000021e:0008 LOP_MODIFY_ROW LCX_IAM           0000:00001ff7
0000009d:0000021e:0009 LOP_MODIFY_ROW LCX_PFS           0000:00001ff7 Deallocated 0001:0000009b
0000009d:0000021e:000a LOP_MODIFY_ROW LCX_IAM           0000:00001ff7
0000009d:0000021e:000b LOP_MODIFY_ROW LCX_PFS           0000:00001ff7 Deallocated 0001:0000009c
0000009d:0000021e:000c LOP_MODIFY_ROW LCX_IAM           0000:00001ff7
0000009d:0000021e:000d LOP_MODIFY_ROW LCX_PFS           0000:00001ff7 Deallocated 0001:0000009d
0000009d:0000021e:000e LOP_MODIFY_ROW LCX_IAM           0000:00001ff7
0000009d:0000021e:000f LOP_MODIFY_ROW LCX_PFS           0000:00001ff7 Deallocated 0001:0000009e
0000009d:0000021e:0010 LOP_MODIFY_ROW LCX_IAM           0000:00001ff7
0000009d:0000021e:0011 LOP_MODIFY_ROW LCX_PFS           0000:00001ff7 Deallocated 0001:0000009f
0000009d:0000021e:0012 LOP_MODIFY_ROW LCX_PFS           0000:00001ff7 Deallocated 0001:0000009a
0000009d:0000021e:0013 LOP_HOBT_DDL    LCX_NULL          0000:00001ff7 Action 3 on HoBt 0xd:100 <snip>
0000009d:0000021e:0014 LOP_DELETE_ROWS LCX_MARK_AS_GHOST 0000:00001ff7
0000009d:0000021e:0032 LOP_LOCK_XACT   LCX_NULL          0000:00001ff7
<snip>

Cool eh?

Now we take another log backup, which clears the log, and contains the log we just looked at.

BACKUP LOG FNDBLogTest TO DISK = 'D:\SQLskills\FNDBLogTest_Log2.bak' WITH INIT;
GO

Restoring using STOPBEFOREMARK

The LSN for the LOP_BEGIN_XACT log record is where we need to restore to just before.

To do that we need to convert the LSN to the format necessary when using the STOPBEFOREMARK option for RESTORE. The option is documented but the format is not - how helpful!!

The LSN we have from the log dump above is 0000009d:0000021e:0001. To convert it:

Take the rightmost 4 characters (2-byte log record number) and convert to a 5-character decimal number, including leading zeroes, to get stringA
Take the middle number (4-byte log block number) and convert to a 10-character decimal number, including leading zeroes, to get stringB
Take the leftmost number (4-byte VLF sequence number) and convert to a decimal number, with no leading zeroes, to get stringC
The LSN string we need is stringC + stringB + stringA

So 0000009d:0000021e:0001 becomes '157' + '0000000542' + '00001' = '157000000054200001'.

The restore sequence to restore to just before the DROP is therefore:

RESTORE DATABASE FNDBLogTest2
    FROM DISK = 'D:\SQLskills\FNDBLogTest_Full.bak'
    WITH MOVE 'FNDBLogTest' TO 'C:\SQLskills\FNDBLogTest2.mdf',
    MOVE 'FNDBLogTest_log' TO 'C:\SQLskills\FNDBLogTest2_log.ldf',
    REPLACE, NORECOVERY;
GO

RESTORE LOG FNDBLogTest2
    FROM DISK = 'D:\SQLskills\FNDBLogTest_Log1.bak'
    WITH NORECOVERY;
GO

RESTORE LOG FNDBLogTest2
    FROM DISK = 'D:\SQLskills\FNDBLogTest_Log2.bak'
    WITH STOPBEFOREMARK = 'lsn:157000000054200001',
    NORECOVERY;
GO

RESTORE DATABASE FNDBLogTest2 WITH RECOVERY;
GO

And the table is there again, right before the point it was dropped. You can see where I used the constructed LSN string in the final log restore.

Using fn_dump_dblog

So what if the log records are no longer in the log? You can use the fn_dump_dblog function. For instance, here is how you use it to look in the FNDBLogTest_Log2.bak backup:

SELECT COUNT (*) FROM fn_dump_dblog (
    NULL, NULL, 'DISK', 1, 'D:\SQLskills\FNDBLogTest_Log2.bak',
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT);
GO

You have to specify all the DEFAULT parameters (63 of them!) or it won't work. The other parameters are:

Starting LSN (usually just NULL)
Ending LSN (again, usually just NULL)
Type of file (DISK or TAPE)
Backup number within the backup file (for multi-backup media sets)
File name

So you could do the same query as I did above:

SELECT
   [Current LSN],
   [Operation],
   [Context],
   [Transaction ID],
   [Description]
FROM fn_dump_dblog (
   NULL, NULL, 'DISK', 1, 'D:\SQLskills\FNDBLogTest_Log2.bak',
   DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
   DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
   DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
   DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
   DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
   DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
   DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
   DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
   DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT),
   (SELECT [Transaction ID] AS tid
   FROM fn_dump_dblog (
         NULL, NULL, 'DISK', 1, 'D:\SQLskills\FNDBLogTest_Log2.bak',
         DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
         DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
         DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
         DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
         DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
         DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
         DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
         DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
         DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT)
     WHERE [Transaction Name] LIKE '%DROPOBJ%') fd
WHERE [Transaction ID] = fd.tid;
GO

Which works perfectly, but takes much longer to run.

So maybe you're wondering what all the other parameters to fn_dump_dblog are for? They are for specifying the media families of a media set that has more than one media family.

Here's an example using a log backup striped across two files:

BACKUP LOG FNDBLogTest
    TO DISK = 'D:\SQLskills\FNDBLogTest_Log3_1.bak',
    DISK = 'D:\SQLskills\FNDBLogTest_Log3_2.bak'
    WITH INIT;
GO

If I try to use fn_dump_dblog and only specify a single file, I get an error:

SELECT COUNT (*) FROM fn_dump_dblog (
    NULL, NULL, 'DISK', 1, 'D:\SQLskills\FNDBLogTest_Log3_1.bak',
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT);
GO

Msg 3132, Level 16, State 1, Line 1
The media set has 2 media families but only 1 are provided. All members must be provided.

So I have to specify both media families:

SELECT COUNT (*) FROM fn_dump_dblog (
    NULL, NULL, 'DISK', 1, 'D:\SQLskills\FNDBLogTest_Log3_1.bak',
    'D:\SQLskills\FNDBLogTest_Log3_2.bak', DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
    DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT);
GO

Summary

So there you go - some more powerful tools to add to your disaster recovery arsenal.

Enjoy!

Understanding data vs log usage for spills in tempdb

paul.nospam@nospam.sqlskills.com (paul) — Fri, 11 May 2012 02:08:00 -0700

Earlier this morning I noticed a discussion on the SQL MCM distribution list (that all the original MCM instructors are part of) that was trying to make sense of a huge disparity between tempdb data file usage and log file usage. I explained the answer and thought I'd share it with you all too.

The situation was a tempdb where the data files grew from 30GB to 120GB, running out of space on the disk, but the tempdb log file did not grow at all from its initial size of 1GB! How could that be?

One of the things to consider about tempdb is that logging in tempdb is ultra-efficient. Log records for updates in tempdb, for instance, only log the before image of the data instead of logging both before and after images. There is no need to log the after image - as that is only used for the REDO portion of crash recovery. As tempdb never gets crash-recovered, REDO never occurs. The before image *is* necessary, however, because transactions can be rolled back in tempdb, just like other databases, and so the before image of an update must be available to be able to successfully roll back the update.

Getting to the question though, I can easily explain the observed behavior by considering how a sort spill happens with tempdb.

I can simulate this using a gnarly query on the SalesDB database you can download from our resources page (see the top of the page for the sample databases to download).

I'm going to do a join of my Sales and Products tables and then sort the multi-million row result set by product name:

SELECT S.*, P.* from Sales S
JOIN Products P ON P.ProductID = S.ProductID
ORDER BY P.Name;
GO

The query plan for this is (using Plan Explorer):

I know that the sort is going to spill out of memory into tempdb in this case. First I checkpoint tempdb (to clear out the log) and then after running the query, I can analyze the transaction log for tempdb.

Looking at the operation in the log:

SELECT
     [Current LSN],
     [Operation],
     [Context],
     [Transaction ID],
    [Log Record Length],
    [Description]
FROM fn_dblog (null, null);
GO

Current LSN            Operation       Context Transaction ID Len Description
---------------------- --------------- -------- -------------- --- ----------------------------------------------------------
000000c0:00000077:0001 LOP_BEGIN_XACT LCX_NULL 0000:00005e4d 120 sort_init;<snip>
000000c0:00000077:0002 LOP_BEGIN_XACT LCX_NULL 0000:00005e4e 132 FirstPage Alloc;<snip>
000000c0:00000077:0003 LOP_SET_BITS    LCX_GAM 0000:00005e4e 60 Allocated 1 extent(s) starting at page 0001:0000aa48
000000c0:00000077:0004 LOP_MODIFY_ROW LCX_PFS 0000:00005e4e 88 Allocated 0001:0000aa48;Allocated 0001:0000aa49;
000000c0:00000077:0005 LOP_MODIFY_ROW LCX_PFS 0000:00005e4d 80 Allocated 0001:00000123
000000c0:00000077:0006 LOP_FORMAT_PAGE LCX_IAM 0000:00005e4d 84
000000c0:00000077:0007 LOP_SET_BITS    LCX_IAM 0000:00005e4e 60
000000c0:00000077:0009 LOP_COMMIT_XACT LCX_NULL 0000:00005e4e 52
000000c0:00000077:000a LOP_BEGIN_XACT LCX_NULL 0000:00005e4f 128 soAllocExtents;<snip>
000000c0:00000077:000b LOP_SET_BITS    LCX_GAM 0000:00005e4f 60 Allocated 1 extent(s) starting at page 0001:0000aa50
000000c0:00000077:000c LOP_MODIFY_ROW LCX_PFS 0000:00005e4f 88 Allocated 0001:0000aa50;Allocated 0001:0000aa51;<snip>
000000c0:00000077:000d LOP_SET_BITS    LCX_IAM 0000:00005e4f 60
000000c0:00000077:000e LOP_SET_BITS    LCX_GAM 0000:00005e4f 60 Allocated 1 extent(s) starting at page 0001:0000aa58
000000c0:00000077:000f LOP_MODIFY_ROW LCX_PFS 0000:00005e4f 88 Allocated 0001:0000aa58;Allocated 0001:0000aa59;<snip>
000000c0:00000077:0010 LOP_SET_BITS    LCX_IAM 0000:00005e4f 60
000000c0:00000077:0011 LOP_SET_BITS    LCX_GAM 0000:00005e4f 60 Allocated 1 extent(s) starting at page 0001:0000aa60
000000c0:00000077:0012 LOP_MODIFY_ROW LCX_PFS 0000:00005e4f 88 Allocated 0001:0000aa60;Allocated 0001:0000aa61;<snip>
000000c0:00000077:0013 LOP_SET_BITS    LCX_IAM 0000:00005e4f 60
000000c0:00000077:0014 LOP_COMMIT_XACT LCX_NULL 0000:00005e4f 52
000000c0:00000077:0015 LOP_BEGIN_XACT LCX_NULL 0000:00005e50 128 soAllocExtents;<snip>
000000c0:00000077:0016 LOP_SET_BITS    LCX_GAM 0000:00005e50 60 Allocated 1 extent(s) starting at page 0001:0000aa68
000000c0:00000077:0017 LOP_MODIFY_ROW LCX_PFS 0000:00005e50 88 Allocated 0001:0000aa68;Allocated 0001:0000aa69;<snip>
000000c0:00000077:0018 LOP_SET_BITS    LCX_IAM 0000:00005e50 60
000000c0:00000077:0019 LOP_SET_BITS    LCX_GAM 0000:00005e50 60 Allocated 1 extent(s) starting at page 0001:0000aa70
000000c0:00000077:001a LOP_MODIFY_ROW LCX_PFS 0000:00005e50 88 Allocated 0001:0000aa70;Allocated 0001:0000aa71;<snip>
000000c0:00000077:001b LOP_SET_BITS    LCX_IAM 0000:00005e50 60
000000c0:00000077:001c LOP_SET_BITS    LCX_GAM 0000:00005e50 60 Allocated 1 extent(s) starting at page 0001:0000aa78
000000c0:00000077:001d LOP_MODIFY_ROW LCX_PFS 0000:00005e50 88 Allocated 0001:0000aa78;Allocated 0001:0000aa79;<snip>
000000c0:00000077:001e LOP_SET_BITS    LCX_IAM 0000:00005e50 60
000000c0:00000077:001f LOP_SET_BITS    LCX_GAM 0000:00005e50 60 Allocated 1 extent(s) starting at page 0001:0000aa80
000000c0:00000077:0020 LOP_MODIFY_ROW LCX_PFS 0000:00005e50 88 Allocated 0001:0000aa80;Allocated 0001:0000aa81;<snip>
000000c0:00000077:0021 LOP_SET_BITS    LCX_IAM 0000:00005e50 60
000000c0:00000077:0022 LOP_COMMIT_XACT LCX_NULL 0000:00005e50 52
000000c0:00000077:0023 LOP_BEGIN_XACT LCX_NULL 0000:00005e51 128 soAllocExtents;<snip>

<snip>

000000cd:00000088:01d3 LOP_SET_BITS    LCX_GAM 0000:000078fc 60 Deallocated 1 extent(s) starting at page 0001:00010e50
000000cd:00000088:01d4 LOP_COMMIT_XACT LCX_NULL 0000:000078fc 52
000000cd:00000088:01d5 LOP_BEGIN_XACT LCX_NULL 0000:000078fd 140 ExtentDeallocForSort;<snip>
000000cd:00000088:01d6 LOP_SET_BITS    LCX_IAM 0000:000078fd 60
000000cd:00000088:01d7 LOP_MODIFY_ROW LCX_PFS 0000:000078fd 88 Deallocated 0001:00010e68;Deallocated 0001:00010e69;<snip>
000000cd:00000088:01d8 LOP_SET_BITS    LCX_GAM 0000:000078fd 60 Deallocated 1 extent(s) starting at page 0001:00010e68
000000cd:00000088:01d9 LOP_COMMIT_XACT LCX_NULL 0000:000078fd 52
000000cd:00000088:01da LOP_MODIFY_ROW LCX_PFS 0000:00005fac 80 Deallocated 0001:00000109
000000cd:00000088:01db LOP_SET_BITS    LCX_SGAM 0000:00005fac 60 ClearBit 0001:00000108
000000cd:00000088:01dc LOP_SET_BITS    LCX_GAM 0000:00005fac 60 Deallocated 1 extent(s) starting at page 0001:00000108
000000cd:00000088:01dd LOP_COMMIT_XACT LCX_NULL 0000:00005fac 52

(I snipped out a few extraneous log records plus the 6 extra 'Allocated' and 'Deallocated' for each of the PFS row modifications.)

One of the things I notice is that the sort spill space is allocated in extents, and almost the entire sort - from initialization, through allocating all the extents, to deallocating them - is contained in a few very large transactions. But the transactions aren't actually that large.

Look at the soAllocExtents transaction with Transaction ID 00005e50. It's allocating 4 extents - i.e. 256KB - in a single system transction (4 x mark an extent as unavailable in the GAM, 4 x bulk set the 8 PFS bytes for the 8 pages in the extent, 4 x mark an extent allocated in the IAM). The total size of the log records for this transaction is 1012 bytes. (The first soAllocExtents system transaction only allocates 3 extents, all the others allocate 4 extents.)

When the sort ends, the extents are deallocated one-at-a-time in system transactions called ExtentDeallocForSort. An example is the transaction with Transaction ID 000078fd. It generates log records totalling 400 bytes. This means each 256KB takes 4 x 400 = 1600 bytes to deallocate.

Combining the allocation and deallocation operations, each 256KB of the sort that spills into tempdb generates 2612 bytes of log records.

Now let's consider the original behavior that I explained. If the 90GB was all sort space:

90GB is 90 x 1024 x 1024 = 94371840KB, which is 94371840 / 256 = 368640 x 256KB chunks.
Each 256KB chunk takes 2612 bytes to allocate and deallocate, so our 90GB would take 368640 x 2612 = 962887680 bytes of log, which is 962887680 / 1024 / 1024 = ~918MB of log.

And this would explain the observed behavior. 90GB of tempdb space can be allocated and used for a sort spill with roughly 918MB of transaction log, give or take a bit from my rough calculations.

Tempdb logs things very efficiently - especially things that spill out of memory. The next stop in debugging such a problem would be regularly capturing the output of sys.dm_db_task_space_usage to figure out who is using all the space and then digging in from there.

Hope this helps explain things!

Survey: most prevalent latch waits (code to run)

paul.nospam@nospam.sqlskills.com (paul) — Thu, 10 May 2012 02:26:00 -0700

I first started blogging about latches and some of the deeper parts of SQL Server internals last year (see Advanced performance troubleshooting: waits, latches, spinlocks) and now I'd like to pick up that thread (no scheduling pun intended :-)) and blog some more about some of the common latches that could be a performance bottleneck.

To that end, I've got some code below (plus example output) that will show the most common latch waits that have occurred on your system.

WITH Latches AS
    (SELECT
        latch_class,
        wait_time_ms / 1000.0 AS WaitS,
        waiting_requests_count AS WaitCount,
        100.0 * wait_time_ms / SUM (wait_time_ms) OVER() AS Percentage,
        ROW_NUMBER() OVER(ORDER BY wait_time_ms DESC) AS RowNum
    FROM sys.dm_os_latch_stats
    WHERE latch_class NOT IN (
        'BUFFER')
    AND wait_time_ms > 0
    )
SELECT
    W1.latch_class AS LatchClass,
    CAST (W1.WaitS AS DECIMAL(14, 2)) AS Wait_S,
    W1.WaitCount AS WaitCount,
    CAST (W1.Percentage AS DECIMAL(14, 2)) AS Percentage,
    CAST ((W1.WaitS / W1.WaitCount) AS DECIMAL (14, 4)) AS AvgWait_S
FROM Latches AS W1
INNER JOIN Latches AS W2
    ON W2.RowNum <= W1.RowNum
WHERE W1.WaitCount > 0
GROUP BY W1.RowNum, W1.latch_class, W1.WaitS, W1.WaitCount, W1.Percentage
HAVING SUM (W2.Percentage) - W1.Percentage < 95; -- percentage threshold
GO

LatchClass                        Wait_S WaitCount Percentage AvgWait_S
--------------------------------- ------- ---------- ----------- ----------
LOG_MANAGER                       221.43 4659       45.81       0.0475
ACCESS_METHODS_HOBT_VIRTUAL_ROOT 199.56 7017       41.28       0.0284
FGCB_ADD_REMOVE                   35.17   1047       7.27        0.0336
DBCC_OBJECT_METADATA              26.85   256490     5.55        0.0001

I'd like you to run the code and send me the output (either as a comment or in email). I'll collate all your output and do some blogging for your enjoyment.

Thanks!

Cool free tool to parse and analyze SQLIO results

paul.nospam@nospam.sqlskills.com (paul) — Wed, 02 May 2012 14:23:00 -0700

During every one of our Immersion Events, we designate Thursday evening as 'open mic' night where anyone can do a 15-minute presentation on anything they want (to do with SQL Server) to the class. We usually have 4 or 5 people who entertain us with interesting talks, and our recent classes in Chicago were no different.

One of the talks really impressed me. David Klee (b|t) demonstrated an automated analysis tool he's written for SQLIO result file parsing to save him time. He mentioned he was going to put it online and I encouraged him to do so as I could see the benefit to many people out there of not having to write their own analysis tools/spreadsheets.

You can get to David's free analysis site at http://tools.davidklee.net/sqlio.aspx. Clicking on the link at bottom right allows you to upload a SQLIO results text file. Once you've clicked ANALYZE, select the option to output the results to a spreadsheet and one will be automatically generated for you. If you look in the Analysis pane of the spreadsheet, you'll see something like below (using David's supplied example SQLIO output).

Very cool stuff - thanks David!

SQLskills community mentoring - round 2

paul.nospam@nospam.sqlskills.com (paul) — Wed, 02 May 2012 10:15:00 -0700

Back in November last year I blogged about Jonathan's idea to mentor someone who's attended one of our classes and how Jonathan, Joe, and I each picked someone to mentor for six months. Our mentees (Steven Ormrod, Luke Jian, and Brad Hoff, respectively) have all said how much they've benefited from the arrangement and we've really enjoyed helping them out.

Now it's time to announce the next three people who we'll be mentoring for the next six months, with brief bios I've put together based on their own words.

Joe is going to mentor Dan Taylor, who attended our IE1 and IE3 classes in Tampa earlier this year:

Daniel Taylor started his career over 17 years ago doing QA and mainframe PL-I programming, eventually landing a Junior DBA position at Nielsen Media Research Company working with Sybase ASE 11 thru 12.5 and Sybase IQ, eventually moving to SQL server. He is currently the SQL DBA Team Lead and a Database Staff Specialist at Publix Supermarkets and he's worked with SQL Server versions from 7.0 to 2008 R2.

Daniel has B.S. degrees in Psychology and Economics. In a past incarnation, he was even a Flight Attendant for T.W.A. ([Paul] which I heard was to settle a bet...)

When not at work Daniel likes to spend time with his friends and family. Daniel, Missy (Daniel's wife of almost 17 years), and their son Parker (5-1/2 year old) enjoy taking trips to the Smokies of North Carolina where they lose themselves "in the hills." One of Daniel's favorite quotes is "The Mountains are Calling and I must go" - John Muir.

He's on Twitter as @DBABullDog.

Jonathan is going to mentor Kenneth Urena, who attended our IE1, IE2, and IE3 classes in Tampa earlier this year:

Kenneth is from the "Los Santos" (The Saints) area of Costa Rica, where they produce the best coffee in the world ([Paul] It is really, really good...)

Kenneth started out as an 'accidental DBA' back in 1999 on SQL Server 7.0. Since then he has grown to become the Database Architect of a multi-national company. He's responsible for managing a DBA team who is responsible for the entire development cycle from design through production support of multiple applications on around 100 SQL Server instances from SQL Server 2005 through 2008 R2.

Kenneth holds multiple MCTS and MCITP certifications on SQL Server 2008 and is working towards his MCM certification.

He's on Twitter (very recently) as @sqlcr.

I'm going to mentor Orson Weston, who we've known for years starting at SQL Connections in 2007 and who has attended 3 of our classes, most recently IEBI in Chicago last month:

Orson was born and raised in southern California and currently works in San Diego for Continental Data Graphics, a Boeing Company, as a Corporate Service DBA. He has a Bachelor's degree in Computer Information Systems and has been working with SQL Server since 2001.

When Orson is not working with SQL Server, he enjoys traveling, sports, and spending time with family and friends, including his brand new addition - an amazing newborn!

He's on Twitter as @oweston12.

I'd like to congratulate these three guys and look forward to us helping them out over the next six months!

Spring cleaning health check special offer in May

paul.nospam@nospam.sqlskills.com (paul) — Tue, 01 May 2012 15:26:00 -0700

Spring takes a while to get going in the Pacific Northwest but spring is definitely in the air now that it's May - and spring means spring cleaning!

It's been about 18 months since we last ran a special pricing offer so I've decided to offer one through the month of May for new customers: a 6-hour SQL Server health check for US$1300 (a 1/3 price saving).

The US$1300 special offer is for a 6-hour health check of a single SQL Server instance (SQL Server 2005 or higher) and you can be anywhere in the world.

For a typical SQL Server Health Check we ask you to download a customized SQLDiag package to run from an FTP site we provide to you. The scripts gather information on more than 100 areas such as:

Wait statistics
IO statistics
Memory configuration
Buffer pool usage
Server configuration
Databases configuration
Backup information
Information from the query plan cache

We also provide you with a questionnaire which asks about your maintenance practices and I/O subsystem configuration.

The collection utility, SQLDiag, ships with SQL Server and is a tool that Microsoft Product Support uses to run data-collecting scripts. Our scripts should take only a few minutes to run and will output several text files to a SQLDiagOutput directory where you unzipped the package to. You can see what data we're collecting as everything is output as plain text. We then ask you to upload the completed questionnaire and output files to the same FTP site. Once we have the data we will review all of the information and generate the report for your environment. For regular health checks we can also add in data gathering questionnaires/SQLDiag packages regarding virtualization, clustering, your HA/DR strategy, and indexing configuration if desired, but the special offer doesn't cover time for those.

The majority of clients on our Past Clients page have gone through this process with one or more servers - so we have plenty of references available, including US government if required.

Typically we like to start out performance tuning engagements with an initial health check of the environment, which provides a comprehensive review of the configuration of the server to isolate any problems that exist in the environment. This has proven to provide most clients with the best return on their investment time-wise since we methodically review over 100 different items that are important for SQL Server performance and availability. Based on the outcome of the health check, we provide you with a detailed report of the problem areas that includes supporting links to blog posts and articles that we and others have written that provide details about how you can fix the problems. Alternatively, we can also assist you with remediation of the identified problems on a WebEx session - most customers do the latter or opt for our Remote DBA service to provide ongoing support.

All you have to do is send me an email before June to qualify for the special rate and we can get started.

We look forward to hearing from you, and to helping your SQL Servers get healthy!

Visiting Scotland (part 3)

paul.nospam@nospam.sqlskills.com (paul) — Tue, 01 May 2012 12:19:00 -0700

This is part three of my three-part series of posts about what I recommend on a visit to Scotland. I'm writing posts because I get asked a lot and this is easier than repeating myself a bunch of times.

You can get part 1 of the series here - dealing with Glasgow, Edinburgh, and Stirling, and general links to agencies and our past photo posts - and part 2 of the series here - dealing with the Isle of Skye.

Part 3: Road trips

There are a lot of cool places to see in Scotland but I don't have time to write a travel book or extensive posts about all of them (except the two previous ones). In this post I'm going to list some of my favorite driving routes that allow you to see a bunch of cool scenery and/or places along with a few pointers to specific items. I recommend getting the Ordinance Survey Landranger series of maps that cover the routes you're going to drive as they list all kinds of interesting historical things to see. For all of these I also recommend doing more research of the routes and places to stop, depending on what you like to do. Many of the places listed here have whisky distilleries nearby or clan centers. I've put in wikipedia links (if existing) the first time a place is mentioned.

Glasgow to Crianlarich. This goes along the A82 road that skirts the side of Loch Lomond, one of the most picturesque, and the largest, bodies of water in the UK. For the adventurous, take a detour along the other side of the loch to Rowardennan and climb Ben Lomond. Luss is a pretty village to stop at - many times I've jumped off its pier into the loch. Make sure to stop at the hydro plant alongside the A82 (you can't miss it - four giant pipes climbing the mountainside to the reservoir at the top). Crianlarich is a railway junction where the Callendar & Oban and West Highland railways converged. The next stop, Tyndrum, has two stations - one for the Oban line and one for the Fort William line.
Arrochar to Oban via Inverary. This is one of my most favorite drives in all of Scotland. Get to Arrochar on the A814 - either coming through Helensburgh (which is my home town in Scotland) and Garelochhead on the A814 past the giant submarine base as Faslane (the reason we moved to Helensburgh in 1977) or crossing over from Tarbet on the A82 using the A83. If you go through Helensburgh, stop at the Hill House, designed by Charles Rennie Mackintosh. The A83 skirts the head of the imaginatively-named Loch Long and then heads up the old military road to the pass called the Rest and Be Thankful. Stop and look down the hill at what you've just come up, and marvel at the old road which rises precipitously below you. Continue down to Loch Fyne and stop in at the Loch Fyne Oyster Bar - a wonderful place to eat seafood. Continue along the road to Inverary. As you go over the bridge at the traffic lights outside the town, look to the right to see the impressive Inverary Castle, seat of the Duke of Argyll. Inverary is good to stop and walk around - lots of things to do. Continue down the A83 through excellent scenery to Lochgilphead. From here you can take a long detour down to Campbeltown on the Mull of Kintyre, from which you'll be able to see Northern Ireland on a good day. You can also go a little north and go left on the B841 to explore the old churches, 700-year old grave stones and crosses at Kilmory and Kielmore, with excellent views to the Paps of Jura. You can walk down to the cool ruins of Castle Sween. Crinan is also worth stopping at - the start of the Crinan Canal. Continue up the A816 to one of my top five places in the world, Kilmartin. There's an excellent visitor center here, along with 5000-year old stone circles, standing stones, and Neolithic burial chambers. Continue north to Oban, stopping every so often to see if you can see any sea eagles, particularly at the large marina, Craobh Haven. Oban is a cool place with lots to do - I recommend walking down the pier and getting some fresh seafood.
Oban to Crianlarich. The A85 from Oban passes through some cool little villages, with Connel Ferry being the first. There's no ferry any longer since the bridge was built. Loch Etive drains into the sea here and the tidal rush can be extreme, especially when sea kayaking or in a boat. Taynuilt is worth stopping at for the old Bonawe Iron Furnace. Stop at the Cruachan power station and also take a detour to see a replica crannog in Loch Awe. From there it's downhill to Tyndrum, unless you take a detour along the B8074 through Glen Orchy up to Bridge of Orchy on the A82. I once saw a pair of huge Golden Eagles in the road there.
Oban to Fort William via Ballachulish. At Connel Ferry, turn left on the A828 towards Ballachulish. A great little road - make sure to check out Barcaldine Castle and the Scottish Sea Life Sanctuary - I took a school trip there by train from Helensburgh when I was 9. At Portnacroish you'll see Castle Stalker, which is the castle at the end of the movie Monty Python and The Holy Grail. There's also a great little luxury hotel with excellent food at Port Appin. From there you'll drive up the side of Loch Linnhe, eventually joining the A82 at Ballachulish and heading up the nondescript road to Fort William. There isn't a huge amount to do in Fort William - it's more a place to rest and stay overnight if you're skiing, climbing, walking or touring.
Crianlarich to Fort William through Glen Coe. After Tyndrum you'll climb up into the mountains. When you reach the top of the hill, you'll see the railway line and a trail on your right, which both go to Fort William. The trail is the famous West Highland Way, which starts just outside Glasgow - I've never done it, but my younger brother did a few years back. Continue to look on your right to see the horseshoe curve the railway line makes as it traverses three mountains. After passing through Bridge of Orchy, the road heads downhill to Loch Tulla. Here you'll go through a distinctive bridge, which marks the south end of Rannoch Moor. The other bridge is at the entrance to Glen Coe. You'll climb a steep hill and then you're on Rannoch Moor proper. Make sure to stop along the way and get some reflection photos in one of the little bodies of water by the road. After cross the moor, you'll see a giant mountain right in front of you - this is Buachaille Etive Mòr (colloquially known simply as The Buachialle pronounced 'The Boo-kal'). A cool detour goes down Glen Etive, where I must have spent 20-odd nights over the years camped beside the river while hill walking. Glen Coe is steeped in history, most notably the Massacre of Glencoe in 1692. It's also got some of the most amazing scenery in Scotland - I think it's best seen in overcast weather, when the mountains look like they're brooding. There are numerous cool walks to take, from strolls to hard-core roped-up mountaineering - this is one of the most popular walking and climbing destinations in Scotland. Make sure to stop at the visitor center in Glencoe Village. From there you follow the road around to Ballachulish and up to Fort William.
Train to Fort William. Optionally, take the train from Glasgow to Fort William - a stunning ride through desolate countryside. It rides up high along the side of Loch Lomond too and goes through my home town of Helensburgh.
Ardnamurchan Peninsula. This is a great place to go camping, especially by the side of Loch Sunart. It's pretty remote but has some wonderful beaches and plenty of camping space. You get there from the A830 almost at Mallaig or by taking the Corarn Ferry just south of Fort William (I've done both). Drive down to the ferry to the Isle of Mull, cross over to Tobermory (a very picturesque little town) and then head down to Fhionnphort and take the ferry to the isle of Iona to see the ancient Iona Abbey (which I've yet to do). You can also get to Tobermory by ferry from Oban (which is what I've done in the past).
Fort William to Inverness. This drive takes you along the Great Glen. Stop at Fort Augustus to see all the river locks. You can also rent a barge or boat and motor/sail between the town and the city. Check out the very cool remains of Urquhart Castle on the banks of Loch Ness and see if you can see the monster :-) There's a visitor center in nearby Drumnadrochit that has a giant Loch Ness Monster that your kids will like. Inverness has a lot of cool things to see but I've never stayed overnight there as I much prefer being out on the West Coast.
Perth to Inverness. This follows the A9 road. Be careful when driving it as it's a notorious accident blackspot. Places to visit include Dunkeld, The Hermitage, Pitlochry, Blair Castle in Blair Atholl, Aviemore, the Cairngorms, and all the whisky distilleries around the River Spey (collectively known as the Speyside Malts). I can recommend the Hilton Coylumbridge where they also have lodges for rent. Also checkout the Culloden Battefield and visitor center - the site of the decisive battle that ended the 1745 Jacobite Rebellion.
Fort William to Kyle of Lochalsh. Follow the A82 to the junction with the A87, maybe driving up to the Aonach Mòr ski center just north of Fort William. On the A87, make sure to stop at the viewpoint overlooking Loch Garry, which from there looks like a map of Scotland. Loch Cluanie is very interesting depending on the height of the water. You can get down to the foot of the Cluanie dam and there's an overlook too. At the far end of the loch, stop at the Cluanie Inn for some soup and a beer. You then drive down through picturesque Glen Shiel to Shiel Bridge. Here you can take a detour over the Man Ratagan to Glenelg (where there's an excellent broch to see) and get on to Skye through the ferry there. Continuing along the A87 you'll pass the world famous (from the movie Highlander) Eilean Donan castle - well worth a visit - before arriving in Kyle of Lochalsh.
Skye. See my second post in the series.
Kyle of Lochalsh to Torridon. This is another of my favorite drives in all of Scotland. It takes you through Lochcarron (maybe take a detour to Plockton on the way) and over the (in)famous Bealach-na-Ba road to Applecross, one of my top five favorite places on the planet. You can read all about that trip in my photo post from 2009. After driving north, with stunning views across to Skye and Raasay, you'll come to Loch Torridon with stunning views of the Torridon mountains, eventually joining the A832. For a short trip, turn right towards the A890 and then right again towards Kyle of Lochalsh. For the more adventurous, turn left and head around the Gairloch pensinsula. Lots of excellent views and deserted beaches. When you get to Gruinard, look out at the island. It's where the British government tested anthrax during WWII. It's safe now, apparently... Also check out the excellent Inverewe Garden. When you reach the A835, turn right to head south towards the A832 junction to make a loop back to Kyle of Lochalsh.
Ullapool to Durness. From Inverness or Kyle of Lochalsh, you'll eventually end up on the A835 if you want to go north west of Ullapool. Make sure to stop at Corrieshalloch Gorge. Ullapool is also the main ferry port for the Outer Hebrides islands. From Ullapool, drive north on the A835 and turn left when you hit the A837. Follow this north and then west to Lochinver. From Lochinver, take the B869 road around the peninsula and make sure to stop at Achmelvich. It's a great place to camp and has a stunning beach - check out the little ranger hut too. The road is single-track, very twisty, and very steep in places - definitely for the adventurous. Whichever way you go, you'll end up on the A894. At Kylesku you'll go over the only bridge over the Atlantic and here was the one time I had to stop driving in the middle of the road because the rain was coming down so hard I literally couldn't see, even with the wipers on full. Make sure you have a hat :-) Continue north through stunning scenery until you get to Durness. There's nothing much at Kinlochbervie so I don't recommend taking that side trip.
Durness to John o' Groats. If you can, spend the day at Durness - the most sparsely populated area in Western Europe. There are utterly stunning beaches just a little east of the village and also just to the west of where the road enters the village. You absolutely must see the fabulous Smoo Cave just to the west of the village, where a 60 foot waterfall goes under the road and into a chamber you can access. If you can, go visit the lighthouse at Cape Wrath. This is driving along the Pentland Firth - one of the roughest bodies of water around the UK and partially what persuaded me not to follow my Father's footsteps in the Royal Navy. You'll go past Loch Eriboll where the German U-boats surrendered in WWII after the Battle of the Atlantic, Tongue (where you can cut south to Inverness), and Thurso - the main ferry port for Orkney and the nearest town to the Dounreay nuclear reactor where my Father was stationed for a small time. Take a detour to Dunnet Head (the most northerly point of the British mainland - check out the lighthouse and sea stacks) before heading to John o' Groats (often mistakenly referred to as the most northerly point).

There's easily several week's worth of things to do here and the driving can be done in small chunks as the country isn't really big. You can get from Glasgow or Edinburgh to Kyle of Lochalsh in about 6 hours on a good day.

There are many, many more places to see - I didn't even touch on areas south of Glasgow and Edinburgh, The Trossachs, or in eastern Scotland - but I ran out of time - the series took me about 6 hours altogether.

I hope you've enjoyed my series of blog posts and they prove useful to some of you!

New script: When were the sp_configure options last changed?

paul.nospam@nospam.sqlskills.com (paul) — Thu, 26 Apr 2012 11:30:00 -0700

In my previous post I explained how the sp_configure settings are stored in a special page in the master database called the CONFIG block. Sometimes you might want to know when these were last changed if error logs are not available for some reason (as sp_configure changes are noted in the error log) or someone tried to cover his/her tracks by editing them. You can figure this out by dumping the CONFIG block directly using DBCC PAGE or DBCC CONFIG.

Here's the CONFIG block for one of the instances on my laptop:

DBCC TRACEON (3604);
DBCC CONFIG;
GO

CONFIG:

DS_CONFIG @0x00000000043A3060

cconfsz = 8                          cmajor = 9                           cminor = 0
crevision = 76                       cbootsource = 2                      crecinterval = 0
ccatalogupdates = 0                  cmbSrvMemMin = 16                    cmbSrvMemMax = 2147483647
cusrconnections = 0                  cnetworkpcksize = 4096               ckbIndexMem = 0
cfillfactor = 0                      ctapreten = 0                        cwritestatus = 0
cfgpriorityboost = 0x0               cfgexposeadvparm = 0x1               cfglogintime = 20
cfgpss = 0                           cfgpad = 4096                        cfgxdes = 16
cfgaffinitymask = 0                  cfgaffinitymask64 = 0                cfgIOAffinityMask = 0
cfgIOAffinity64Mask = 0              cfgbuf = 4362                        cfgdes = 0
cfglocks = 0                         cfgquerytime = 600                   cfgcursorthrsh = -1
cfgrmttimeout = 10                   cfg_dtc_rpcs = 0                     cclkrate = 31250
cfg_max_text_repl_size = 65536       cfgupddate = 41023                   cfgupdtime = 14252889
fRemoteAccess = 1                    cfgbufminfree = 331                  cnestedtriggers = 0x1
cdeflang = 0                         cfgTransformNoiseWords = 0x0         cfgPrecomputeRank = 0x0
crossdbownchain = 0                  cidCfg = 0x3400d008                  cidCfgOld = 0x3400d008
cfgCutoffYear = 2049                 cfgLangNeutralFT = 1033              maxworkthreads = 0
minworkthreads = 32                  minnetworkthreads = 32               threadtimeout = 15
connectsperthread = 0                cusroptions = 0                      exchcostthreshold = 5
maxdop = 1                           cpwdpolicyupgrade = 0x1              cfServerTriggerRecursion = 1
cfDisableResultsetsFromTriggers = 0 cfgPHConnectTimeout = 60             CLREnabled = 0
cfgmaxcrawlrange = 4                 ftSmallBufMin = 0                    ftSmallBufMax = 100
ftLargeBufMin = 0                    ftLargeBufMax = 100                  RemoteDacEnabled = 0
CommCritComplianceEnabled = 0        EkmEnabled = 0                       cUserInstanceTimeout = 0x3c
cfgEnableUserInstances = 0x1         m_BackupCompressionDefault = 0x0     FilestreamAccessLevel = 2
OptimizeForAdhocWorkloads = 0        cchecksum = 1191
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

The two highlighted fields are the time the sp_configure options were last updated. The cfgupddate is the day that sp_configure was last updated and the cfgupdtime is the time on that day is was last updated. Here's how to interpret them:

cfgupdtime is the number of 3.3ms intervals since midnight. 14252889 x 3.3ms = 47034533.7ms = 47034s. 47036 div 3600 (secs/hour) = 13 hours. And (47036 mod 3600) div 60 (mins/hour) = 3 mins. And (47036 mod 3600) - (3 x 60) = 56 secs. I last updated my sp_configure settings at 13:03:56 when I tested it by setting MAXDOP to 1.
cfgupddate is more complex. It's the number of days since January 1st, 1900. Doing a raw 41023 / 365 = 112.391blah. So 112 years, leaving 41023 - (112 * 365) = 143 days over. but we also have to account for the extra day in all the leap years since 1900. 1900 itself isn't a leap year, but 2000 is, plus 24 between 1900 and 2000, and 2 since 2000, not including this year. So we have 143 - 1 - 24 - 2 = 116 days. 116 - 31 (Jan) - 29 (Feb) - 31 (Mar) = 25. But it's the number of days *since* January 1st, 1900 so we add 1 and we get 26 - and today's the 26th of April.

I last changed the sp_configure options at 13:03:56 on April 26, 2012. Its trivial to come up with T-SQL code to do all of this, using the WITH TABLERESULTS option of DBCC PAGE.

Note the time of the last sp_configure change is only flushed to the CONFIG blocck on disk when the server restarts, is recollated, or some other major change occurs. This means that if you make a change, the time returned by the code will not change. You can prove this to your self by making a change, waiting an hour, rebooting, and running the script. The time returned will be the change time, not the reboot time.

[Edit 4/30/12: I fixed a small arithmetic bug in my milliseconds calculation thanks to Nils Gustav Stråbø.]

You can download the code from SQLskillsSPConfigureChanged.zip (1.50 kb)

If you want to figue out *what* changed and you don't have error logs available, you'll have to restore previous backups of master (you're backing it up every night, right?) and compare the CONFIG blocks.

Hope this is useful (or at least interesting!) to some of you. Better go set MAXDOP back to zero before I forget...

The code to do this is below (I'm sure someone will comment on a cleverer way to do some of this):

/*============================================================================
   File: SQLskillsSPConfigureChanged.sql

   Summary: This script reports the time that sp_configure options were
   last changed

   SQL Server Versions:
         2005 RTM onwards
------------------------------------------------------------------------------
Written by Paul S. Randal, SQLskills.com

(c) 2011, SQLskills.com. All rights reserved.

For more scripts and sample code, check out
    http://www.SQLskills.com

You may alter this code for your own *non-commercial* purposes. You may
republish altered code as long as you include this copyright and give due
credit, but you must obtain prior permission before blogging this code.

THIS CODE AND INFORMATION ARE PROVIDED "AS IS" WITHOUT WARRANTY OF
ANY KIND, EITHER EXPRESSED OR IMPLIED, INCLUDING BUT NOT LIMITED
TO THE IMPLIED WARRANTIES OF MERCHANTABILITY AND/OR FITNESS FOR A
PARTICULAR PURPOSE.
============================================================================*/

SET NOCOUNT ON;

-- Create the temp table
--
IF EXISTS (SELECT * FROM msdb.sys.objects WHERE NAME = 'SQLskillsDBCCPage')
DROP TABLE msdb.dbo.SQLskillsDBCCPage;

CREATE TABLE msdb.dbo.SQLskillsDBCCPage (
    [ParentObject] VARCHAR (100),
    [Object]       VARCHAR (100),
    [Field]        VARCHAR (100),
    [VALUE]        VARCHAR (100));

DECLARE @hours   INT;
DECLARE @minutes  INT;
DECLARE @seconds  INT;
DECLARE @milliseconds BIGINT;
DECLARE @LastUpdateTime DATETIME;
DECLARE @upddate  INT;
DECLARE @updtime  BIGINT;
DECLARE @dbccPageString VARCHAR (200);

-- Build the dynamic SQL
--
SELECT @dbccPageString = 'DBCC PAGE (master, 1, 10, 3) WITH TABLERESULTS, NO_INFOMSGS';

-- Empty out the temp table and insert into it again
--
INSERT INTO msdb.dbo.SQLskillsDBCCPage EXEC (@dbccPageString);

SELECT @updtime = [VALUE] FROM msdb.dbo.SQLskillsDBCCPage
WHERE [Field] = 'cfgupdtime';
SELECT @upddate = [VALUE] FROM msdb.dbo.SQLskillsDBCCPage
WHERE [Field] = 'cfgupddate';

-- Convert updtime to seconds
SELECT @milliseconds = CONVERT (INT, CONVERT (FLOAT, @updtime) * (3 + 1.0/3))
SELECT @updtime = @milliseconds / 1000;

-- Pull out hours, minutes, seconds, milliseconds
SELECT @hours = @updtime / 3600;

SELECT @minutes = (@updtime % 3600) / 60;

SELECT @seconds = @updtime - (@hours * 3600) - (@minutes * 60);

-- Calculate number of milliseconds
SELECT @milliseconds = @milliseconds -
@seconds * 1000 -
@minutes * 60 * 1000 -
@hours * 3600 * 1000;

-- No messy conversion code required for the date as SQL Server can do it for us
SELECT @LastUpdateTime = DATEADD (DAY, @upddate, '1900-01-01');

-- And add in the hours, minutes, seconds, and milliseconds
-- There are nicer functions to do this but they don't work in 2005/2008
SELECT @LastUpdateTime = DATEADD (HOUR, @hours, @LastUpdateTime);
SELECT @LastUpdateTime = DATEADD (MINUTE, @minutes, @LastUpdateTime);
SELECT @LastUpdateTime = DATEADD (SECOND, @seconds, @LastUpdateTime);
SELECT @LastUpdateTime = DATEADD (MILLISECOND, @milliseconds, @LastUpdateTime);

SELECT @LastUpdateTime AS 'sp_configure options last updated';

-- Clean up
--
DROP TABLE msdb.dbo.SQLskillsDBCCPage;
GO

Where are sp_configure settings stored? Another reason to backup master...

paul.nospam@nospam.sqlskills.com (paul) — Thu, 26 Apr 2012 10:15:00 -0700

Earlier today I blogged on our SQL Server Pro magazine blog about false-alarm corruptions you will *definitely* see if you restore a backup of the master database as a user database and run DBCC CHECKDB on the restored copy. You might be doing this as part of offloading consistency checks to another server or validating your backups restore correctly and contain an undamaged database. You'll definitely get a shock the first time you see these false-alarms and think your real master is corrupt!

One of the 'corruptions' is because of a special page that only exists in the master database - the CONFIG block of the SQL Server instance. It's page number 10 in data file ID 1 of master. DBCC CHECKDB flags this as a corruption if it's present in any other database apart from master, as the page in master is marked as allocated, but no object owns it. This is only allowed in master. Similar allowances are made by DBCC CHECKDB in every database for the boot page (page 9 in file 1) and for each data and log file's file header page (page 0 in each file). See here for a blog post about the boot page and here for a blog post about file header pages.

What does this special page store? It stores all the sp_configure options for the SQL Server instance. This is yet one more reason to make sure you regularly back up the master database because if you lose master then you lose all your configuration settings for that SQL Server instance.

You can examine this page using DBCC PAGE or the equally undocumented, but nowhere nearly as well known, DBCC CONFIG command (they use the same code under the covers and both require trace flag 3604).

Here's an example from one of my laptop instances:

DBCC TRACEON (3604);
DBCC PAGE ('master', 1, 10, 3);
GO

PAGE: (1:10)

BUFFER:

BUF @0x0000000080FC0AC0

bpage = 0x0000000080572000           bhash = 0x0000000000000000           bpageno = (1:10)
bdbid = 1                            breferences = 0                      bcputicks = 264
bsampleCount = 1                     bUse1 = 23062                        bstat = 0xc00009
blog = 0x32159                       bnext = 0x0000000000000000

PAGE HEADER:

Page @0x0000000080572000

m_pageId = (1:10)                    m_headerVersion = 1                  m_type = 14
m_typeFlagBits = 0x0                 m_level = 0                          m_flagBits = 0x200
m_objId (AllocUnitId.idObj) = 99     m_indexId (AllocUnitId.idInd) = 0    Metadata: AllocUnitId = 6488064
Metadata: PartitionId = 0            Metadata: IndexId = 0                Metadata: ObjectId = 99
m_prevPage = (0:0)                   m_nextPage = (0:0)                   pminlen = 0
m_slotCnt = 1                        m_freeCnt = 0                        m_freeData = 8190
m_reservedCnt = 0                    m_lsn = (0:0:1)                      m_xactReserved = 0
m_xdesId = (0:0)                     m_ghostRecCnt = 0                    m_tornBits = -1051583237

Allocation Status

GAM (1:2) = ALLOCATED                SGAM (1:3) = NOT ALLOCATED
PFS (1:1) = 0x64 MIXED_EXT ALLOCATED 100_PCT_FULL                         DIFF (1:6) = CHANGED
ML (1:7) = NOT MIN_LOGGED

Slot 0, Offset 0x60, Length 9, DumpStyle BYTE

Record Type = PRIMARY_RECORD         Record Attributes =                  Record Size = 9

Memory Dump @0x000000001580C060

0000000000000000:   00000800 e2040000 09†††††††††††††††††....â...

DS_CONFIG @0x000000001580C060

cconfsz = 8                          cmajor = 9                           cminor = 0
crevision = 75                       cbootsource = 2                      crecinterval = 0
ccatalogupdates = 0                  cmbSrvMemMin = 0                     cmbSrvMemMax = 2147483647
cusrconnections = 0                  cnetworkpcksize = 4096               ckbIndexMem = 0
cfillfactor = 0                      ctapreten = 0                        cwritestatus = 0
cfgpriorityboost = 0x0               cfgexposeadvparm = 0x0               cfglogintime = 20
cfgpss = 0                           cfgpad = 4096                        cfgxdes = 16
cfgaffinitymask = 0                  cfgaffinitymask64 = 0                cfgIOAffinityMask = 0
cfgIOAffinity64Mask = 0              cfgbuf = 4362                        cfgdes = 0
cfglocks = 0                         cfgquerytime = 600                   cfgcursorthrsh = -1
cfgrmttimeout = 10                   cfg_dtc_rpcs = 0                     cclkrate = 31250
cfg_max_text_repl_size = 65536       cfgupddate = 41023                   cfgupdtime = 14252889
fRemoteAccess = 1                    cfgbufminfree = 331                  cnestedtriggers = 0x1
cdeflang = 0                         cfgTransformNoiseWords = 0x0         cfgPrecomputeRank = 0x0
crossdbownchain = 0                  cidCfg = 0x3400d008                  cidCfgOld = 0x3400d008
cfgCutoffYear = 2049                 cfgLangNeutralFT = 1033              maxworkthreads = 0
minworkthreads = 32                  minnetworkthreads = 32               threadtimeout = 15
connectsperthread = 0                cusroptions = 0                      exchcostthreshold = 5
maxdop = 0                           cpwdpolicyupgrade = 0x1              cfServerTriggerRecursion = 1
cfDisableResultsetsFromTriggers = 0 cfgPHConnectTimeout = 60             CLREnabled = 0
cfgmaxcrawlrange = 4                 ftSmallBufMin = 0                    ftSmallBufMax = 100
ftLargeBufMin = 0                    ftLargeBufMax = 100                  RemoteDacEnabled = 0
CommCritComplianceEnabled = 0        EkmEnabled = 0                       cUserInstanceTimeout = 0x3c
cfgEnableUserInstances = 0x1         m_BackupCompressionDefault = 0x0     FilestreamAccessLevel = 2
OptimizeForAdhocWorkloads = 0        cchecksum = 1250

DBCC execution completed. If DBCC printed error messages, contact your system administrator.

You can see that the CONFIG block is stored in a special way as the record length DBCC PAGE reports is only 9 bytes, whereas the CONFIG block is several hundred bytes. When SQL Server starts, it opens a channel directly to master's MDF and reads the entire 8Kb of page 10 into memory and typecasts it into the in-memory CONFIG data structure. If the CONFIG block is damaged, the server won't start.

As you can see from the output, not everything in the CONFIG block is exposed or settable via sp_configure.

In the next post, I'll explain how to tell when sp_configure options were last updated.

Make sure you're backing up the master database!

Photos from the Mojave Desert

paul.nospam@nospam.sqlskills.com (paul) — Fri, 20 Apr 2012 07:18:00 -0700

(Sitting in the back of the class while Kimberly's teaching and I'm cranking through my massive backlog of blog posts.)

Inside a lave tube with light streaming through ceiling holes and through the dust.

After SQL Connections at the start of April in Las Vegas we drove across to San Diego for a friend's birthday party. We decided to bring all our camera gear along and drive through the Mojave National Preserve, renting a 4x4 so we could go off into the dirt roads where necessary.

It's a pretty cool place - vast, of course - and one of the few times I've stood and had tens of miles of flat ground around me in all directions with nothing except scrub bushes and a small road, and deep, deep blue sky overhead.

There's a good PDF map of the Preserve on the National Park Service website here and I recommend perusing their site before going.

We entered the Preserve just off I-15 west of Vegas at a place call Nipton and headed down to the information center at Hole-In-The-Wall. This was a 20 mile drive on a dirt road, great fun in the 4x4 with wheel ruts throwing the SUV around (I love driving off-road, and fast if possible :-). Lots of bird life around and some ground squirrels too. At Hole-In-The-Wall (named after the more famous bandit hide-out in Wyoming) there are cool rock formations and rock-climbing routes. We drove back up to the main road and headed along to Kelso Depot, which used to be a major locomotive depot for the Union Pacific Railroad during WWII. It provided extra locomotives for the ore trains heading east - now it's a really small town, but has a great little restaurant in the information center. Try the chili - it's excellent. We then headed back north to I-15 through the Cinder Cone Lava Beds - lots of giant lava flows and cinder cones from volcanic vents. Turning off onto a tiny road (Aiken Mine Road) we headed out into the lava to find a lava tube that you can get down into and explore - this was fabulous and the highlight of the day for sure. It's marked on the map I linked to above.

After the party, the next day we drove down to San Diego airport and stopped at the flying park north of the city. This is a flying club and launch area set on high sea cliffs over the Pacific with excellent thermals for hang-gliding and parascending. At one point I counted over 30 flyers in the air. If we'd had more time we'd have signed up for some tandem flights.

All in all a great road trip, albeit a little short. We're going to make a point of driving to more places in future - flying makes you miss so much!

All photos were taken with a Canon 5D Mark II with a 24-105mm f/4L lens shooting fully manual. It took me a while to figure out, but once you have the shutter speed/focal-length/'film' speed triangle worked out in your head, you'll never go back from fully manual control of your camera.

Click on the photos for a 1024x768 version. Full-size versions available on request.

Below: Preserve entrance sign with scrub to the horizon and then mountains; abandoned cabin in a small homestead in the hamlet of Cima.

Below: Kimberly in front of the rocks at Hole-In-The-Wall; a cactus about to flower - we were just a bit too early for the flowering to be in full swing.

Below: the main cavern inside the lave tube. The light was just incredible, with powerful sun rays coming through the dust inside the cavern. It kind of reminded me of the scene in Raiders of the Lost Ark where Indy goes down into a chamber in the Egyptian city and a ray of light comes through a skylight, through a gem he's holding and lights up a location on a map of the city. The second photo is of a smaller skylight with a really intense beam of light. Just stunning.

Below: the blocked-up entrance to an old mineshaft - maybe part of the old abandoned Aiken Mine?

Below: flyers over the Pacific just north of San Diego. The second photo has 8 flyers in!