Skip to Content

FAQ:  My transaction log filled, which process is responsible for filling up the log?

A: There are several different possible interpretations of “process which filled up the log” – you can have the oldest open transaction preventing the log from being truncated, even if that transaction itself has generated few log records or is just the replication LTM marker, or you can have a process that has generating a lot of activity in one big transaction, or you can have a process that has generated a lot of small transactions.  There is also the spid that used up the very last of the available space and hit the first 1105 error.

Generally, after the log is truncated a time or two, the first two cases merge – the open big transaction will also be the oldest open transaction. By itself, a session generating a large number of small transactions shouldn’t cause the log to completely fill as long as some process is being used to truncate the log, though it would lead to large transaction log dump files.

Determining log usage by spid depends on exactly what you want to measure (number of records, sum of the size of all records, etc.) Note that space can be used both directly (actual size of the log record) and indirectly.  For example, on a 2k page size server, a transaction inserting a batch of 1100 byte rows will use a 2K log page for each inserted row as only one insert record that size will fit on each row.

Some possible approaches to answering the question:

1) Oldest open transaction

This is the transaction that is preventing the log from being truncated.  It may not have used much log space directly, but as everything behind it in the log cannot be deallocated, it can be said to be responsible for using up all that space (or at least the space up to the next oldest open transaction).

SELECT * FROM master..syslogshold

2) monProcessActivity summary

From within ASE, you can get a rough feel for how many bytes a SPID has written to the log from monProcessActivity.  (ULC = User Log Cache, the spid accumulates log records in the ULC and flushes them to syslogs in batches).

SELECT TOP 5
     SPID,
     ULCBytesWritten,
     Transactions,
     Commits,
     Rollbacks
FROM
     master..monProcessActivity
ORDER BY ULCBytesWritten DESC

However, not all logged activity registers in ULCBytesWritten, and the number of transactions, commits, and rollbacks tells you little about the size of the individual transactions or which database they occurred in.  The values are also for the life of the spid and so include activities that may have been truncated from the log a long time ago.  So this is most useful if you only have one main database in use on the server, and clients that don’t stay connected for long.

3) Transaction with the most records

You may actually be more interested in simply identifying who is running the largest transactions in syslogs and what those transactions are. This is a considerably easier problem.

The syslogs table only exposes two columns to the user, even though each log record actually contains much more. xactid is the session id with the two fields (page (int),row (smallint)), in hex, concatenated. The session id identifies the syslogs page and row containing the BEGINXACT log record for the transaction and appears in all the log records for that transaction.  The following query identifies the transactions with the largest number of log records:

SELECT TOP 5 — ‘5’ is arbitrary, just used to limit output
     xactid,
     convert(int,substring(xactid,1,4)) as “logpage”,
     convert(smallint,substring(xactid,5,2)) as “logrow”,
     count(*) as “records_in_xact”
FROM
     syslogs
GROUP BY
     xactid
ORDER BY
     count(*) desc

  xactid         logpage     logrow records_in_xact
————– ———– —— —————
0x00001962000b        6498     11            9951
0x000019410010        6465     16              38
0x000019440009        6468      9              37
0x0000195d0002        6493      2              34
0x000019610003        6497      3              28

(5 rows affected)

A slight variation on the query gives you just the transactions that are currently still open:

SELECT TOP 5
      xactid,
      count(*) as “records_in_xact”
FROM      syslogs
GROUP BY  xactid
HAVING
xactid NOT IN ( SELECT xactid FROM  syslogs
    WHERE op = 17 /*checkpoint is atomic, no commit*/
    OR op = 30 /*commit tran */ 
)
ORDER BY count(*)

You can now plug the session id (page,row) values into dbcc log to get the BEGINXACT log record for the transaction which will give you the uid of the user, the spid, the transaction name and when it started.

dbcc log(dbid, 1, <session page>, <session row>, 1,0)

LOG SCAN DEFINITION:
Database id : 2
Forward scan: starting at beginning of log
Log records for session id 935,21,0
Log operation type BEGINXACT (0)
maximum of 1 log records.

LOG RECORDS:
BEGINXACT (935,21) sessionid=935,21,0
attcnt=1 rno=21 op=0 padlen=1 sessionid=935,21,0 len=76
odc_stat=0x0000 (0x0000)
loh_status: 0x0 (0x00000000)
masterxsid=(invalid sessionid)
xstat=XBEG_ENDXACT,
spid=19 suid=1 uid=1 masterdbid=0 dtmcord=0
name=$user_transaction time=Nov 16 2010 10:42:19:910AM

Total number of log records 1
DBCC execution completed. If DBCC printed error messages, contact a user
with
System Administrator (SA) role.

Note:  You can easily generate the DBCC command by adding the following as a column in the select list:

“dbcc log( “
  + db_name()
  + “,1, “
  + str(convert(int,xactid),10,0)
  + “, “
  + str(convert(smallint, substring(xactid,5,2)),10,0)
  + “, 1, 0)” as “dbcc command”

4) DBCC LOG

DBCC LOG can provide far more information, but is a less convenient brute force method.

Given a spid <spid>, you can get the beginxact log records (and thus the session ids) for every transaction that spid has started.

set switch on 3604  — sends dbcc output to client
go
dbcc log(<dbid>, -<spid>, -3,0)
go

You can get the BEGINXACT log records for all spids with

dbcc log(<dbid>, 0, 0,0, <records>,0)

Passing a positive number for <records> will give you the that many of the oldest BEGINXACTS; passing a negative number will give you the most recent records.

For each of those session ids, you can dump all the log records for that session with

dbcc log(<dbid>, 1, <session page>, <session row>)

Save that output to a file and use grep/awk/perl to extract the value for the “len” field of each record and sum those up. The result will be the total amount of log space on disk directly used by the log records for that spid.  It does not account for any share of the unused space on log pages holding these records.

To report this post you need to login first.

5 Comments

You must be Logged on to comment or reply to a post.

  1. Javier Ernesto Barthe

    Hi Bret, very good post!!!

    About monProcessActivity the log consumed by the currently active task using the spid (connection) you may calculate with previous mda captures, calculating the delta between captures. I listen about this mda captures in a jeff podcast and it was really helpfull specially when you have pools of concurrent connections that are never released

    Regards.

    (0) 
  2. Cory Sane

    Bret,

    Thank you for posting this information in the SCN pages for public consumption.  Based on sections 3 & 4 in your article, I was able to isolate a problem.  I had a process that was holding the log open with a small number of changes, while a few other processes were jumping in and out creating large changes.  Independently, neither set of processes were the problem, but the combination of processes running concurrently was an opportunity for improvement.

    I appreciate your technical knowledge and willingness to share.

    Cory

    (0) 
  3. Cory Sane

    Bret,

    Are there any documentation pages for dbcc log?

    Are there any hidden gems to the loginfo function relating to showing information about spids or statement ids that have already completed but still behind the transaction holding the log?

    Cory

    (0) 

Leave a Reply