0

One of my production database log file drive filled up and I noticed below messages in SQL Server error log.

2022-02-13 03:16:24.500 spid72  Error: 9002, Severity: 17, State: 4.
2022-02-13 03:16:24.500 spid72  The transaction log for database 'huge_database' is full due to 'ACTIVE_TRANSACTION'.
2022-02-13 03:16:26.060 spid72  Error: 9002, Severity: 17, State: 4.
2022-02-13 03:16:26.060 spid72  The transaction log for database 'huge_database' is full due to 'ACTIVE_TRANSACTION'.
2022-02-13 03:16:26.070 spid72  Error: 3314, Severity: 21, State: 3.
2022-02-13 03:16:26.070 spid72  During undoing of a logged operation in database 'huge_database', an error occurred at log record ID (2766:550754:254). Typically, the specific failure is logged previously as an error in the Windows Event Log service. Restore the database or file from a backup, or repair the database.
2022-02-13 03:16:26.090 spid72  Database huge_database was shutdown due to error 3314 in routine 'XdesRMReadWrite::RollbackToLsn'. Restart for non-snapshot databases will be attempted after all connections to the database are aborted.
2022-02-13 03:16:26.090 spid72  Error: 3314, Severity: 21, State: 5.
2022-02-13 03:16:26.090 spid72  During undoing of a logged operation in database 'huge_database', an error occurred at log record ID (2678:51796:1). Typically, the specific failure is logged previously as an error in the Windows Event Log service. Restore the database or file from a backup, or repair the database.
2022-02-13 03:16:32.900 spid48s Starting up database 'huge_database'.
2022-02-13 03:16:37.980 spid48s Recovery of database 'huge_database' (20) is 0% complete (approximately 89573 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
2022-02-13 03:16:57.980 spid48s Recovery of database 'huge_database' (20) is 0% complete (approximately 60835 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
...
2022-02-13 04:26:15.160 spid36s Recovery of database 'huge_database' (20) is 85% complete (approximately 721 seconds remain). Phase 3 of 3. This is an informational message only. No user action is required.
...
2022-02-13 04:36:35.230 spid36s Recovery of database 'huge_database' (20) is 99% complete (approximately 1 seconds remain). Phase 3 of 3. This is an informational message only. No user action is required.
2022-02-13 04:36:35.790 spid36s 1 transactions rolled back in database 'huge_database' (20:0). This is an informational message only. No user action is required.
2022-02-13 04:36:35.790 spid36s Recovery is writing a checkpoint in database 'huge_database' (20). This is an informational message only. No user action is required.
2022-02-13 04:36:36.850 spid36s Recovery completed for database huge_database (database ID 20) in 4804 second(s) (analysis 4881 ms, redo 1196931 ms, undo 3600721 ms.) This is an informational message only. No user action is required.  

So it seems that the database log drive is full, and it started a recovery process, which took more than an hour. Why it needs to recover in this case? I want to reproduce it but failed. Below is my code:

CREATE DATABASE MyDatabase
ON 
    (NAME = MyDatabase_Data,
    FILENAME = 'f:\mssql\data\MyDatabase_Data.mdf',
    SIZE = 10MB,
    MAXSIZE = 1000MB,
    FILEGROWTH = 5MB)
LOG ON
    (NAME = MyDatabase_Log,
    FILENAME = 'U:\data\MyDatabase_Log.ldf',
    SIZE = 5MB,
    MAXSIZE = 500MB,
    FILEGROWTH = 1MB);
GO

USE MyDatabase;
GO

CREATE TABLE MyTable (
    ID INT IDENTITY(1,1) PRIMARY KEY,
    Data VARCHAR(MAX) NOT NULL
);
GO

BEGIN TRANSACTION;

DECLARE @i INT = 0;
WHILE @i < 1000000
BEGIN
    INSERT INTO MyTable (Data) VALUES (REPLICATE('A', 8000));
    SET @i = @i + 1;
END;

-- Don't commit the transaction
-- COMMIT TRANSACTION;

When I run my code, I got this in SSMS:

Msg 9002, Level 17, State 4, Line 30 The transaction log for database 'MyDatabase' is full due to 'ACTIVE_TRANSACTION' and the holdup lsn is (39:24:1).

And this from the SQL Server error log:

2023-08-18 02:59:54.200 spid84  Error: 17053, Severity: 16, State: 1.
2023-08-18 02:59:54.200 spid84  U:\data\MyDatabase_Log.ldf: Operating system error 112(There is not enough space on the disk.) encountered.
2023-08-18 02:59:55.200 spid84  Error: 9002, Severity: 17, State: 4.
2023-08-18 02:59:55.200 spid84  The transaction log for database 'MyDatabase' is full due to 'ACTIVE_TRANSACTION' and the holdup lsn is (39:24:1).  

There is no recovery process. Why? How to mimic my production database issue?


Update:

Btw, during the recovery of my production database, I can still access it. It still have the same status as in other databases in sys.databases. Is this expected? I though databases in recovery is not accessible.

Update2:

During undoing of a logged operation in database 'huge_database', an error occurred at log record ID (2678:51796:1).

This error log sounds like SQL didn't reserve enough space to roll back. I remembered that Paul Randal said that SQL Server always reserve some log for rollback. If so, why this could happen?

3
  • 1) Is this database in an Availability Group? 2) If so, is database level health detection set for this AG? Aug 17, 2023 at 19:37
  • @SeanGallardy, no, it's not in AG. Aug 17, 2023 at 19:44
  • 2
    "I though databases in recovery is not accessible." Fast Recovery in Enterprise Edition allows the database to be available once the redo phase of recovery completes while the undo phase executes.
    – Dan Guzman
    Aug 17, 2023 at 20:19

1 Answer 1

3

Why it needs to recover in this case?

There was an issue undoing a transaction, this leaves the database in an inconsistent state, in fact the database should move to suspect. You can see from the error that SQL Server is doing the restart automatically.

2022-02-13 03:16:26.090 spid72  Database huge_database was shutdown due to error 3314 in routine 'XdesRMReadWrite::RollbackToLsn'. Restart for non-snapshot databases will be attempted after all connections to the database are aborted.

Btw, during the recovery of my production database, I can still access it.

Much as Dan Guzman has stated, Enterprise Edition has "Fast Recovery" which will allow the database to be open to users after redo has completed and locks have all been taking on outstanding undo items. You can see when this occurred in the log (Phase 1 is Analysis, 2 is Redo, 3 is Undo):

2022-02-13 03:16:57.980 spid48s Recovery of database 'huge_database' (20) is 0% complete (approximately 60835 seconds remain). Phase 2 of 3. This is an informational message only. No user action is required.
...
2022-02-13 04:26:15.160 spid36s Recovery of database 'huge_database' (20) is 85% complete (approximately 721 seconds remain). Phase 3 of 3. This is an informational message only. No user action is required.

Note that the "..." in your original data is when the database was available, which is sometime after "2022-02-13 03:16:57.980".

There is no recovery process. Why? How to mimic my production database issue?

You're not hitting the same issue. In your production example there was a failure to undo a change, in your repro there was no failure just that the log is full.

I remembered that Paul Randal said that SQL Server always reserve some log for rollback. If so, why this could happen?

The log manager makes a guess at how much space it needs to reserve per transaction, whether that is too little, too much, or just right is not known at the time. There is, additionally, extra space held called "critical reserved" log space, just in case. In some situations where not enough log was held in reserve and it spills over, the log may run out of reserved space and an exception may occur while doing something, such as, say, rolling back a transaction. It shouldn't be a frequent occurrence but it can happen.

2
  • Thanks for the detailed answer. I've learned a lot. Aug 18, 2023 at 1:34
  • is it possible to manually create a repro to mimic what happened on my prod? It seems very hard to me. Aug 18, 2023 at 1:37

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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