DBCC CHECKDB - SQL Log Says Completed, SQL Server Agent Says Failed

Question

I run a nightly Integrity Check (set up via Maintenance Plans) on all of my databases. For the last two nights, the final CHECKDBCC has failed... at least according to the SQL Server Agent Job.

Progress: 2019年01月25日 03:51:01.15 Source: Check Database Integrity Executing query "USE [CellTestData_QC] ".: 50% complete End Progress
Error: 2019年01月25日 05:14:43.79 Code: 0xC002F210 Source: Check Database Integrity Execute SQL Task Description: Executing the query "DBCC CHECKDB(N'CellTestData_QC') WITH NO_INFOMSGS..." failed with the following error: "A severe error occurred on the current command. The results if any should be disca... The package execution fa... The step failed.

But if I check the SQL Server Logs, I get two conflicting messages.

First I get:

01/25/2019 05:00:39,spid105,Unknown,DBCC CHECKDB (CellTestData_QC) WITH no_infomsgs executed by sa terminated abnormally due to error state 6. Elapsed time: 1 hours 9 minutes 38 seconds.

But then I get:

01/25/2019 05:32:06,spid110,Unknown,CHECKDB for database 'CellTestData_QC' finished without errors on 2019年01月24日 23:01:46.507 (local time). This is an informational message only; no user action is required.

So what exactly is going on here? Is my process completing? Or erroring out?

For a bit more context...

• We restore [CellTestData_QC] every morning at 5AM (likely why I'm getting the SQL Server Log message of 'terminated abnormally at 5AM).
• Additionally, my backups of [CellTestData] and integrity checks of [CellTestData] and [CellTestData_QC] have been taking longer over the last few days - possibly because of issues with our SAN, which is why we're getting the IntegrityCheck of [CellTestData_QC] beginning to run into the restore of [CellTestData_QC]
• Integrity checks run every night at 11PM
• DB backups (full and partial) run nightly
• Transaction Log backups run every 15min
• Currently working with 8 databases, that range in size from 4MB to 100GB, with a total of 330GB of databases
• I'm running SQL Server Standard 2012 on a 64-bit Windows Server VM (using vSphere) with 64GB RAM, 1TB SAN storage, 175GB NAS storage, 4CPU, 4.9GHz

Any ideas what might be going on here?

Answer 1

There is no mystery, the 2 messagges for CellTestData_QC reference 2 different databases CellTestData_QC.

The first one is your database CellTestData_QC on which DBCC CHECKDB did not complete because you began a restore.

The second message refers to the restored database CellTestData. It's not DBCC CHECKDB that was running on 25/01, it's just an info that is stored within CellTestData, and it reports the last date when DBCC CHECKDB completed without errors on this database.

Every time the database is opened (goes online), the last known good dbcc checkdb date is reported in eroor log. So the second message tells you that DBCC CHECKDB completed successfully on your database CellTestData on 2019年01月24日 23:01:46.507. This message appears in error log as soon as restore is completed.

You can see this on every server restart. SQL Server opens every database that should go online and within every database it reads the date called last known good time and reports it in errorlog. This does not mean that checkdb runs on every restart, in fact, the date reported is always earlier than the current date.

For example, if you run checkdb every Sunday, and the restart occurs on Saturday, you'll see these messages reporting previous Sunday date in errorlog as it was the last date when dbcc checkdb completed successfully.

Here CHECKDB From Every Angle: When did DBCC CHECKDB last run successfully? you can read more on last-known good time.

• A Sch: I'm not sure I follow, as I only have a single server that these DBs are running on. [CellTestData_QC] is a nightly restore of [CellTestData].
• sepupic: Ok, even if it's the same server, your dbcc checkdb failed on 25/01, this is the first message produced by CHECKDB(the command issued on 25/01), but this db was OVERWRITTEN with the copy of CellTestData, and when this restored copy went online, it reported that checkdb on CellTestData was finished without errors on 24/01, it's NOT checkdb that produced this message, it was the server that read this in the db restored. It just reported WHAT WAS WRITTEN in CellTestData when bringing db online. I'll try to update my answer to be more clear

Answer 2

Look closely it seems like there are 2 different queries running for checkdb.

Executing the query "DBCC CHECKDB(N'CellTestData_QC') WITH NO_INFOMSGS..." failed with the following error

The query is DBCC CHECKDB(N'CellTestData_QC') WITH NO_INFOMSGS

Now look at other error message

01/25/2019 05:00:39,spid105,Unknown,DBCC CHECKDB (CellTestData_QC) WITH no_infomsgs

The query is DBCC CHECKDB (CellTestData_QC) WITH no_infomsgs

It seems like there are 2 processes running checkdb. Can you check this.

We restore [CellTestData_QC] every morning at 5AM (likely why I'm getting the SQL Server Log message of 'terminated abnormally at 5AM).

Is it possible that checkdb, because it is taking long time, is overlapping with restore and eventually getting terminated because restore has to start ?. Again lot of things you have to find out.

• A Sch: To your first point - I just think that's a difference in how the SQL Server Agent Job history logs information vs. how the SQL Server Log logs information. I'm pretty sure that's the same query, just one uses the N prefix to tell SQL to convert it to unicode. To your second point, the restore starting at 5AM is definitely messing with the DBCC CHECKDB. I just want to know if it's actually completed or not... I've moved up my Integrity checks by 1hr so I'll see tonight what actually happens.