Share via

Database is marked for restoring and is in a state that does not allow recovery

  • Article

Question

Wednesday, March 14, 2012 10:50 PM

When restoring transaction logs for different databases on the same server, some databases log messages that cache stores are being flushed, attempting to start up the Db, and database being in recovery mode. Some don't. Does anyone know why is the difference? All restores in this scenario are with norecovery, expecting more logs to be restored. (SQL 2005, no trace flags)

For example, one DB will just log a log restored statement :

- Log was restored. Database: ProdDB2 creation date(time): 2011/05/20(11:15:21) first LSN: 5234:606205....

But another DB, restoring log five seconds later, will write a lot more:

- SQL Server has encountered 8 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to some

  • SQL Server has encountered 8 occurrence(s) of cachestore flush for the 'SQL Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
  • SQL Server has encountered 8 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
  • Starting up database 'ProdDB1'.
  • The database 'ProdDB1' is marked RESTORING and is in a state that does not allow recovery to be run.
  • Log was restored. Database: ProdDB1 creation date(time): 2011/05/21(11:55:42) first LSN: 41021:209049....

All replies (6)

Thursday, March 15, 2012 3:46 AM | 1 vote

 >>>The database 'ProdDB1' is marked RESTORING and is in a state that does not allow recovery to be run. 

Perhaps there are huge amount of not commited/commited transactions that SQL Server needs red/undo in order to bring up the database in consistent  state.

Best Regards, Uri Dimant SQL Server MVP http://dimantdatabasesolutions.blogspot.com/ http://sqlblog.com/blogs/uri_dimant/

Thursday, March 15, 2012 11:09 AM

Yes, this may be true... The source of DB that logs all these messages (ProdDB1) is a lot busier than the other one. 

But a large log restore (say, 3 hours) of a less busy DB2 still does not attempt to start it up, flush caches and so on. Yet a 5 minutes of log activity from a busier DB1 still does all this stuff. I guess I'm also wondering why it would even attempt to start the DB1 up? It's been told "restore with norecovery"...

Thanks for your input!

Thursday, March 15, 2012 2:28 PM | 1 vote

Thinking out loud, two things comes to mind:

1. Restore was made with STANDBY

2. There was some cross.database transaction going on (internaly handled as 2pc).

Tibor Karaszi, SQL Server MVP | web | blog

Thursday, March 15, 2012 10:19 PM

Yes, there is certainly a cross-db chat in ProdDB1. Is that really what makes the Db to attempt to start-up?

It is also published (transactional, but restored without "keep replication")

No Standby in this case.

Thanks!

Friday, March 16, 2012 12:07 PM | 1 vote

Cross db transactions was just a guess. I just tried it, and it didn't cause those messages in the errorlog file. I doubt the replication stuff should cause this.

I'm pretty much out of ideas. My last thinking was some database option, according to http://msdn.microsoft.com/en-us/library/ms174269.aspx forcing log flush. I tried with OFFLINE and READ_ONLY, but still couldn't repro. Perhaps there are some more database options in 2005 (the URL above is for 2008 R2, which is what I ran on) that can cause cacheflush. However, it seems weird that a cacheflush should cause recovery at startup.... Below is the script I used.

USE tempdb
GO
IF DB_ID('a') IS NOT NULL DROP DATABASE a
IF DB_ID('b') IS NOT NULL DROP DATABASE b
GO

CREATE DATABASE a
CREATE DATABASE b
ALTER DATABASE a SET RECOVERY FULL
ALTER DATABASE b SET RECOVERY FULL
GO

CREATE TABLE a..t(c1 int)
CREATE TABLE b..t(c1 int)
GO

IF OBJECT_ID('tempdb..#ModifyData') IS NOT NULL DROP PROC #ModifyData
GO

CREATE PROC #ModifyData @inTran tinyint, @rollb tinyint = 0 AS
IF @inTran = 1
  BEGIN TRAN
INSERT INTO a..t(c1) VALUES(1)
INSERT INTO b..t(c1) VALUES(1)
IF @inTran = 1
  IF @rollb = 0
    COMMIT
  ELSE
    ROLLBACK
GO

--First, full backup
BACKUP DATABASE a TO DISK = 'R:\a.bak' WITH INIT --1
BACKUP DATABASE b TO DISK = 'R:\b.bak' WITH INIT --1

--Do modification, no distributed transaction
EXEC #ModifyData @inTran = 0

--Log backups
BACKUP LOG a TO DISK = 'R:\a.bak' --2
BACKUP LOG b TO DISK = 'R:\b.bak' --2

--Do modification, WITH distributed transaction
EXEC #ModifyData @inTran = 1
ALTER DATABASE a SET READ_ONLY
PRINT 1
ALTER DATABASE a SET READ_WRITE
--Log backups
BACKUP LOG a TO DISK = 'R:\a.bak' --3
BACKUP LOG b TO DISK = 'R:\b.bak' --3

--Do modification, WITH distributed transaction
EXEC #ModifyData @inTran = 1, @rollb = 1

--Log backups
BACKUP LOG a TO DISK = 'R:\a.bak' --4
BACKUP LOG b TO DISK = 'R:\b.bak' --4

--Do modification, no distributed transaction
EXEC #ModifyData @inTran = 0

--Log backups
BACKUP LOG a TO DISK = 'R:\a.bak' --5
BACKUP LOG b TO DISK = 'R:\b.bak' --5

--Empty errorlog file
EXEC sp_cycle_errorlog

--Now restore each database, and transaction log backups
RESTORE DATABASE a FROM DISK = 'R:\a.bak' WITH FILE = 1, NORECOVERY, REPLACE
WAITFOR DELAY '00:00:02'
RESTORE LOG a FROM DISK = 'R:\a.bak' WITH FILE = 2, NORECOVERY
WAITFOR DELAY '00:00:02'
RESTORE LOG a FROM DISK = 'R:\a.bak' WITH FILE = 3, NORECOVERY
WAITFOR DELAY '00:00:02'
RESTORE LOG a FROM DISK = 'R:\a.bak' WITH FILE = 4, NORECOVERY
WAITFOR DELAY '00:00:02'
RESTORE LOG a FROM DISK = 'R:\a.bak' WITH FILE = 5, RECOVERY
WAITFOR DELAY '00:00:02'

RESTORE DATABASE b FROM DISK = 'R:\b.bak' WITH FILE = 1, NORECOVERY, REPLACE
WAITFOR DELAY '00:00:02'
RESTORE LOG b FROM DISK = 'R:\b.bak' WITH FILE = 2, NORECOVERY
WAITFOR DELAY '00:00:02'
RESTORE LOG b FROM DISK = 'R:\b.bak' WITH FILE = 3, NORECOVERY
WAITFOR DELAY '00:00:02'
RESTORE LOG b FROM DISK = 'R:\b.bak' WITH FILE = 4, NORECOVERY
WAITFOR DELAY '00:00:02'
RESTORE LOG b FROM DISK = 'R:\b.bak' WITH FILE = 5, RECOVERY
WAITFOR DELAY '00:00:02'

--See what was in the errorlog file
EXEC sp_readerrorlog

Tibor Karaszi, SQL Server MVP | web | blog

Friday, March 16, 2012 1:22 PM

Thanks for the test, Tibor.

Yeah, weired. There are also some ANSI settings that differ this DB from others, but I can't imagine why that would be a factor.
I just hope this is not  a sign of trouble. Searching the net showed posts from other people's logs where this attempt to start-up seemed to be a normal inclusion.