July 20, 2007 at 6:49 am
We are restoring a SQL transaction log every 15 minutes via tsql scripts. The process seems to be working fine but there are 3 messages in the SQL Error Log regarding cachsestore flushing that appear at the start of each restore operation. "SQL Server has encountered 8 occurrence(s) of cachestore flush for the 'Object Plans' cachestore"... etc. I've included the SQL Error log of the entire restore operation below (read from bottom up).
Are these messages anything to be concerned about? I found an MSDN article that states that these messages are the expected result of running various adminstrative commands including a restore. The article also says that "Clearing the plan cache causes a recompilation of all subsequent execution plans and cause a sudden, temporary excessive CPU usage and decrease in query performance."
07/20/2007 07:38:25,Backup,Unknown,Log was restored. Database: CCS_Siebelprod_1<c/> creation date(time): 2007/05/21(11:55:42)<c/> first LSN: 41021:213213:1<c/> last LSN: 41021:219919:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'\\BOSOPS2\D$\OperationalFiles\SQLServerFiles\CRCSBLDB\siebelprodTransactionLogs\siebelprod_backup_200707200730.trn'}). This is an informational message. No user action is required.
07/20/2007 07:38:25,spid69,Unknown,Starting up database 'CCS_Siebelprod_1'.
07/20/2007 07:38:24,spid69,Unknown,Recovery is writing a checkpoint in database 'CCS_Siebelprod_1' (15). This is an informational message only. No user action is required.
07/20/2007 07:38:24,spid69,Unknown,The database 'CCS_Siebelprod_1' is marked RESTORING and is in a state that does not allow recovery to be run.
07/20/2007 07:38:24,spid69,Unknown,Starting up database 'CCS_Siebelprod_1'.
07/20/2007 07:38:22,Backup,Unknown,Log was restored. Database: CCS_Siebelprod_1<c/> creation date(time): 2007/05/21(11:55:42)<c/> first LSN: 41021:209049:1<c/> last LSN: 41021:213213:1<c/> number of dump devices: 1<c/> device information: (FILE=1<c/> TYPE=DISK: {'\\BOSOPS2\D$\OperationalFiles\SQLServerFiles\CRCSBLDB\siebelprodTransactionLogs\siebelprod_backup_200707200715.trn'}). This is an informational message. No user action is required.
07/20/2007 07:38:21,spid69,Unknown,Starting up database 'CCS_Siebelprod_1'.
07/20/2007 07:38:20,spid69,Unknown,Recovery is writing a checkpoint in database 'CCS_Siebelprod_1' (15). This is an informational message only. No user action is required.
07/20/2007 07:38:18,spid69,Unknown,The database 'CCS_Siebelprod_1' is marked RESTORING and is in a state that does not allow recovery to be run.
07/20/2007 07:38:18,spid69,Unknown,Starting up database 'CCS_Siebelprod_1'.
07/20/2007 07:38:18,spid69,Unknown,SQL Server has encountered 8 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
07/20/2007 07:38:18,spid69,Unknown,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.
07/20/2007 07:38:18,spid69,Unknown,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.
July 23, 2007 at 9:59 am
Hi Christopher,
THis isn't an official Microsoft answer, but this is my gut instinct. If I were to see something like this, I would interpret it as follows. Essentially, we are restoring to a database that has some objects cached. The transaction log is restored and changes are applied to the database. As a result, SQL no longer "trusts" that the cache for this database is accurate (i.e the cached pages are dirty). Since SQl is doing a large cache flush, it provides a warning as it decides to flush the cache for this database. I think the biggest clue that this isn't a big deal is that the error message gives some common explanations "due to some database maintenance or reconfigure operations." As such, I think it's a clue that this isn't that big of a deal IF you are doing something like what the are suggesting/guessing.
I've seen a lot more logging for warnings and potential problems in SQL '05, so to sum it up, I would guess that this isn't a big deal.
Thanks,
Eric
July 26, 2007 at 7:37 am
Thanks Eric,
Your assessment sounds right to me. It doesn't seem to have caused any problems so far, so I'll keep my fingers crossed.
November 1, 2007 at 8:52 am
We're encountering the same situation. A colleague found this item which seems offer a good explanation.
http://blogs.msdn.com/sqlprogrammability/archive/2007/01/17/10-0-plan-cache-flush.aspx
April 24, 2008 at 10:19 am
Christopher, r u still happy these messages are still not causing you a problem. I get the exact same messages after log restores due to log shipping, trouble is there are also live databases on the server, and I get the impression the WHOLE of the proccache is cleared. This is what BOL says:
Restoring a database clears the plan cache for the instance of SQL Server. Clearing the plan cache causes a recompilation of all subsequent execution plans and can cause a sudden, temporary decrease in query performance. In SQL Server 2005 Service Pack 2, for each cleared cachestore in the plan cache, the SQL Server error log contains the following informational message: "SQL Server has encountered %d occurrence(s) of cachestore flush for the '%s' cachestore (part of plan cache) due to some database maintenance or reconfigure operations". This message is logged every five minutes as long as the cache is flushed within that time interval
My messages also refers to 8 occurrences - coincidence?
---------------------------------------------------------------------
June 24, 2009 at 8:33 am
Fellows,
I have same issue during restoration 59G backup from a different server 2000 on 2005. It's came second time in 3 days and after all messages related to "due to some database maintenance or reconfigure operations" I'm getting "SQL Server has encountered 1 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file" and restoration failed. Do you have exact answer what should be done?
Thanks
June 24, 2009 at 9:07 am
Vlad, nothing to do, its not an error, just informational. Just be aware restores will clear out your proccache.
I raised a request to change this behavior on technet but no-one else seemed bothered to vote for it (to my surprise). Having said that MS did say they were looking into this and may change this behavior in a 'future release'
---------------------------------------------------------------------
June 24, 2009 at 9:18 am
George , thanks for a quick response. But the issue is still exists and I'm on the phone with MS. Every 2-3 days restoration started failing and no clear answer anywhere. My boss and me don't like it at all. Thanks again
June 24, 2009 at 10:15 am
...er, your post fooled me, the rest of this thread is about cache flushes, not slow i/o, which your warning refers to.
You would be best starting a new thread but basically your io system isn't up to the load imposed on it. If the .bak file is on the same disk as the database you are restoring to perhaps move it to a different disk.
---------------------------------------------------------------------
Viewing 9 posts - 1 through 8 (of 8 total)
You must be logged in to reply to this topic. Login to reply