2017-03-19

Sybase log space exhausted, transactions frozen -what to do?

The main reason for the log file existence is logging all the user transactions incoming to the database. Every transaction needs to go through the transaction log. The main reason of troubles related to log is a full log condition. Indeed, if the log is full, we cannot execute any transaction and all the activity needs to be halted. The log should be big enough to accommodate all the transactions. Transaction can be stored longer or shorter depending on the settings of database

  • if the database has option 'truncate on checkpoint', whenever transaction has been finished, after a CHECKPOINT, when all the modified by this transaction pages have been saved in the database, the log entries are not longer required
  • if the option is not set, then first a backup of the log needs to be taken. After transaction has finished, and dbo has performed the backup of the log, the space in the log can be released.
Let's consider following example:


CREATE DATABASE Beta ON
BetaDataDev='10M'
LOG ON BetaLogDev='5M'
GO

USE Beta
GO

CREATE TABLE TestTran (ID INT IDENTITY PRIMARY KEY, SomeText NVARCHAR(1000))
GO

BEGIN TRAN
    WHILE(1=1)
    BEGIN
        DECLARE @info VARCHAR(100)
        INSERT TestTran VALUES(@info)
        SET @info = Convert(VARCHAR(100),GETDATE())
        PRINT  @info
    END

  • database Beta has been created, it has small data segment (10MB) and also small log (5MB) - we are asking for problems
  • In the database a new table has been created
  • Next a BIG transaction starts, there is no COMMIT or ROLLBACK statement here, just a never-ending WHILE adding rows into the table
After some seconds of execution something needs to fill up. In my case it was the log segment. In the error log following entry could be found (and it was repeated every minute):


00:0006:00000:00007:2017/03/19 12:49:44.92 server  1 task(s) are sleeping waiting for space to become available in the log segment for database Beta.
00:0006:00000:00007:2017/03/19 12:50:44.92 server  1 task(s) are sleeping waiting for space to become available in the log segment for database Beta.

That is the default behaviour, as by default databases don't have the option ABORT TRAN ON LOG FULL enabled. The default is FREEZE TRAN ON LOG FULL, what is the case here.

The space available in the log can be monitored by hand using following commands:

USE Beta
GO

EXEC sp_helpsegment logsegment
GO


Probably the last one table gives us the best information here. Free pages count is very low here! The same result would be returned when using:

EXEC sp_spaceused syslogs

or

dbcc checktable(syslogs)

What to do to unfreeze the transactions? For example more space could be added to the log like this:


USE master
GO

ALTER DATABASE Beta LOG ON BetaLogDev='3M'
GO

Remember that command like this ADDS given amount of disk space to the database's log. So taking look to our database, we have now 5+3=8 MB for the log. Immediately after adding more space, the transaction started again:

Mar 19 2017 12:06PM
1 row(s) affected
1 row(s) affected
Mar 19 2017 12:06PMSpace available in segment 'logsegment' has fallen critically low in database 'Beta'. All future modifications to this database will be suspended until the transaction log is successfully dumped and space becomes available.
The transaction log in database Beta is almost full. Your transaction is being suspended until space is made available in the log.
1 row(s) affected
1 row(s) affected
Mar 19 2017 6:40PM1 row(s) affected 



For example here the transaction was frozen at 12:06, but administrator has added more disk space to log around 6:40. At this moment the transaction was started again

Information like this can be also found in errorlog:

00:0006:00000:00007:2017/03/19 18:40:44.92 server  1 task(s) are sleeping waiting for space to become available in the log segment for database Beta.
00:0006:00000:00033:2017/03/19 18:41:43.31 server  Space available in segment 'logsegment' has fallen critically low in database 'Beta'. All future modifications to this database will be suspended until the transaction log is successfully dumped and space becomes available.
00:0006:00000:00036:2017/03/19 18:41:43.31 server  Error: 2812, Severity: 16, State: 5
00:0006:00000:00036:2017/03/19 18:41:43.31 server  Stored procedure 'sp_thresholdaction' not found. Specify owner.objectname or use sp_help to check whether the object exists (sp_help may produce lots of output).
00:0006:00000:00007:2017/03/19 18:41:44.92 server  1 task(s) are sleeping waiting for space to become available in the log segment for database Beta.

Transaction were suspended, then some more space has been added, but the space was shortly again exhausted and the transactions were frozen again.

The other solution could be stopping the transaction. As you see in this example the transaction will never stop! So killing it is the only solution!

First of all we need to determine who causes the log being filled up. There may be also different reasons for filling up the log:

  • A lot of small transactions were started, but one of them was not finished, so the log cannot be overwritten. Try to find the oldest transaction:
SELECT * FROM master..syslogshold



  • One heavy session has generated the biggest transaction, that consumed all the space in the log. Note the number of opened and committed/rolled back transactions. Generally those amounts should be equal. Here, the session 33 has opened one transaction that is not finished and this transaction has sent ~5MB of data:

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



  • To find the heavy session also following query can be used. It searches for records in syslogs table assigned to one session. (the idea is that column xactid is composed as session number concatenated with page number and row number in hex). Having it we can note which session has created the biggest amount of entries in syslogs. The last column is just a dbcc command that can be started to analyze the situation deeper and finally find the session spid:

SELECT TOP 5  

     xactid, 
     convert(int,substring(xactid,1,4)) as logpage,
     convert(smallint,substring(xactid,5,2)) as logrow,
     count(*) as records_in_xact,
    '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'
FROM 
     syslogs
GROUP BY 
     xactid
ORDER BY
     count(*) desc
GO




set switch on 3604 -- this returns results to the client

dbcc log( Beta,1, 2572, 10, 1, 0)


Execution time: 0.002 seconds

LOG SCAN DEFINITION:
Database id : 8
log records for session id (2572,10)
Log operation type BEGINXACT (0)
Forward scan: starting at beginning of log for 1 records
Maximum of 1 log records.

LOG RECORDS: (0 records did not qualify so far.)

BEGINXACT (2572,10) sessionid=2572,10
attcnt=1 rno=10 op=0 padlen=5 len=80
odc_stat=0x0000 (0x0000)
loh_status: 0x0 (0x00000000)
masterxsid=(invalid sessionid)
xstat=XBEG_ENDXACT,
spid=33 suid=1 uid=1 masterdbid=0 dtmcord=0
name=$user_transaction time=Mar 19 2017 12:06:45:850PM


Total number of log records 1 qualified out of 1 scanned.
DBCC execution completed. If DBCC printed error messages, contact a user with System Administrator (SA) role.
Execution time: 0.002 seconds



The query above displays all the transactions, however the resultset can be reduced to only currently running transactions:

SELECT TOP 5

      xactid,

     convert(int,substring(xactid,1,4)) as logpage,

     convert(smallint,substring(xactid,5,2)) as logrow,

      count(*) as records_in_xact,

      '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'

FROM      syslogs

GROUP BY  xactid, convert(int,substring(xactid,1,4)),convert(smallint,substring(xactid,5,2))

HAVING

xactid NOT IN ( SELECT xactid FROM  syslogs

    WHERE op = 17 --checkpoint is atomic, no commit

    OR op = 30    ---commit tran

)

ORDER BY count(*)

Resuming, when a session causing log being full has been found and when no other solution can be implemented, this session could be  killed:

kill 33

This causes the transaction to be rolled back but this may still not release the space in the log! What needs to be done is just starting a log backup. One of following commands can be used:

DUMP TRAN Beta to dumpsdev

or

DUMP TRAN Beta WITH TRUNCATE_ONLY

or

DUMP TRAN Beta WITH NO_LOG

BTW: For the first command to work a database dump must be created first! Database backup can be done issuing following command:

DUMP DATABASE Beta to dumpsdev

The next above two DUMP LOG commands cause just emptying the log. The difference between them is:

  • TRUNCATE_ONLY will try to release the inactive part of the log, but will need a small amount of free space in the log to write information about the log being truncated. If there is no space in the log it may fail
  • NO_LOG will also try to release the inactive portion of the log but will not record any information in log, so it has bigger chances to succeed

Anyway, always after using TRUNCATE_ONLY or after NO_LOG, the database should have a new normal backup started. Without it, you may finally not have a valid backups (backup files chain may be broken). Below result of command

EXEC sp_spaceused syslogs

just after a DUMP TRAN:



Well, at this moment the log contains again a lot of free pages and the transactions can be started in the database again

Some articles, forum discussions related to the topic:


Posted by at
Labels: ,

No comments:

Post a Comment

Subscribe to: Post Comments (Atom)

SAP Adaprive Server Enterprise

SAP Adaprive Server Enterprise
SAP Adaprive Server Enterprise