Tuesday, July 2, 2013

trace flag for backup and restore operation

1. 3004
show the internal backup/restore operation for every step.
ex.
dbcc traceon(3004,3605,-1)
GO

3605 means output the message to errorlog. you can use 3604 to direct the output to client, but it doesn't have the time info which 3605 has. The output looks like below:
LogDate                                 ProcessInfo Text
2013-07-02 16:48:52.280 spid53 RestoreDatabase: Database AdventureWorks
2013-07-02 16:48:52.280 spid53 Opening backup set
2013-07-02 16:48:52.310 spid53 SetTargetRestoreAge: 0
2013-07-02 16:48:52.310 spid53 Restore: Configuration section loaded
2013-07-02 16:48:52.310 spid53 Restore: Backup set is open
2013-07-02 16:48:52.310 spid53 Restore: Planning begins
2013-07-02 16:48:52.320 spid53 Restore: Planning complete
2013-07-02 16:48:52.320 spid53 Restore: BeginRestore (offline) on AdventureWorks
2013-07-02 16:48:52.320 spid53 Restore: Attached database AdventureWorks as DBID=15
2013-07-02 16:48:52.320 spid53 Restore: PreparingContainers
2013-07-02 16:48:52.340 spid53 Zeroing C:\Program Files\Microsoft SQL Server\MSSQL11.SQL2012\MSSQL\DATA\AdventureWorks2012_log.ldf from page 1 to 64000 (0x2000 to 0x1f400000)
2013-07-02 16:48:52.350 spid53 Restore: Containers are ready
2013-07-02 16:48:52.400 spid53 Restore: Restoring backup set
2013-07-02 16:48:52.400 spid53 Restore: Transferring data to AdventureWorks
2013-07-02 16:49:01.640 spid53 Restore: Waiting for log zero on AdventureWorks
2013-07-02 16:49:11.160 spid53 Zeroing completed on C:\Program Files\Microsoft SQL Server\MSSQL11.SQL2012\MSSQL\DATA\AdventureWorks2012_log.ldf
2013-07-02 16:49:11.210 spid53 Restore: LogZero complete
2013-07-02 16:49:11.210 spid53 SetTargetRestoreAge: 0
2013-07-02 16:49:11.320 spid53 FileHandleCache: 0 files opened. CacheSize: 12
2013-07-02 16:49:11.320 spid53 Restore: Data transfer complete on AdventureWorks
2013-07-02 16:49:11.330 spid53 Restore: Backup set restored
2013-07-02 16:49:11.410 spid53 Starting up database 'AdventureWorks'.
2013-07-02 16:49:11.410 spid53 The database 'AdventureWorks' is marked RESTORING and is in a state that does not allow recovery to be run.
2013-07-02 16:49:11.420 spid53 Restore-Redo begins on database AdventureWorks
2013-07-02 16:49:13.390 spid53 RunOfflineRedo logIter.Init(): FirstLsn(PruId: 0): 0x82:0x155:0x45
2013-07-02 16:49:13.390 spid53 RunOfflineRedo logIter.Init(): LastLsn(PruId: 0): 0x82:0x173:0x1
2013-07-02 16:49:13.400 spid53 OfflineRollforward: StopLsn/LastLsn(PruId: 0): 0x82:0x173:0x1
2013-07-02 16:49:13.410 spid53 Rollforward complete on database AdventureWorks
2013-07-02 16:49:13.420 spid53 Restore: Done with fixups
2013-07-02 16:49:13.420 spid53 Restore: Transitioning database to ONLINE
2013-07-02 16:49:13.430 spid53 Restore: Restarting database for ONLINE
2013-07-02 16:49:13.530 spid53 Starting up database 'AdventureWorks'.
2013-07-02 16:49:13.970 spid53 FixupLogTail(progress) zeroing C:\Program Files\Microsoft SQL Server\MSSQL11.SQL2012\MSSQL\DATA\AdventureWorks2012_log.ldf from 0x23ee600 to 0x23f0000.
2013-07-02 16:49:13.970 spid53 Zeroing C:\Program Files\Microsoft SQL Server\MSSQL11.SQL2012\MSSQL\DATA\AdventureWorks2012_log.ldf from page 4600 to 4688 (0x23f0000 to 0x24a0000)
2013-07-02 16:49:13.980 spid53 Zeroing completed on C:\Program Files\Microsoft SQL Server\MSSQL11.SQL2012\MSSQL\DATA\AdventureWorks2012_log.ldf
2013-07-02 16:49:14.080 spid53 PostRestoreContainerFixups: fixups complete
2013-07-02 16:49:14.130 spid53 PostRestoreReplicationFixup for AdventureWorks starts
2013-07-02 16:49:14.810 spid53 PostRestoreReplicationFixup for AdventureWorks complete
2013-07-02 16:49:14.870 spid53 Restore: Database is restarted
2013-07-02 16:49:14.870 Backup Restore is complete on database 'AdventureWorks'.  The database is now available.
2013-07-02 16:49:14.880 spid53 Resuming any halted fulltext crawls
2013-07-02 16:49:15.060 spid53 Restore: Writing history records
2013-07-02 16:49:15.060 Backup Database was restored: Database: AdventureWorks, creation date(time): 2013/07/02(16:33:47), first LSN: 130:341:69, last LSN: 130:371:1, number of dump devices: 1, device information: (FILE=1, TYPE=DISK: {'c:\temp\AdventureWorks.bak'}). Informational message. No user action required.
2013-07-02 16:49:15.060 spid53 Writing backup history records
2013-07-02 16:49:15.080 spid53 Restore: Done with MSDB maintenance
2013-07-02 16:49:15.080 spid53 RestoreDatabase: Finished

The error log shows the it took 9 seconds to restore data and 19 seconds to zero log file. since I have enabled "Instant file initialization", there is zeroing file step for .mdf file. with trace flag 3004 you can see on which step it takes longest time.


2. 3213
show the buffer and maxtransfersize info.
ex.
dbcc traceon(3213,3605,-1)
GO

in errorlog
2013-07-02 17:24:52.070 spid56 Backup/Restore buffer configuration parameters
2013-07-02 17:24:52.070 spid56 Memory limit: 1009MB
2013-07-02 17:24:52.070 spid56 BufferCount:                6
2013-07-02 17:24:52.070 spid56 Sets Of Buffers:            2
2013-07-02 17:24:52.070 spid56 MaxTransferSize:            1024 KB
2013-07-02 17:24:52.070 spid56 Min MaxTransferSize:        64 KB
2013-07-02 17:24:52.070 spid56 Total buffer space:         12 MB
2013-07-02 17:24:52.070 spid56 Tabular data device count:  1
2013-07-02 17:24:52.070 spid56 Fulltext data device count: 0
2013-07-02 17:24:52.070 spid56 Filestream device count:    0
2013-07-02 17:24:52.070 spid56 TXF device count:           0
2013-07-02 17:24:52.070 spid56 Filesystem i/o alignment:   512
2013-07-02 17:24:52.070 spid56 Media Buffer count:            6
2013-07-02 17:24:52.070 spid56 Media Buffer size:          1024KB
2013-07-02 17:24:52.070 spid56 Encode Buffer count:           6
2013-07-02 17:25:00.880 spid56 Starting up database 'sqlnexus'.
2013-07-02 17:25:00.910 spid56 The database 'sqlnexus' is marked RESTORING and is in a state that does not allow recovery to be run.

here we see 6 buffercount, maxtransfersize is 1024.(for buffercount calculation, please refer to http://blogs.msdn.com/b/sqlserverfaq/archive/2010/05/06/incorrect-buffercount-data-transfer-option-can-lead-to-oom-condition.aspx). before you optimize the buffercount and maxtransfersize parameter of backup and restore command, using trace flag 3213 to check the current default value.

3. other trace flag
    a) 3023
        If Trace Flag 3023 is turned on, the CHECKSUM option is automatically enabled for the BACKUP command. You can turn on Trace Flag 3023 to make sure that all backups use the backup CHECKSUM option. If you do this, you do not have to rewrite all the existing backup scripts
       http://support.microsoft.com/kb/2656988

    b) 3226
        No log backup info written into SQL errorlog file

    c) 3001
        No log backup info saved in msdb tables.

    d) 1806
         Turn off "Instant file initialization". maybe only useful when testing.

    e) 3014 and 3216
        log more detail info , ex.
dbcc traceon(3213,3004,3216,3605,-1)
GO

1 comment: