Abstract
SQL Server's transaction log plays a critical role in replication and in the automatic roll-forward and rollback recovery process. This chapter explains how to use the operation codes to decipher a log and how to get detailed information about transactions in a log using DBCC.
INSERT AND DELETE STATEMENTS
When an Insert statement is sent to the server, it is identified with an op code of 4 in the transaction log. It is also the only statement that causes insert triggers to execute. Similarly, when a Delete statement is sent to the server, it gets an operation code of 5 in the transaction log and is the only statement that causes delete triggers to execute.
UPDATE STATEMENTS
Update statements are more difficult to analyze because of the different ways SQL Server interprets and handles them. The two primary types of Updates, direct and deferred, are explained in detail Chapter 16, “Performance Tuning.” We focus here on the log entries related to direct and deferred Updates.
When you analyze the performance of Update statements in your application, reviewing entries in transaction log is the only way to know whether you have succeeded in setting up a direct update-in-place. A direct update-in-place, the fastest type of update, gets an op code of 9. The first entry is op code 0, which is a Begin Transaction command. All data modifications get this code, regardless of whether you have actually specified the Begin Transaction statement yourself. The op code of 9 comes next, followed by a 30, which is an End Transaction. You always get an End Transaction, even if you specify a Commit Transaction or Rollback Transaction. Commit and Rollback do not have separate op codes.
A direct, same-page Update occurs when a record is deleted from a page and inserted onto that same page, usually because of increasing row length. Because the record does not move to a new page, none of the indexes needs to be updated, unless, of course, an indexed field is updated. This type of Update gets two records, an op code of 5 (Delete), followed by an op code of 6 (Indirect Insert).
A deferred update is the most expensive. A deferred Update is actually a Delete operation followed by an Insert, but everything is done twice. The operation is first performed as a no-op Delete and Insert (op codes 11 and 12), then as the actual Delete and Insert (op codes 5 and 6). The record is usually placed on another page, which means that the index entries are also deleted and inserted (op codes 7 and 8).
Table A.1 lists the op codes in the transaction logs.
DBCC LOG COMMAND
Run DBCC TRACEON (3604) then DBCC LOG to get a printout containing more information on each record in the log file. The following pages show an example of the output from the DBCC LOG command. Use the table above to help you decipher it.
LOG RECORDS:
BEGINXACT (791 , 2)
attcnt=1 rno=2 op=0 padlen=3 xactid=(791 , 2) len=64
status=0x0000
xendstat=XBEG_ENDXACT
masterid=(0 , 0) lastrec=(0 , 0) spid=3 suid=1
uid=1 masterdbid=0
mastersite=0 endstat=3
name=dmpxact time=Apr 21 1997 11:59PM
MODIFY (791 , 4)
attcnt=1 rno=4 op=9 padlen=2 xactid=(791 , 2) len=64
status=0x0000
tabid=2 pageno=24 offset=1163 status=0x0000
old ts=0x0001 0x00001ae2 new ts=0x0001 0x00001afd
ENDXACT (791 , 8)
attcnt=1 rno=8 op=30 padlen=0 xactid=(791 , 2) len=36
status=0x0000
xendstat=
endstat=COMMIT time=Apr 21 1997 11:59PM
BEGINXACT (791 , 9)
attcnt=1 rno=9 op=0 padlen=3 xactid=(791 , 9) len=64
status=0x0000
xendstat=XBEG_ENDXACT
masterid=(0 , 0) lastrec=(0 , 0) spid=3 suid=1
uid=1 masterdbid=0
mastersite=0 endstat=3
name=dmpxact time=Apr 22 1997 12:00AM
DEXTENT (791 , 11)
attcnt=1 rno=11 op=20 padlen=0 xactid=(791 , 9) len=60
status=0x0000
DEXTENT Extentid=776 endextid=0 count=1 bitmap=
0x0 0x0 0x0 0x0
EXTENT next=0, prev=0, objid=8, alloc=0xff,
dealloc=0x0,
indexid=0, status=0x0
CHGSYSINDPG (791 , 13)
attcnt=1 rno=13 op=39 padlen=0 xactid=(791 , 9) len=36
status=0x0000
FIRSTPAGE
tabid=8 indexid=0 oldvalue=776 newvalue=791
MODIFY (791 , 14)
attcnt=1 rno=14 op=9 padlen=2 xactid=(791 , 9) len=56
status=0x0000
tabid=8 pageno=791 offset=8 status=0x0000
old ts=0x0001 0x00001afb new ts=0x0001 0x00001afb
ENDXACT (791 , 19)
attcnt=1 rno=19 op=30 padlen=0 xactid=(791 , 9) len=36
status=0x0000
xendstat=
endstat=COMMIT time=Apr 22 1997 12:00AM
BEGINXACT (791 , 22)
attcnt=1 rno=22 op=0 padlen=3 xactid=(791 , 22) len=60
status=0x0000
xendstat=XBEG_ENDXACT
masterid=(0 , 0) lastrec=(0 , 0) spid=12 suid=1
uid=1 masterdbid=0
mastersite=0 endstat=3
name=ins time=Apr 25 1997 3:46PM
INSERT (791 , 23)
attcnt=1 rno=23 op=4 padlen=3 xactid=(791 , 22) len=84
status=0x0000
tabid=16003088 pageno=360 offset=927 status=0x0000
old ts=0x0001 0x00001afa new ts=0x0001 0x00001b08
IINSERT (791 , 24)
attcnt=1 rno=24 op=7 padlen=3 xactid=(791 , 22) len=64
status=0x0000
tabid=16003088 pageno=544 offset=327 status=0x0000
old ts=0x0001 0x00001a55 new ts=0x0001 0x00001b09
CHGSYSINDSTAT (791 , 25)
attcnt=1 rno=25 op=38 padlen=0 xactid=(791 , 22) len=52
status=0x0000
tabid=16003088 rows=1 used=0 dpages=0 reserved=0
uts_chg=0x0000000100000019 uts_undo=0xffffffffffffffff
ENDXACT (791 , 26)
attcnt=1 rno=26 op=30 padlen=0 xactid=(791 , 22) len=36
status=0x0000
xendstat=
endstat=COMMIT time=Apr 25 1997 3:46PM
BEGINXACT (791 , 30)
attcnt=1 rno=30 op=0 padlen=3 xactid=(791 , 30) len=60
status=0x0000
xendstat=XBEG_ENDXACT
masterid=(0 , 0) lastrec=(0 , 0) spid=12 suid=1
uid=1 masterdbid=0
mastersite=0 endstat=3
name=upd time=Apr 25 1997 3:52PM
DNOOP (791 , 31)
attcnt=1 rno=31 op=12 padlen=0 xactid=(791 , 30) len=24
status=0x0000
noopdel=(360 , 23)
INOOP (791 , 32)
attcnt=1 rno=32 op=11 padlen=3 xactid=(791 , 30) len=56
status=0x0000
IDELETE (791 , 33)
attcnt=1 rno=33 op=8 padlen=3 xactid=(791 , 30) len=64
status=0x0000
tabid=16003088 pageno=544 offset=327 status=0x0000
old ts=0x0001 0x00001b09 new ts=0x0001 0x00001b0d
DELETE (791 , 34)
attcnt=1 rno=34 op=5 padlen=3 xactid=(791 , 30) len=84
status=0x0000
tabid=16003088 pageno=360 offset=927 status=0x0000
old ts=0x0001 0x00001b0b new ts=0x0001 0x00001b0e
INSIND (790 , 0)
attcnt=1 rno=0 op=6 padlen=0 xactid=(791 , 30) len=52
status=0x0000
tabid=16003088 pageno=360 offset=927 status=0x0000
old ts=0x0001 0x00001b0e new ts=0x0001 0x00001b0f
ptr=(791 , 32)
IINSERT (790 , 1)
attcnt=1 rno=1 op=7 padlen=3 xactid=(791 , 30) len=64
status=0x0000
tabid=16003088 pageno=544 offset=327 status=0x0000
old ts=0x0001 0x00001b0d new ts=0x0001 0x00001b11
ENDXACT (790 , 2)
attcnt=1 rno=2 op=30 padlen=0 xactid=(791 , 30) len=36
status=0x0000 xendstat= endstat=COMMIT time=Apr 25
1997 3:52PM
CHECKPOINT (791 , 3)
attcnt=1 rno=3 op=17 padlen=0 xactid=(0 , 0) len=60
status=0x0000
rows=-44, pages=0 extents=8
timestamp=0x0001 0x00001afc active xacts:(776 , 15)
DBCC execution completed. If DBCC printed error messages,
see your System Administrator.
|