13

In SQL Server 2008 R2, how are these two rollbacks different:

  1. Run an ALTER statement, for a few minutes, and then hit 'Cancel Executing'. It takes a few minutes to rollback completely.

  2. Run the same ALTER statement, but this make sure that the LDF file is not big enough for it to complete successfully. Once the LDF limit is met and no 'autogrowth' is allowed, query execution stops immediately (or a rollback happens) with this error message:

The statement has been terminated.
Msg 9002, Level 17, State 4, Line 1
The transaction log for database 'SampleDB' is full. 
To find out why space in the log cannot be reused, see the 
log_reuse_wait_desc column in sys.databases

How are these two different on the following points?

  1. Why is the second 'rollback' instantaneous? I'm not entirely sure if it could be called a rollback. My guess is, the transaction log is written as the execution progresses and once it realizes that there is not enough space to fully complete the task, it just stops with some 'end' message, without commit.

  2. What happens when the first rollback takes so much time (is a rollback single threaded)?
    2.1. Does SQL Server go back and undo the entries made in the LDF file?
    2.2. The LDF file size gets smaller at the end of the rollback (from DBCC SQLPERF(LOGSPACE))

  3. One additional question: During the second scenario, SQL Server starts consuming LDF file pretty quickly. In my case, it increased from 18% usage to 90% usage in the first few minutes (< 4 mins). But once it reached 99%, it stayed there for another 8 mins, while fluctuating usage between 99.1% to 99.8%. It goes up (99.8%) and down (99.2%) and up again (99.7%) and down (99.5%) a few times before the error is thrown. What is happening behind the scenes?

Any MSDN links that could help explain this more are appreciated.

At Ali Razeghi suggestion, I'm adding perfmon : Disk Bytes/sec

Scenario 1:

Scenario 1

Scenario 2:

Scenario 2

  • Just a quick comment: file size != space used within a file. – Aaron Bertrand Aug 10 '15 at 20:40
  • @Aaron Yes, I'm familiar with that. I used DBCC SQLPERF(LOGSPACE) to measure the usage. The LDF file stayed the same during the whole duration, as I limited the file size to 10 GB. The internal usage varies. – ToC Aug 10 '15 at 20:46
  • 1
    I suspect that the second rollback appears instantaneous, because the error is reported after the rollback completes. These are probably the 8 minutes that you observe in 3., where the LDF usage remains pretty constant. – mustaccio Aug 10 '15 at 20:49
  • @mustaccio I would agree with you but the artifacts are pointing in different direction. If in fact, the rollback happened, then the log file usage must be back to a smaller number; and not stay at 99.3% when the error message is thrown. – ToC Aug 10 '15 at 20:57
  • 1
    I believe rollback takes log space. When the log becomes full during rollback the DB becomes suspect. It is not touched any further. This looks like instantaneous rollback but rollback has been deferred until you are able to take the database back online (when there is disk space available).; Also, when the log becomes full SQL Server might try to make room by checkpointing which might explain spikes in IO activity. – usr Aug 11 '15 at 23:22
1

As indicated above, after running more tests, I arrived at an calculated conclusions. I summarized all of them into a blog post here, but I'll copy some content over to this post for posterity.

Conjecture (based on some tests)

As of now, I do not have a clear explanation as to why this is. But following are my estimations based on the artifacts gathered during the tests.

Rollback happens in both scenarios. One is explicit rollback (user hitting Cancel button), the other is implicit (Sql Server making that decision internally).

In both scenarios, the traffic going to the log file is consistent. See the images below:

Scenario 1:

Scenario 1:

Scenario 2:

Scenario 2

  • One artifact that reinforced this line of thinking is capturing Sql Trace during both the scenarios.

    • Scenario 1 is self evident a.k.a. when we hit ‘Cancel’, it rolls back.
    • In Scenario 2, the error message is displayed after performing ‘rollback’ implicitly. In Sql Trace, we see the error message “The transaction log for database ‘SampleDB’ is full” a long time before the message is displayed on the screen. So, my guess is that rollbacks happens in both scenarios, but the error message is Scenario 2 is displayed after successfully and completely performing the rollback.
  • Scenario 2 seems to take longer as as it progresses much further along, so the rollback takes longer.

Unexplained behavior:

  • Why does the log file usage vary so much?
    • It increases to 90%, then down to 85%, then up to 99% and hovers there for a long time. I see it going up and down like this several times: 99.2 %, 99.8 %, 99.1 %, 99.7 %. Why does this happen?
    • One possible explanation is that, there might be a background process (something like Log Flush) that cleans up log file every few minutes. And everytime it kicks in, some entries are cleared up, resulting in more free space available.

Any ideas to help explain this behavior in a better way are welcome.

  • 2
    Checked with Paul Randal, he confirmed that you came to the correct conclusion - rollback is the same in both cases. – Paul White Aug 14 '15 at 17:03
0

I tried the following experiment and got similar results. In both cases, fn_dblog() shows rollback occurring and it seems to happen quicker in Scenario 2 than in Scenario 1.

By the way, I placed both the MDF and LDF on the same single external (USB 2.0) disk.

My initial conclusion is that there is no difference in the operation of rollback in this case, and probably any apparent speed difference is I/O subsystem related. That is just my working hypothesis at the moment.

Scenario 1:

  • Create a database with a log file that begins at 1MB, grows in 4MB chunks, and has a max size of 100MB.
  • Open an explicit transaction, run it for 10 seconds, and then manually cancel it within SSMS
  • Look at fn_dblog() count and log reserve size and check out DBCC SQLPERF(LOGSPACE)

Scenario 2:

  • Create a database with a log file that begins at 1MB, grows in 4MB chunks, and has a max size of 100MB.
  • Open an explicit transaction, run it until the log is full error shows up
  • Look at fn_dblog() count and log reserve size and check out DBCC SQLPERF(LOGSPACE)

Performance Monitor Results:

Scenario 1: ***Scenario 1***

Scenario 2: ***Scenario 2***

Code:

USE [master];
GO

IF DATABASEPROPERTYEX (N'SampleDB', N'Version') > 0
BEGIN
    ALTER DATABASE [SampleDB] SET SINGLE_USER
        WITH ROLLBACK IMMEDIATE;
    DROP DATABASE [SampleDB];
END;
GO

CREATE DATABASE [SampleDB] ON PRIMARY 
( 
      NAME = N'SampleDB'
    , FILENAME = N'E:\data\SampleDB.mdf' 
    , SIZE = 3MB 
    , FILEGROWTH = 1MB 
)
LOG ON 
( 
      NAME = N'SampleDB_log'
    , FILENAME = N'E:\data\SampleDB_log.ldf'
    , SIZE = 1MB 
    , MAXSIZE = 100MB 
    , FILEGROWTH = 4MB 
);
GO

USE [SampleDB];
GO

-- Add a table
CREATE TABLE dbo.test
(
    c1 CHAR(8000) NOT NULL DEFAULT REPLICATE('a',8000)
) ON [PRIMARY];
GO

-- Ensure that we are not is pseudo-simple recovery model
BACKUP DATABASE SampleDB
TO DISK = 'NUL';
GO

-- Backup the log file
BACKUP LOG SampleDB
TO DISK = 'NUL';
GO

-- CHeck the used log space
DBCC SQLPERF(LOGSPACE);
GO

-- How many records are visible with fn_dblog()?
SELECT * FROM fn_dblog(NULL,NULL); -- Around 9 in my case

/**********************************
             SCENARIO 1
**********************************/
-- Open a new transaction and then roll it back
BEGIN TRANSACTION

    INSERT INTO dbo.test DEFAULT VALUES;
    GO 10000 -- Let is run for 10 seconds and then hit cancel in SSMS query window

    -- Cancel the transaction
    -- It should take a couple seconds to finish


-- No need to rollback the transaction, since the cancel already did that for you.
-- Just try it. You'll get this error
-- Msg 3903, Level 16, State 1, Line 1
-- The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION.
ROLLBACK TRANSACTION;

-- What is the used log space? Above 100%.
DBCC SQLPERF(LOGSPACE);
GO

-- How many records are visible with fn_dblog()?
SELECT * 
FROM fn_dblog(NULL,NULL); -- Around 91,926 in my case

-- Total log reserve shown by fn_dblog()?
SELECT SUM([Log Reserve]) AS [Total Log Reserve]
FROM fn_dblog(NULL,NULL); -- Around 88.72MB


/**********************************
             SCENARIO 2
**********************************/
-- Blow away the DB and start over
USE [master];
GO

IF DATABASEPROPERTYEX (N'SampleDB', N'Version') > 0
BEGIN
    ALTER DATABASE [SampleDB] SET SINGLE_USER
        WITH ROLLBACK IMMEDIATE;
    DROP DATABASE [SampleDB];
END;
GO

CREATE DATABASE [SampleDB] ON PRIMARY 
( 
      NAME = N'SampleDB'
    , FILENAME = N'E:\data\SampleDB.mdf' 
    , SIZE = 3MB 
    , FILEGROWTH = 1MB 
)
LOG ON 
( 
      NAME = N'SampleDB_log'
    , FILENAME = N'E:\data\SampleDB_log.ldf'
    , SIZE = 1MB 
    , MAXSIZE = 100MB 
    , FILEGROWTH = 4MB 
);
GO

USE [SampleDB];
GO

-- Add a table
CREATE TABLE dbo.test
(
    c1 CHAR(8000) NOT NULL DEFAULT REPLICATE('a',8000)
) ON [PRIMARY];
GO

-- Ensure that we are not is pseudo-simple recovery model
BACKUP DATABASE SampleDB
TO DISK = 'NUL';
GO

-- Backup the log file
BACKUP LOG SampleDB
TO DISK = 'NUL';
GO

-- Now, let's blow up the log file within our transaction
BEGIN TRANSACTION
    INSERT INTO dbo.test DEFAULT VALUES;
    GO 10000

-- The rollback never fires. Try it. You'll get an error.
-- Msg 3903, Level 16, State 1, Line 1
-- The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION.
ROLLBACK TRANSACTION;

-- Is the log file 100% full? 
DBCC SQLPERF(LOGSPACE);

-- How many records are visible with fn_dblog()?
SELECT * 
FROM fn_dblog(NULL,NULL); -- Around 91,926 in my case
GO

-- Total log reserve shown by fn_dblog()?
SELECT SUM([Log Reserve]) AS [Total Log Reserve]
FROM fn_dblog(NULL,NULL); -- 88.72MB
GO
  • Thank you for the detailed tests. After running more tests, I came to a similar conclusion.So, I wrote a blog post. For me Scenario 2 takes longer to rollback because the amount of work performed in Scenario 2, before Sql Server realizes the need to rollback is more than Scenario 1. – ToC Aug 12 '15 at 16:23

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.